hostByName encounters IN_PROGRESS status and immediately returns

[alberthdev]

During a normal client connection, there are periods within execution that the client fails to connect with the server immediately without any noticeable delay. (This means that in my serial logs, the program would print a connection attempt, and immediately print that it failed.)

My code essentially can be boiled down to this:

  // Use WiFiClient class to create TCP connections
  WiFiClient client;
  
  // WiFi MAC address should be populated at this point!
  
  if (client.connect(server, 80)) {
    // do stuff here
  } else {
    Serial.println("ERROR: Connection failed!");
    Serial.print("WiFi.status() = ");
    Serial.println(WiFi.status());
  }

"Do stuff here" executes successfully for the first few data transmissions, and then begins to fail afterwards for a significant period of time, usually for 2-6 minutes of failed connections before sparsely succeeding again.

Upon enabling debugging on Serial, as well as Core+WiFi debugging, I see this:

[hostByName] request IP for: example.com
[hostByName] Host: example.com IP: xxx.xx.xxx.xxx
:ref 1
...
[hostByName] request IP for: example.com
bcn_timout,ap_probe_send_start
[hostByName] Host: example.com lookup error: -5!
ERROR: Connection failed!
WiFi.status() = 3
Collecting data...
 - Current mid thresh: 500
 - Current high thresh: 600
Transmit NTP Request
:urn 48
Receive NTP Response
:urd 48, 48, 0
...
[hostByName] request IP for: example.com
[hostByName] Host: example.com lookup error: -5!
ERROR: Connection failed!
WiFi.status() = 3

At the very beginning, hostByName succeeds. After a few lookups, however, it begins failing as shown above.

I've traced this message to here, where there is some info about the message printed. Searching the error codes leads to this header, which defines each error semantically. -5 seems to be the IN_PROGRESS error, which seems to get handled but does not seem to pause for execution to succeed.

As an additional check, I tried using the latest version on Git (with the newest SDK 2.1.0 branch), and this problem seems to occur there too.

Is this an error on my part (as in should I be specifying a timeout of some sort?), or is there some sort of strange handling going on in the library?

[igrr]

Hi, i have tried running the code snipped (setting server to example.com), but i can't get this issue reproduced. Could you give a more complete example which shows the issue?

[alberthdev]

Unfortunately, the code above no longer exists - I've switched to the builtin HTTP library, which seems to work better.

If you don't mind running the entire project, it requires TimeLib and can be found here. The HTTP based rewrite still encounters some oddities from time to time, as seen below:

[2017-06-27 12:46:37,948] [submitSum] >> http://.../datasubmit?id=fffffffffff&d=1498581998,0,0,86890
[2017-06-27 12:46:37,950] [sturdyHTTP] Attempt 1/5
[2017-06-27 12:46:37,958] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498581998,0,0,86890
[2017-06-27 12:46:37,964] [sturdyHTTP] HTTP GET... failed, error: connection refused
[2017-06-27 12:46:37,966] [sturdyHTTP] Attempt 2/5
[2017-06-27 12:46:37,974] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498581998,0,0,86890
[2017-06-27 12:46:38,445] [sturdyHTTP] ** Server responded with 15 byte payload
[2017-06-27 12:46:38,448] [sturdyHTTP] << SenseOK:600:700
[2017-06-27 12:46:38,453] [setCalibration] ----------- setCalibration -----------
--
[2017-06-27 12:46:48,011] [submitSum] >> http://.../datasubmit?id=fffffffffff&d=1498582008,0,0,86481
[2017-06-27 12:46:48,013] [sturdyHTTP] Attempt 1/5
[2017-06-27 12:46:48,021] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498582008,0,0,86481
[2017-06-27 12:46:48,027] [sturdyHTTP] HTTP GET... failed, error: connection refused
[2017-06-27 12:46:48,029] [sturdyHTTP] Attempt 2/5
[2017-06-27 12:46:48,037] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498582008,0,0,86481
[2017-06-27 12:46:48,330] [sturdyHTTP] ** Server responded with 15 byte payload
[2017-06-27 12:46:48,332] [sturdyHTTP] << SenseOK:600:700
[2017-06-27 12:46:48,337] [setCalibration] ----------- setCalibration -----------
--
[2017-06-27 12:46:58,063] [submitSum] >> http://.../datasubmit?id=fffffffffff&d=1498582018,0,0,88171
[2017-06-27 12:46:58,065] [sturdyHTTP] Attempt 1/5
[2017-06-27 12:46:58,073] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498582018,0,0,88171
[2017-06-27 12:46:58,078] [sturdyHTTP] HTTP GET... failed, error: connection refused
[2017-06-27 12:46:58,081] [sturdyHTTP] Attempt 2/5
[2017-06-27 12:46:58,089] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498582018,0,0,88171
[2017-06-27 12:46:58,499] [sturdyHTTP] ** Server responded with 15 byte payload
[2017-06-27 12:46:58,501] [sturdyHTTP] << SenseOK:600:700
[2017-06-27 12:46:58,506] [setCalibration] ----------- setCalibration -----------
--
[2017-06-27 12:47:08,121] [sturdyHTTP] Attempt 1/5
[2017-06-27 12:47:08,129] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498582028,0,0,87021
[2017-06-27 12:47:08,132] bcn_timout,ap_probe_send_start
[2017-06-27 12:47:08,137] [sturdyHTTP] HTTP GET... failed, error: connection refused
[2017-06-27 12:47:08,139] [sturdyHTTP] Attempt 2/5
[2017-06-27 12:47:08,147] [sturdyHTTP] >> http://.../datasubmit?id=fffffffffff&d=1498582028,0,0,87021
[2017-06-27 12:47:08,642] [sturdyHTTP] ** Server responded with 15 byte payload
[2017-06-27 12:47:08,645] [sturdyHTTP] << SenseOK:600:700
[2017-06-27 12:47:08,650] [setCalibration] ----------- setCalibration -----------

If running this full project is a bit overwhelming, I think a simpler example would be to run a GET request every 10-12 seconds in a loop, and catch any errors that may occur. This is essentially what my project is doing at the moment, and could probably significantly reduce the noise for finding the possible bug.

EDIT: Something else that may help - not sure if this is related, but the 10-12 second delay in my code is a while loop that constantly checks the time. This while loop requires me to feed the WDT in order to prevent a reset... not sure if that would impact the WiFi or not.

[jsdevel]

I'm seeing this now with WifiClientSecure

[jsdevel]

I was able to resolve my hostByName issue. See #4949

[devyte]

Closing per previous comment.