Running the library without #define DEBUG results in failures to connect to pushdata.io

[kaderud]

I'm experiencing very weird behaviour with the library depending on if I enable #define DEBUG in the library.

If I run it without DEBUG, I get random connection failures. If I enable DEBUG, the code seems to run flawlessly. Granted, I haven't dug into the library code to see if there's a difference with debug enabled, so this might be known already.

Arduino 1.8.8 under Linux; tested with NodeMCU 1.0, using ESP8266 Core v2.5.0

[kaderud]

Running library WITHOUT #define DEBUG

Logs from running example code pushing a random value to a defined time series (pd.send("Temperature", mRange);) results in various connection failures:

02:14:18.357 -> Connecting to 0xCAFEBABE
02:14:18.975 -> .....
02:14:22.124 -> WiFi connected
02:14:22.124 -> IP address: 10.10.0.23
02:14:22.124 -> Ethernet MAC address = a0:xx:xx:xx:xx:xx
02:15:21.965 -> Pushing value => -13
02:16:22.370 -> Pushing value => 15
02:17:33.350 -> Pushdata_ESP8266: Error: failed to connect to pushdata.io:443
02:17:33.350 -> Last SSL error was:
02:17:33.350 -> Unknown error code.
02:17:33.350 -> ERRCODE: 0
02:17:33.350 -> Pushing value => 0
02:18:33.329 -> Pushdata_ESP8266: Error: failed to connect to pushdata.io:443
02:18:33.363 -> Last SSL error was:
02:18:33.363 -> Unknown error code.
02:18:33.363 -> ERRCODE: 0
02:18:33.363 -> Pushing value => -19
02:19:33.331 -> Pushdata_ESP8266: Error: failed to connect to pushdata.io:443
02:19:33.331 -> Last SSL error was:
02:19:33.365 -> Unknown error code.
02:19:33.365 -> ERRCODE: 0
02:19:33.365 -> Pushing value => -19
02:20:30.592 -> Pushdata_ESP8266: Error: failed to connect to pushdata.io:443
02:20:30.592 -> Last SSL error was:
02:20:30.592 -> Unknown error code.
02:20:30.592 -> ERRCODE: 0
02:20:30.592 -> Pushing value => -16
02:21:21.520 -> Pushing value => -11
02:22:21.559 -> Pushing value => 7
02:23:21.502 -> Pushing value => 14
02:24:33.339 -> Pushdata_ESP8266: Error: failed to connect to pushdata.io:443
02:24:33.339 -> Last SSL error was:
02:24:33.339 -> Unknown error code.
02:24:33.372 -> ERRCODE: 0
[..]
03:12:33.401 -> Pushing value => -12
03:13:21.836 -> Pushing value => 3
03:14:33.411 -> Pushdata_ESP8266: Error: failed to connect to pushdata.io:443
03:14:33.411 -> Last SSL error was:
03:14:33.411 -> Unknown error code.
03:14:33.411 -> ERRCODE: 0
03:14:33.411 -> Pushing value => 16
03:15:21.805 -> Pushing value => -7
03:16:21.774 -> Pushing value => -13
03:17:21.634 -> Pushing value => -18
03:18:21.722 -> Pushing value => -17
03:19:21.633 -> Pushing value => 18
03:20:21.660 -> Pushing value => 19
03:21:21.781 -> Pushing value => 19
03:22:22.438 -> Pushing value => -10
03:23:22.235 -> Pushing value => -5
03:24:21.869 -> Pushing value => -11
03:25:21.697 -> Pushing value => 6
03:26:21.679 -> Pushing value => 15

(I just noticed I have my Serial.println after pd.send())

[kaderud]

Running library WITH #define DEBUG

Logs from running example code pushing a random value to a defined time series (pd.send("Temperature", mRange);) results in NO failures:

