Inconsistent Post Requests

[KyleHunter]

Basic Infos

Hardware

Hardware: ESP-12
Core Version: Latest NodeMCU

Description

So this issue has been infuriating to me for the last several weeks.. It is related to my prior issue: #3182

I had incorrectly assumed that it was fixed when it wasn't. So I am sending post requests to dweetpro.io every 15 seconds. I have the most inconsistent results with it. I have tried everything, from having a local WiFiClient instance, to a global one, that only connects at the start of the sketch. When I do WiFiClient.println(); sometimes it will go super fast, submit the post, return a response in less than half a second. Other times it will take seconds for each println(), but still get a valid post. Other times it will take 5+ seconds on each println() and won't submit a valid post..

But what is so frustrating, is that it will work for hours/days only failing on a few here and there, and then it will fail completely until a restart, but many times restarting it doesn't immediately solve it either. I've tried printing the current signal strength, and it's in the same room as the router so it is always -50dB or better.

Everything with the website, dweetpro is fine. Because when the esp is failing, I am able to manually make post requests from other sources and they work perfectly.

I've tried with a generic esp-12, nodemcu, same issues. I really don't know what else to try, as it is just bizarre how inconsistent this board is.

Settings in IDE

Module: ESP-12
Flash Size: 4MB
CPU Frequency: ?80Mhz?
Flash Mode: ?qio?
Flash Frequency: ?40Mhz?
Upload Using: SERIAL
Reset Method: ?ck / nodemcu?

Sketch

  bool send_post_to_server(WiFiClient client, String content, int content_length)
  {
    Serial.println(client.connected()); //always prints 1
    Serial.println("Here2.2"); // For debugging
    client.println("POST /v2/dweets HTTP/1.1");
    Serial.println("Here2.21"); // For debugging
    client.println("Host: dweetpro.io");
    Serial.println("Here2.22"); // For debugging
    client.println("X-DWEET-AUTH: xxx");
    Serial.println("Here2.23"); // For debugging
    client.println("Accept: application/json");
    Serial.println("Here2.24"); // For debugging
    client.println("Content-Type: application/json");
    Serial.println("Here2.25"); // For debugging
    client.print("Content-Length: ");
    Serial.println("Here2.36"); // For debugging
    client.println(content_length);
    client.println();
    Serial.println("Here2.4"); // For debugging
    client.print(content);
    Serial.println("Here2.5"); // For debugging
  }

  void send_to_server(String* time_sent, String status,
    bool, float* data, int data_size, WiFiClient client)
  {
    Serial.println("Here2"); // For debugging
    int content_length;
    String content = make_json_content(&content_length, status, data, data_size);
    Serial.println("Here2.1"); // For debugging
    send_post_to_server(client, content, content_length);
    Serial.println("Here3"); // For debugging
    delay(10);
    int timer = millis();
    while (client.available() == 0)
    {
      delay(10);
      if (millis() - timer > 3000)
      {
        Serial.println("2"); // When it fails, it is here. I have increased time to 10000, no difference
        return;
      }
    }

      Serial.println("Here4"); // For debugging
      String json = "";
      bool http_body = 0;

      led::turn_green_led(0);
      while(client.available())
      {
        String line = client.readStringUntil('\r');
        if (!http_body && line.charAt(1) == '{')
          http_body = 1;
        if (http_body)
          json += line;
      }

      Serial.println("Response: ");
      Serial.println(json);
  }

// In main loop I use:

  if (!client.connected())
  {
    client.stop();
    client.connect(IPAddress(54, 236, 198, 240), 80);
  }
//I have tried local instances, and global where I connect/disconnect each request.
//This way I have now seems slightly(?) more reliable

Other thoughts I've had are maybe interference from electronics/router..? I'm out of ideas, as I have tried literally everything.

I have a 2Amp usb power supply, tried multiple different ones as well

[igrr]

Just to confirm, are you using the (latest) git version of the core, or the one installed via boards manager (2.3.0)?

Is there any specific reason for formatting the request manually using WiFiClient, instead of using the bundled ESP8266HTTPClient library? In version 2.3.0, every println you do causes 3 TCP segments to be sent — one for the line itself, and two more for \r and \n. This has been optimized in git version (so Nagle algorithm will prevent short writes from being sent immediately), but still it is better to prepare all the headers in a single buffer and send them in a single TCP segment — that's what the HTTPClient library does.

[KyleHunter]

@igrr I'm using the latest version on git.

That's one thing I haven't tried yet, I'll give that a shot

[KyleHunter]

@igrr using platformIO, my version is:
"Updating espressif8266                   @ 1.3.0          [Up-to-date]"

Using this new code:

  void send_to_server(String* time_sent, String status, float* data, int data_size)
  {
    HTTPClient http;

    int content_length;
    String content = make_json_content(&content_length, data, data_size);

    http.begin("http://dweetpro.io/v2/dweets");

    http.addHeader("Content-Type", "application/json");
    http.addHeader("Accept", "application/json");
    http.addHeader("Content-Type", "application/json");
    http.addHeader("Content-Length", String(content_length));
    http.addHeader("X-DWEET-AUTH", "xxx");

    http.POST(content);
    http.writeToStream(&Serial);
    http.end();
  }

Same issues as before.. Still very inconsistent

[KyleHunter]

Sorry, didn't mean to close..

[KyleHunter]

@igrr if I do:
"int s = http.POST(content);"
and then print s, it returns -3 or -1 when it fails.

RSSI strength: -62
Post len: 200
{"this":"succeeded","by":"dweeting","the":"stored_dweets","with":{"content":{"data":[-0.24,2.13,0.09,-0.07,0.42,0.05,-0.04,-0.05,0.03,0.09,0.28,0.47,-0.3,0.18,-0.03,0.08,0.45,-0.28,0.4,-0.32,0.2,-0.18,-0.08,0.06,0.21,0.07,0.15,-0.07,0.13,-0.04,-0.1,0.54,-0.27,-0.03,0.07,-0.37,0.39,-0.32,0.19,0.06,-0.16,0.15,-0.49,0.3,-0.45,0.17,0.24,0.1,0.39,-0.13,0.32,-0.32,0.43,-0.16,-0.39,0.55,-0.47,0.4,-0.25,0.08,0.33,-0.27,0.35,-0.36,0.36,-0.11,0.08,-0.39,0.15,0.05,-0.07,0.36,0.27,-0.37,-0.17,0.12,0.23,0.35,-0.01,0.36,0.43,-0.26,-0.2,0.08,-0.23,0.14,0.12,-0.1,0.05,0.01,0.15,0.28,-0.17,0.45,-0.12,-0.29,0,-0.11,0.15,-0.06,0.1,0.05,0.12,-0.05,-0.15,0.17,-0.24,0.13,0.19,0.12,-0.01,0.21,-0.35,-0.01,-0.24,0.16,0.06,0.11,0.17,-0.28,0.38,0.09,0.38,-0.04,0.1,-0.36,-0.17,0.24,0.08,0.2,-0.37,0.2,-0.11,0.14,-0.06,-0.11,0.03,-0.18,0.29,0.03,0.04,0.27,-0.13,0.1,0.14,-0.03,-0.04,0.21,-0.23,0.02,-0.02,0.12,-0.16,0.09,0,-0.21,-0.02,-0.02,0.19,0.13,0.12,-0.3,0.16,0.08,0,0.01,0.06,-0.03,0.4,-0.31,0.26,-0.17,-0.02,-0.04,-0.05,-0.06,0.12,0.07,0.25,0.13,-0.1,-0.16,-0.02,0.11,-0.05,0.14,-0.12,0.09,-0.35,0.1,-0.22,0.17,0.09,-0.08,-0.18,0.35,-0.29,0.1,0.01,0.07,0.07,-0.18,0.08,0.0000916,0.1,-0.18,0.05,-0.09,-0.17,0.24,0.34,0.13,-0.04,0.19,0.05,-0.28,-0.05,-0.1,0.25,-0.29,0.4,-0.78,0.24,-0.05,-0.38,0.27,-0.46,0.2,-0.17,0.23,-0.11,-0.15,0.1,-0.04,-0.06,0.04,0.12,0.14,-0.01,-0.12,0.1,-0.15,-0.04,0.05,0.24,-0.09,-0.04,0.08,0.02,0],"status":"OK"},"thing":"foo","account":"LOCAL","created":"2017-05-20T00:44:28.224Z","transaction":"xx"}}
RSSI strength: -53
Post len: -1
 