03:28:41.684 -> Connecting to 0xCAFEBABE
03:28:41.684 -> Pushdata_8266_SSL: Lost WiFi connection, reconnecting
03:28:41.902 -> .....Pushdata_8266_SSL: Connected to network 0xCAFEBABE
03:28:45.050 -> 
03:28:45.050 -> WiFi connected
03:28:45.050 -> IP address: 10.10.0.23
03:28:45.083 -> Ethernet MAC address = a0:xx:xx:xx:xx:xx
03:29:41.253 -> Pushdata_8266_SSL: BearSSL::WifiClientSecure init
03:29:41.253 -> Pushdata_8266_SSL: BearSSLPublicKey init
03:29:41.286 -> Pushdata_8266_SSL: key.parse() succeeded
03:29:41.286 -> Pushdata_8266_SSL: client.setKnownKey()
03:29:41.286 -> Pushdata_8266_SSL: client.connect()
03:29:43.671 -> Pushdata_8266_SSL: connect took 2388 ms
03:29:43.671 -> Pushdata_8266_SSL: Connected to pushdata.io:443
03:29:43.671 -> Pushdata_8266_SSL: packetBuf: len=54
03:29:43.671 ->    {"name":"Temperature","points":[{"value":-10.000000}]}
03:29:44.865 -> Pushdata_8266_SSL: Wrote 241 bytes
03:29:44.865 -> Pushdata_8266_SSL: request sent, reading response:
03:29:44.865 ->    HTTP/1.1 201 Created
03:29:44.865 ->    Server: nginx/1.14.0 (Ubuntu)
03:29:44.865 ->    Date: Thu, 07 Mar 2019 02:29:44 GMT
03:29:44.865 ->    Content-Type: text/plain; charset=utf-8
03:29:44.865 ->    Content-Length: 1
03:29:44.865 ->    Connection: close
03:29:44.865 ->    X-Content-Type-Options: nosniff
03:29:44.898 ->    X-Frame-Options: DENY
03:29:44.898 ->    
03:29:44.898 ->    
03:29:44.898 -> Pushing value => -10
03:30:41.270 -> Pushdata_8266_SSL: BearSSL::WifiClientSecure init
03:30:41.270 -> Pushdata_8266_SSL: BearSSLPublicKey init
03:30:41.270 -> Pushdata_8266_SSL: key.parse() succeeded
03:30:41.270 -> Pushdata_8266_SSL: client.setKnownKey()
03:30:41.270 -> Pushdata_8266_SSL: client.connect()
03:30:43.490 -> Pushdata_8266_SSL: connect took 2227 ms
03:30:43.490 -> Pushdata_8266_SSL: Connected to pushdata.io:443
03:30:43.490 -> Pushdata_8266_SSL: packetBuf: len=53
03:30:43.562 ->    {"name":"Temperature","points":[{"value":-7.000000}]}
03:30:44.518 -> Pushdata_8266_SSL: Wrote 240 bytes
03:30:44.518 -> Pushdata_8266_SSL: request sent, reading response:
03:30:44.518 ->    HTTP/1.1 201 Created
03:30:44.610 ->    Server: nginx/1.14.0 (Ubuntu)
03:30:44.610 ->    Date: Thu, 07 Mar 2019 02:30:44 GMT
03:30:44.610 ->    Content-Type: text/plain; charset=utf-8
03:30:44.610 ->    Content-Length: 1
03:30:44.610 ->    Connection: close
03:30:44.610 ->    X-Content-Type-Options: nosniff
03:30:44.610 ->    X-Frame-Options: DENY
[..]
04:56:44.581 -> Pushing value => 18
04:57:41.347 -> Pushdata_8266_SSL: BearSSL::WifiClientSecure init
04:57:41.380 -> Pushdata_8266_SSL: BearSSLPublicKey init
04:57:41.380 -> Pushdata_8266_SSL: key.parse() succeeded
04:57:41.380 -> Pushdata_8266_SSL: client.setKnownKey()
04:57:41.380 -> Pushdata_8266_SSL: client.connect()
04:57:43.568 -> Pushdata_8266_SSL: connect took 2180 ms
04:57:43.568 -> Pushdata_8266_SSL: Connected to pushdata.io:443
04:57:43.568 -> Pushdata_8266_SSL: packetBuf: len=53
04:57:43.568 ->    {"name":"Temperature","points":[{"value":13.000000}]}
04:57:44.530 -> Pushdata_8266_SSL: Wrote 240 bytes
04:57:44.530 -> Pushdata_8266_SSL: request sent, reading response:
04:57:44.530 ->    HTTP/1.1 201 Created
04:57:44.563 ->    Server: nginx/1.14.0 (Ubuntu)
04:57:44.563 ->    Date: Thu, 07 Mar 2019 03:57:44 GMT
04:57:44.563 ->    Content-Type: text/plain; charset=utf-8
04:57:44.563 ->    Content-Length: 1
04:57:44.563 ->    Connection: close
04:57:44.563 ->    X-Content-Type-Options: nosniff
04:57:44.563 ->    X-Frame-Options: DENY
04:57:44.563 ->    
04:57:44.563 ->    
04:57:44.563 -> Pushing value => 13
04:58:41.368 -> Pushdata_8266_SSL: BearSSL::WifiClientSecure init
04:58:41.368 -> Pushdata_8266_SSL: BearSSLPublicKey init
04:58:41.368 -> Pushdata_8266_SSL: key.parse() succeeded
04:58:41.368 -> Pushdata_8266_SSL: client.setKnownKey()
04:58:41.401 -> Pushdata_8266_SSL: client.connect()
04:58:43.557 -> Pushdata_8266_SSL: connect took 2193 ms
04:58:43.590 -> Pushdata_8266_SSL: Connected to pushdata.io:443
04:58:43.590 -> Pushdata_8266_SSL: packetBuf: len=53
04:58:43.590 ->    {"name":"Temperature","points":[{"value":-2.000000}]}
04:58:44.551 -> Pushdata_8266_SSL: Wrote 240 bytes
04:58:44.551 -> Pushdata_8266_SSL: request sent, reading response:
04:58:44.551 ->    HTTP/1.1 201 Created
04:58:44.551 ->    Server: nginx/1.14.0 (Ubuntu)
04:58:44.551 ->    Date: Thu, 07 Mar 2019 03:58:44 GMT
04:58:44.551 ->    Content-Type: text/plain; charset=utf-8
04:58:44.551 ->    Content-Length: 1
04:58:44.551 ->    Connection: close
04:58:44.551 ->    X-Content-Type-Options: nosniff
04:58:44.584 ->    X-Frame-Options: DENY
04:58:44.584 ->    
04:58:44.584 ->    
04:58:44.584 -> Pushing value => -2