RSSI strength: -51
Post len: -1
 
RSSI strength: -64
Post len: -1
 
RSSI strength: -64
Post len: -3

 ```

[igrr]

As far as i can tell, platformio doesn't use the latest git version of the core, 1.3.0 was released in February (platformio/platform-espressif8266@fc1b95a).

Can you do a packet capture on the router side, or by sniffing the wifi network (using Wireshark or similar)? That would shed some light on the possible cause of the issue.

[KyleHunter]

@igrr Here is the result of me using wireshark: https://drive.google.com/file/d/0B5-5-5KtayGhUDBIUUVpRU8zV28/view?usp=sharing

Data looked weird to me, it didn't use the IP assigned to it from my router, which is "192.168.1.177"

I'm not able to find anything that seems related to the esp, when it sends valid data. The IP of dweetpro should be either 52.86.17.232 or 54.236.198.240.

On the log, there is a lot of stuff that comes back to a "Espressi_16:d6:6e (a0:20:a6:16:d6:6e)." only when it fails I think. That's related to the problem I presume

Though, I'm watching it now, and there really doesn't seem to be much data logged when it fails or succeeds in posting.

[igrr]

Yep this capture doesn't seem to have the POST from 192.168.1.177 recorded. If you are recording on the router side, check which interface you are using (eth/wifi). If recording from the air, check that your adapter is in monitor mode, on the right channel, on the right network.

[KyleHunter]

@igrr Any idea how I can do that? I have a linksys wrt1900c and can't see any way to do it from that. Also, do you have a skype or some other form of communication that would be easier than this?
Thanks for all your help

Just saw something interesting.. So I started looping my posts when it failed until success, and this showed up once:

RSSI strength: -39
Success?: 1
Post len: 200
{"this":"succeeded","by":"dweeting","the":"stored_dweets","with":{"content":{"data":[0.24,-0.27,0.11,0.11,0.08,-0.07,0.19,0.04,0.19,-0.22,-0.32,0.28,-0.01,0.01,0.04,0.09,0.01,0.16,0.11,-0.39,0.1,0.16,-0.4,-0.1,0.04,-0.02,-0.37,-0.04,-0.09,0.08,-0.22,-0.04,0.02,0.74,-0.37,0.2,0.23,0.2,0.37,0.12,0.04,-0.07,0,0.24,0.29,0.2,0.09,-0.13,0.04,0.18,0.12,0.13,0.13,0.06,-0.29,0.13,0.01,-0.29,0.13,-0.16,0.27,-0.05,0.06,-0.03,-0.12,0.21,-0.26,0.25,-0.15,0.34,0.08,0.22,0.14,-0.17,-0.13,-0.02,-0.32,0.02,-0.17,0.3,0.09,0.18,-0.02,-0.03,0.2,0.26,-0.01,-0.18,0.13,0.11,0.32,-0.14,-0.1,0.08,0.27,-0.18,0.16,-0.26,0.07,0.02,0.02,-0.06,0.1,0,-0.03,-0.12,0.38,0.11,-0.11,0.2,0.03,0.05,0.08,-0.05,-0.34,0.07,-0.11,0.02,-0.04,0.13,0.17,-0.06,0.02,-0.18,0.22,-0.1,0.23,-0.39,0.08,0.16,0.22,-0.03,0.08,0.24,-0.07,-0.21,-0.03,-0.08,0.06,-0.06,0.19,-0.03,0.08,0.18,0.05,0.08,0.11,0.19,0.21,-0.27,-0.02,0.22,0.09,-0.24,0,-0.35,0.22,0.09,0.21,0.19,-0.01,0.01,-0.16,-0.03,-0.01,0.07,0.02,0.04,-0.12,-0.05,0.26,-0.01,-0.33,0.11,-0.01,0.08,0.15,-0.31,0.24,0,0.27,-0.34,-0.04,-0.05,0.01,0.32,0.41,0.14,0.15,-0.02,-0.03,0.29,0,0.16,0.15,0.19,-0.16,0.01,-0.03,0.19,-0.08,0.17,0.03,0,0.24,-0.03,-0.34,0.18,0.03,0.09,0.24,0.12,0.43,-0.23,0.08,-0.36,-0.02,-0.35,-0.01,-0.03,0.4,-0.22,-0.21,0.12,-0.06,-0.08,-0.12,0.07,-0.18,-0.06,0.09,0.01,-0.07,0.08,0.12,0.06,0,0.09,0.06,-0.04,0.16,0.24,0,0.02,0.01,-0.11,0.16,0.2,-0.08,0],"earthquake_occured":false,"status":"OK"},"thing":"Thing_Test","account":"LOCAL","created":"2017-05-20T13:39:52.488Z","transaction":"xx"}}
Ended
RSSI strength: -41
Success?: 1
Post len: -11

Success?: 1

Post len: -11

Success?: 1
Post len: -11

Success?: 1
Post len: 200
{"this":"failed","because":"Rate limit exceeded, try again in 1 second(s)."}

The "{"this":"failed","because":"Rate limit exceeded, try again in 1 second(s)."}" shows me that the esp is making a post maybe, but something is happening afterwards..? I'm at a loss, but since they said my rate limit is exceeded, the others got through to some extent.

Also, the .POST takes ~100ms when successful, and > 5seconds when not. The SetTimeout() doesn't work either.

Tried doing indentical posts from my computer with python, and I sent them for 45 minutes without a single one failing. So it's not on the servers end

Yeah definitely is an issue with the timeout. One post just took 70 seconds before failing, another took 123 seconds. If that is fixed and I could use a 1 second timeout I think I could just keep looping until it is successful.

When it takes that long, instead of returning a negative number indicating a failure, it returns a higher number than a successful post, like ~500.

Even causes the occasional wdr:
https://www.hastebin.com/moqusoxelo.go

[KyleHunter]

@igrr Managed to set up a hotspot on my laptop, connect the esp to it, and sniff the data from it.

Here's what I got: https://drive.google.com/file/d/0B5-5-5KtayGhdTFISHZjSFZmYzg/view?usp=sharing

Contains successful posts, and failures.

Thank you so much again for all of your help

[igrr]

There's one case around time=1108 where ESP8266 doesn't receive the SYN/ACK when connection is being established, even though the remote retransmits it 5 times. I don't have an immediate clue why that would be happening, but will try a few things.

The other cases, towards the bottom of the dump show that the remote replies with HTTP/1.1 504 GATEWAY_TIMEOUT. Whether this is intentional (=rate limiting) or unintentional (something wrong with their reverse proxy setup) I don't know.

[KyleHunter]

@igrr Yeah I could see the 5 time retry live while it was failing to post also..

Found these issues which seem fairly similar:
http://www.esp8266.com/viewtopic.php?f=6&t=770&start=20
http://www.esp8266.com/viewtopic.php?f=6&t=1633&start=40

Wonder if it could be dependent on the wifi router I have? I'm using the dual band 5/2.4ghz wrt1900ac which is a pretty darn powerful router. I've noticed that if i'm not in the same room as it, i'm not able to connect to wifi, which seems odd to me.

Also, if you need help to recreate the problem, you can teamview my computer while it is happening

[KyleHunter]

@igrr So, not 100% sure that the problem is fixed, but it has been running for ~18 hours without any failures, so it seems like it very well may be.

What I did, is disabled the 5Ghz band on my dual band router. The SSID for the 2.4Ghz was in this format: "thisisthessid" and the 5Ghz was "thisis thessid". The same ssid, but one has a space in it.

Maybe the esp would get confused with the two different ssids or something?

EDIT: Yeah @igrr been running for two days now, hasn't failed a single time, so I would say that the issues definitely with the dual band router. I'll try to debug some stuff later. So either there is interference with the 5Ghz signal, or a bug with the similar names of the networks.