[kaderud]

[ragnarlonn]

@kaderud This does indeed sound strange. Defining DEBUG just means there will be a lot of Serial.print() and Serial.println() calls activated throughout the code. I can just think of 2 potential causes:

1. Some debug text I am printing is not properly null-terminated or a wild pointer, causing undefined behaviour. This would be the most likely problem if it wasn't for the fact that your program doesn't seem to crash (not crashing makes it a bit less likely this is the issue).

2. The serial communication takes a bit of time, so enabling DEBUG will cause the code to execute slower at various points. There could be some timing issue when doing the TCP connect, or similar.

Would be interesting if you put in a "delay(50);" in a couple of different places, to see if a delay in the right spot will make the program start working. I'd try a delay just before and after the system_update_cpu_freq() call on line 118, and the yield() call on line 132. You can also try removing those calls from the library - the yield() shouldn't really be necessary and if you don't change the CPU frequency it just means the TLS handshake will take 3 seconds instead of 2, which is usually OK.

[ragnarlonn]

There is one other thing:

Here is line 134-136:

#ifdef DEBUG
unsigned long startConnect = millis();
#endif

That variable doesn't get declared unless DEBUG is defined. Later on, we refer to it, but inside a DEFINEd macro, on line 148:

DBGPRINTH("connect took "); DBGPRINT(millis()-startConnect); DBGPRINTLN(" ms");

AFAIK, this shouldn't be an issue. The preprocessor should resolve "DBGPRINT(millis()-startConnect)" to an empty string when DEBUG isn't defined, but just to be paranoid I would also test removing that line (148).

[ragnarlonn]

And perhaps try commenting out line 43:

DBGPRINTH("Connected to network "); DBGPRINTLN(WiFi.SSID().c_str());

(in case there is a problem referring to WiFi.SSID().c_str())

Oh, and of course this is all assuming you have the time and will to take a look at it. I don't think I can reproduce the issue myself, so it is hard for me to debug. Totally understand if you don't want to spend time on it! Then I'll just have to try and reproduce your setup.

[kaderud]

@ragnarlonn Thanks for all the suggestions, I'll definitely try them out! I really like this project and the system you've built seems really "user-friendly", and easy, with great potential for all the makers & iot coders out there! I really want to see this project grow and succeed, in what ever small way I may help.