search

robertklep / nefit-easy-core

Core functionality to implementation communications with Nefit/Bosch backend.
MIT License
21 stars 4 forks source link

UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14663): TypeError: Cannot read property 'write' of null #14

Open koenkooi opened 6 years ago

koenkooi commented 6 years ago

After updating to get SCRAM-SHA1 and updating node to 8.9.4 I'm getting errors like the one below:

Jun 02 08:50:19 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14582): TypeError: Cannot read property 'write' of null
Jun 02 08:50:49 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14584): TypeError: Cannot read property 'write' of null
Jun 02 08:50:55 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14586): TypeError: Cannot read property 'write' of null
Jun 02 08:50:57 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14588): TypeError: Cannot read property 'write' of null
Jun 02 08:50:59 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14590): TypeError: Cannot read property 'write' of null
Jun 02 08:51:01 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14592): TypeError: Cannot read property 'write' of null
Jun 02 08:51:03 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14594): TypeError: Cannot read property 'write' of null
Jun 02 08:51:05 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14596): TypeError: Cannot read property 'write' of null
Jun 02 08:51:07 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14598): TypeError: Cannot read property 'write' of null
Jun 02 08:51:09 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14600): TypeError: Cannot read property 'write' of null
Jun 02 08:51:11 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14602): TypeError: Cannot read property 'write' of null
Jun 02 08:51:13 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14604): TypeError: Cannot read property 'write' of null
Jun 02 08:51:15 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14606): TypeError: Cannot read property 'write' of null
Jun 02 08:51:17 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14608): TypeError: Cannot read property 'write' of null
Jun 02 08:51:19 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14610): TypeError: Cannot read property 'write' of null
Jun 02 08:51:19 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14612): TypeError: Cannot read property 'write' of null
Jun 02 08:51:21 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14614): TypeError: Cannot read property 'write' of null
Jun 02 08:51:23 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14616): TypeError: Cannot read property 'write' of null
Jun 02 08:51:25 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14618): TypeError: Cannot read property 'write' of null
Jun 02 08:51:27 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14620): TypeError: Cannot read property 'write' of null
Jun 02 08:51:29 solar easy-server[18668]: Error: MAX_RETRIES_REACHED
Jun 02 08:51:29 solar easy-server[18668]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 02 08:51:29 solar easy-server[18668]:     at <anonymous>
Jun 02 08:51:29 solar easy-server[18668]: 172.20.0.66 - - [02/Jun/2018:06:51:29 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.51548.0 Safari/602.37"
Jun 02 08:51:49 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14623): TypeError: Cannot read property 'write' of null
Jun 02 08:52:19 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14625): TypeError: Cannot read property 'write' of null
Jun 02 08:52:49 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14627): TypeError: Cannot read property 'write' of null
Jun 02 08:53:00 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14629): TypeError: Cannot read property 'write' of null
Jun 02 08:53:02 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14631): TypeError: Cannot read property 'write' of null
Jun 02 08:53:04 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14633): TypeError: Cannot read property 'write' of null
Jun 02 08:53:06 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14635): TypeError: Cannot read property 'write' of null
Jun 02 08:53:08 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14637): TypeError: Cannot read property 'write' of null
Jun 02 08:53:10 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14639): TypeError: Cannot read property 'write' of null
Jun 02 08:53:12 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14641): TypeError: Cannot read property 'write' of null
Jun 02 08:53:14 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14643): TypeError: Cannot read property 'write' of null
Jun 02 08:53:16 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14645): TypeError: Cannot read property 'write' of null
Jun 02 08:53:18 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14647): TypeError: Cannot read property 'write' of null
Jun 02 08:53:19 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14649): TypeError: Cannot read property 'write' of null
Jun 02 08:53:20 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14651): TypeError: Cannot read property 'write' of null
Jun 02 08:53:22 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14653): TypeError: Cannot read property 'write' of null
Jun 02 08:53:24 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14655): TypeError: Cannot read property 'write' of null
Jun 02 08:53:26 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14657): TypeError: Cannot read property 'write' of null
Jun 02 08:53:28 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14659): TypeError: Cannot read property 'write' of null
Jun 02 08:53:30 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14661): TypeError: Cannot read property 'write' of null
Jun 02 08:53:32 solar easy-server[18668]: (node:18668) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 14663): TypeError: Cannot read property 'write' of null
Jun 02 08:53:34 solar easy-server[18668]: Error: MAX_RETRIES_REACHED
Jun 02 08:53:34 solar easy-server[18668]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 02 08:53:34 solar easy-server[18668]:     at <anonymous>
Jun 02 08:53:34 solar easy-server[18668]: 172.20.0.66 - - [02/Jun/2018:06:53:34 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.51548.0 Safari/602.37"

Restarting the server makes it work for about a day:

Jun 02 08:54:13 solar systemd[1]: Stopping Nefit Easy http bridge...
Jun 02 08:54:13 solar systemd[1]: Stopped Nefit Easy http bridge.
Jun 02 08:54:13 solar systemd[1]: Started Nefit Easy http bridge.
Jun 02 08:54:27 solar easy-server[4874]: HTTP server listening on http://0.0.0.0:3000
Jun 02 08:55:04 solar easy-server[4874]: 172.20.0.66 - - [02/Jun/2018:06:55:04 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 200 496 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.51548.0 Safari/602.37"
robertklep commented 6 years ago

Might be caused by the server losing the network connection. I'll investigate, thanks for the bug report!

EDIT: yeah, this happens when the connection gets lost. I'll see if I can implement some sort of auto reconnect.

robertklep commented 6 years ago

I have a possible fix, if you're willing to try it:

npm i robertklep/nefit-easy-core -g

This updates the nefit-easy-core package (which is a dependency of the server) to make it more robust when the connection gets lost.

If it works okay for you (I suggest running it for at least a day; I don't run the server myself, but I'm testing it in another project), let me know and I'll do a proper release.

koenkooi commented 6 years ago

Thanks for the quick response, I did

root@solar:~# systemctl stop easy ; npm i robertklep/nefit-easy-core -g ; systemctl start easy
+ nefit-easy-core@3.0.0
added 59 packages in 59.451s

And will let it run for a few days. It seems to trigger once a day, so I'll report back around wednesday.

robertklep commented 6 years ago

Cool, thanks for helping out :)

It may still output some warnings when the connection gets lost, but it should pick back up once the server is back online.

koenkooi commented 6 years ago

I think I know what's causing these issues. When I reboot the WIFI accespoint the Nefit unit is connected to I get this:

-- Logs begin at Tue 2016-08-02 09:33:41 CEST. --
Jun 04 08:37:51 solar easy-server[21928]: Error: MAX_RETRIES_REACHED
Jun 04 08:37:51 solar easy-server[21928]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 04 08:37:51 solar easy-server[21928]:     at <anonymous>

It's a bit too early to declare victory, but your fix seems to be working so far.

koenkooi commented 6 years ago

Yesterday around 15:00 it happened again, but that portion has rotated out of the logs already :( The syslog is again filled with repeating entries like this:

Jun 04 21:41:15 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8883): TypeError: Cannot read property 'write' of null
Jun 04 21:41:17 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8885): TypeError: Cannot read property 'write' of null
Jun 04 21:41:19 solar easy-server[21928]: Error: MAX_RETRIES_REACHED
Jun 04 21:41:19 solar easy-server[21928]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 04 21:41:19 solar easy-server[21928]:     at <anonymous>
Jun 04 21:41:19 solar easy-server[21928]: 172.20.0.66 - - [04/Jun/2018:19:41:19 +0000] "GET /bridge/ecus/rrc/recordings/yearTotal HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/601.36 (KHTML, like Gecko) Chrome/53.0.4515.0 Safari/601.36"
Jun 04 21:41:44 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8888): TypeError: Cannot read property 'write' of null
Jun 04 21:42:14 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8890): TypeError: Cannot read property 'write' of null
Jun 04 21:42:29 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8892): TypeError: Cannot read property 'write' of null
Jun 04 21:42:31 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8894): TypeError: Cannot read property 'write' of null
Jun 04 21:42:33 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8896): TypeError: Cannot read property 'write' of null
Jun 04 21:42:35 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8898): TypeError: Cannot read property 'write' of null
Jun 04 21:42:37 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8900): TypeError: Cannot read property 'write' of null
Jun 04 21:42:39 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8902): TypeError: Cannot read property 'write' of null
Jun 04 21:42:41 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8904): TypeError: Cannot read property 'write' of null
Jun 04 21:42:43 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8906): TypeError: Cannot read property 'write' of null
Jun 04 21:42:44 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8908): TypeError: Cannot read property 'write' of null
Jun 04 21:42:45 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8910): TypeError: Cannot read property 'write' of null
Jun 04 21:42:47 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8912): TypeError: Cannot read property 'write' of null
Jun 04 21:42:49 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8914): TypeError: Cannot read property 'write' of null
Jun 04 21:42:51 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8916): TypeError: Cannot read property 'write' of null
Jun 04 21:42:53 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8918): TypeError: Cannot read property 'write' of null
Jun 04 21:42:55 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8920): TypeError: Cannot read property 'write' of null
Jun 04 21:42:57 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8922): TypeError: Cannot read property 'write' of null
Jun 04 21:42:59 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8924): TypeError: Cannot read property 'write' of null
Jun 04 21:43:01 solar easy-server[21928]: (node:21928) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 8926): TypeError: Cannot read property 'write' of null
Jun 04 21:43:03 solar easy-server[21928]: Error: MAX_RETRIES_REACHED
Jun 04 21:43:03 solar easy-server[21928]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 04 21:43:03 solar easy-server[21928]:     at <anonymous>
Jun 04 21:43:03 solar easy-server[21928]: 172.20.0.66 - - [04/Jun/2018:19:43:03 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/601.36 (KHTML, like Gecko) Chrome/53.0.4515.0 Safari/601.36"
robertklep commented 6 years ago

Did it eventually recover, though? Previously, once the connection was gone, any subsequent requests would fail (even if the Easy was back online again).

koenkooi commented 6 years ago

It sadly didn't recover, no data from yesterday afternoon till I restarted it this morning:

schermafbeelding 2018-06-05 om 08 46 33

I've quadrupled the syslog buffer so I can hopefully catch the moment it happens.

Also, the AP didn't have any problems yesterday afternoon, but the ISP modem did drop the connection around that time:

[Mon Jun  4 15:28:24 2018] igb 0000:01:00.0 enp1s0: igb: enp1s0 NIC Link is Down
[Mon Jun  4 15:29:02 2018] igb 0000:01:00.0 enp1s0: igb: enp1s0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
robertklep commented 6 years ago

It happens when the connection gets lost somehow.

I guess I'll have to do a bit more experimenting :(

koenkooi commented 6 years ago

I managed to capture a better log last night:

Jun 05 23:44:03 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:44:03 +0000] "GET /bridge/heatingCircuits/hc1/actualSupplyTemperature HTTP/1.1" 200 163 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:44:04 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:44:04 +0000] "GET /bridge/system/appliance/displaycode HTTP/1.1" 200 101 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:45:08 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:45:08 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:45:08 solar easy-server[12498]:     at <anonymous>
Jun 05 23:45:08 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:45:08 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:46:13 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:46:13 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:46:13 solar easy-server[12498]:     at <anonymous>
Jun 05 23:46:13 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:46:13 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:48:17 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:48:17 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:48:17 solar easy-server[12498]:     at <anonymous>
Jun 05 23:48:17 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:48:17 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:50:21 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:50:21 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:50:21 solar easy-server[12498]:     at <anonymous>
Jun 05 23:50:21 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:50:21 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:50:56 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:50:56 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:50:56 solar easy-server[12498]:     at <anonymous>
Jun 05 23:50:56 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:50:56 +0000] "GET /bridge/system/appliance/systemPressure HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:53:00 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:53:00 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:53:00 solar easy-server[12498]:     at <anonymous>
Jun 05 23:53:00 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:53:00 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:53:44 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:53:44 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:53:44 solar easy-server[12498]:     at <anonymous>
Jun 05 23:53:44 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:53:44 +0000] "GET /bridge/ecus/rrc/recordings/yearTotal HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:55:38 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:55:38 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:55:38 solar easy-server[12498]:     at <anonymous>
Jun 05 23:55:38 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:55:38 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:57:43 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:57:43 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:57:43 solar easy-server[12498]:     at <anonymous>
Jun 05 23:57:43 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:57:43 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 05 23:58:47 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 05 23:58:47 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 05 23:58:47 solar easy-server[12498]:     at <anonymous>
Jun 05 23:58:47 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:21:58:47 +0000] "GET /bridge/system/appliance/systemPressure HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 06 00:00:21 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 06 00:00:21 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 06 00:00:21 solar easy-server[12498]:     at <anonymous>
Jun 06 00:00:21 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:22:00:21 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
Jun 06 00:01:27 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 13): TypeError: Cannot read property 'write' of null
Jun 06 00:01:27 solar easy-server[12498]: (node:12498) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
Jun 06 00:01:52 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 15): TypeError: Cannot read property 'write' of null
Jun 06 00:01:54 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 17): TypeError: Cannot read property 'write' of null
Jun 06 00:01:56 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 19): TypeError: Cannot read property 'write' of null
Jun 06 00:01:57 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 21): TypeError: Cannot read property 'write' of null
Jun 06 00:01:58 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 23): TypeError: Cannot read property 'write' of null
Jun 06 00:02:00 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 25): TypeError: Cannot read property 'write' of null
Jun 06 00:02:02 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 27): TypeError: Cannot read property 'write' of null
Jun 06 00:02:04 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 29): TypeError: Cannot read property 'write' of null
Jun 06 00:02:06 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 31): TypeError: Cannot read property 'write' of null
Jun 06 00:02:08 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 33): TypeError: Cannot read property 'write' of null
Jun 06 00:02:10 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 35): TypeError: Cannot read property 'write' of null
Jun 06 00:02:12 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 37): TypeError: Cannot read property 'write' of null
Jun 06 00:02:14 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 39): TypeError: Cannot read property 'write' of null
Jun 06 00:02:16 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 41): TypeError: Cannot read property 'write' of null
Jun 06 00:02:18 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 43): TypeError: Cannot read property 'write' of null
Jun 06 00:02:20 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 45): TypeError: Cannot read property 'write' of null
Jun 06 00:02:22 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 47): TypeError: Cannot read property 'write' of null
Jun 06 00:02:24 solar easy-server[12498]: (node:12498) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 49): TypeError: Cannot read property 'write' of null
Jun 06 00:02:26 solar easy-server[12498]: Error: MAX_RETRIES_REACHED
Jun 06 00:02:26 solar easy-server[12498]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:199:51)
Jun 06 00:02:26 solar easy-server[12498]:     at <anonymous>
Jun 06 00:02:26 solar easy-server[12498]: 172.20.0.66 - - [05/Jun/2018:22:02:26 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/602.38 (KHTML, like Gecko) Chrome/55.0.63744.0 Safari/602.37"
robertklep commented 6 years ago

I did some more digging, but I can't reproduce this. However, it's difficult to reproduce, because I think it's related to the connection between the Easy and the cloud server, and not so much the client (my lib) and the cloud server.

The latter I can test using a TCP-proxy in between the lib and the cloud server, and any disconnects in that situation are handled properly.

It's annoying that the default "unhandled promise" handler doesn't show a stack trace where exactly the errors occur (especially the "Cannot read property 'write' of null" error). It's happening somewhere inside the XMPP library, but no idea where.

Can you try and run the server in debug-mode? That requires setting an environment variable (probably in the systemd service file):

[Service]
Environment=DEBUG=nefit-easy-core
...

This will create a fair amount of additional logging, although I don't expect it to be GB's a day.

koenkooi commented 6 years ago

Restarted the server with the DEBUG var set. I indeed get more output:

Jun 06 14:57:16 solar systemd[1]: Started Nefit Easy http bridge.
Jun 06 14:57:27 solar easy-server[29847]: 2018-06-06T12:57:27.211Z nefit-easy-core online, jid = rrccontact_618955383@wa2-mz36-qrmzh6.bosch.de/3pys4huqzu
Jun 06 14:57:27 solar easy-server[29847]: 2018-06-06T12:57:27.225Z nefit-easy-core sending ping
Jun 06 14:57:29 solar easy-server[29847]: HTTP server listening on http://0.0.0.0:3000
Jun 06 14:57:57 solar easy-server[29847]: 2018-06-06T12:57:57.265Z nefit-easy-core sending ping
koenkooi commented 6 years ago

New log, with DEBUG set: https://gist.github.com/koenkooi/1f4beb0df25ca8bb19c68479d7629044

robertklep commented 6 years ago

Thanks, I've added another fix to try to squash this bug:

npm i robertklep/nefit-easy-core -g
koenkooi commented 6 years ago

That seems to recover when I reboot the AP: https://gist.github.com/koenkooi/795f654bce3c0750cd3d608027dabb2b

robertklep commented 6 years ago

Interesting! Let's have it run for a few days to see how it behaves, if that's okay with you.

koenkooi commented 6 years ago

More than okay by me :)

koenkooi commented 6 years ago

I managed to have it hang again: https://gist.github.com/koenkooi/6417d334f81be4a1a651b61527fbb0d2

robertklep commented 6 years ago

That's strange: after logging "connection error", it should immediately log "trying to restart the connection", which it doesn't. It should also mark the connection as being offline and not send any more messages to the backend, which it's still doing in the logfile that you post.

Try using npm i robertklep/nefit-easy-core -fg to force-install the latest version.

koenkooi commented 6 years ago

Ok, doing a systemctl stop easy ; npm i robertklep/nefit-easy-core -fg ; systemctl start easy right now.

robertklep commented 6 years ago

I've been running a test program for a few days now, running the latest code, and it seems to pick up broken connections correctly after the backend returns back from the dead again.

CaptainFS commented 6 years ago

Mine is still disconnected. A few days already. I'm running on a Pi3: node(js) v8.11.2 nefit-easy-http-server v4.0.1 nefit-easy-core v3.0.0

robertklep commented 6 years ago

@CaptainFS are you running the Github-hosted version of nefit-easy-core? The published version (hosted by NPM) is still "broken".

CaptainFS commented 6 years ago

I did a git clone then npm install, just did it again, to be sure. I'll keep an eye on it now.

robertklep commented 6 years ago

@CaptainFS make sure that if you have installed nefit-easy-http-server globally (npm install nefit-easy-http-server -g), you need to install nefit-easy-core globally as well.

Tip: NPM knows how to install packages from Github directly:

npm i robertklep/nefit-easy-core -g
CaptainFS commented 6 years ago

Thanks for your help Robert! On my Pi3, sudo npm i robertklep/nefit-easy-core -g is not working. So I cloned the nefit-easy-core:

git clone https://github.com/robertklep/nefit-easy-core
cd nefit-easy-core
sudo npm install -g
CaptainFS commented 6 years ago

I'm pretty sure I run the GitHub package: it still stops after about 2 days.

robertklep commented 6 years ago

@CaptainFS with what error, specifically?

I've been running the HTTP server for about a week now, using the new code, and it's still working fine.

CaptainFS commented 6 years ago

nothing strange in the Syslog, could you point me to another log maybe?

robertklep commented 6 years ago

@CaptainFS you can enable debug logging, as explained in this comment: https://github.com/robertklep/nefit-easy-core/issues/14#issuecomment-395047476

However, it depends on how exactly you run the HTTP server whether or not the instructions in that comment will work for you.

In any case, the DEBUG environment variable should be set to nefit-easy-core to enable debug logging.

If you start it from the command line, this would work:

env DEBUG=nefit-easy-core easy-server
CaptainFS commented 6 years ago

I'm running it with PM2, removed every instance (http-server + core) and started all over again. Will check (again :) how things run. I did paste the git version of the core over the nefit-easy-core into nefit-easy-http-server/node_modules. I presume this is the way to go? Thanks again for your fast and prompt help!

robertklep commented 6 years ago

Setting environment variables with PM2 is relatively straightforward: https://pm2.io/doc/en/runtime/guide/ecosystem-file/#environment-variables

As for installing the core module: sounds okay to me. Alternatively, you can run npm i robertklep/nefit-easy-core -f from inside the nefit-easy-http-server directory.

koenkooi commented 6 years ago

FWIW, I'm still seeing the original issues running a098582ae08c2fe8ee1849ad83ffaa0107d1663f

robertklep commented 6 years ago

I've been running the server for more than a week now, in which the Bosch backend has been offline for quite a few times (and I've rebooted my router at least once as well), but it always picked up the connection again afterwards.

I have no idea why it's not working in your situation, and it's becoming really difficult to debug because I can't reproduce the exact situation which leaves the server in a "broken" state.

vanherelj commented 6 years ago

Hello Robert and others,

As a hobbyist I started playing with Domoticz software on the Raspberry Pi 3. Since I own a Nefit Easy I have tried to do some datalogging using the easy-server, installed from github. Things look going OK, I receive valid data, but only for a short time (less than an hour or so) and after that I als get these UnhandledPromiseRejectionWarning messages. After aborting easy-server by pressing CTRL-C and restarting is, it will run for another (short) period. I don't know if I can be of any help trying to solve this issue. Let me know if so.

Jeroen

robertklep commented 6 years ago

@vanherelj thanks, Jeroen! We're trying to get to the bottom of these issues.

A fix I made works for me, but not for the others :( You could try and see if the fix works for you, by installing a test version of the HTTP server:

npm uninstall nefit-easy-core
npm install robertklep/nefit-easy-http-server#debug-test

You may have to add the -g option for both commands if the original server package was installed globally, and perhaps you need to prefix the commands with sudo if installing global packages require root privileges:

sudo npm uninstall nefit-easy-core -g
sudo npm install robertklep/nefit-easy-http-server#debug-test -g

(@CaptainFS @koenkooi to make sure that you're both using the correct core library, it might be worthwhile to do the same; starting the HTTP server should print [debug version of nefit-easy-core] when starting up, which means it's using the correct core; if not, it's using an incorrect, unfixed, version that needs to be uninstalled first)

koenkooi commented 6 years ago

I did

systemctl stop easy ; npm uninstall nefit-easy-core -g ; npm install 'robertklep/nefit-easy-http-server#debug-test' -g ; systemctl start easy

And I get

Jun 18 20:01:10 solar systemd[1]: Started Nefit Easy http bridge.
Jun 18 20:01:18 solar easy-server[32446]: [debug version of `nefit-easy-core`]

So I should be running the latest now.

CaptainFS commented 6 years ago

@robertklep My issue is/was that by installing via npm etc etc -g, it installed, but on other places than it should. I guess I have it under control now: with a little help of locate I removed every instance of nefit-easy-http-server and nefit-easy-core and started all over again. I have good hopes this solved my issue 👍 Nefit-easy-http-server: /usr/lib/node_modules/nefit-easy-http-server/ and the core modules (the GIT ones): /usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/

vanherelj commented 6 years ago

Hmm, seems to have some problems with installing this version. I first removed all old nefit-easy-* packages installed by npm. I also updated git to the latest version. It looks like some user rights, but I cannot figure out why. Any idea what causes this error?

pi@pi_JHL:/usr $ sudo npm install 'robertklep/nefit-easy-http-server#debug-test' -g npm ERR! code 128 npm ERR! Command failed: /usr/bin/git clone --depth=1 -q -b debug-test git://github.com/robertklep/nefit-easy-http-server.git /root/.npm/_cacache/tmp/git-clone-fbd7f3f9 npm ERR! fatal: could not create leading directories of '/root/.npm/_cacache/tmp/git-clone-fbd7f3f9': Permission denied npm ERR!

npm ERR! A complete log of this run can be found in: npm ERR! /root/.npm/_logs/2018-06-19T04_41_59_975Z-debug.log

robertklep commented 6 years ago

@vanherelj try adding the --unsafe-perm option to the command

koenkooi commented 6 years ago

This morning I triggered a network failure by powercycling the switches inbetween the easy and the internet and it seemed to recover:

Jun 20 08:43:12 solar easy-server[8883]: 2018-06-20T06:43:12.915Z nefit-easy-core error sending message Error: REQUEST_TIMEOUT
Jun 20 08:43:12 solar easy-server[8883]:     at Timeout.setTimeout (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:175:34)
Jun 20 08:43:12 solar easy-server[8883]:     at ontimeout (timers.js:475:11)
Jun 20 08:43:12 solar easy-server[8883]:     at tryOnTimeout (timers.js:310:5)
Jun 20 08:43:12 solar easy-server[8883]:     at Timer.listOnTimeout (timers.js:270:5)
Jun 20 08:43:12 solar easy-server[8883]: 2018-06-20T06:43:12.927Z nefit-easy-core message timed out, retrying...
Jun 20 08:43:12 solar easy-server[8883]: 2018-06-20T06:43:12.928Z nefit-easy-core queuing request (retries = 16)
Jun 20 08:43:12 solar easy-server[8883]: 2018-06-20T06:43:12.929Z nefit-easy-core sending message
Jun 20 08:43:14 solar easy-server[8883]: 2018-06-20T06:43:14.939Z nefit-easy-core error sending message Error: REQUEST_TIMEOUT
Jun 20 08:43:14 solar easy-server[8883]:     at Timeout.setTimeout (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:175:34)
Jun 20 08:43:14 solar easy-server[8883]:     at ontimeout (timers.js:475:11)
Jun 20 08:43:14 solar easy-server[8883]:     at tryOnTimeout (timers.js:310:5)
Jun 20 08:43:14 solar easy-server[8883]:     at Timer.listOnTimeout (timers.js:270:5)
Jun 20 08:43:14 solar easy-server[8883]: 2018-06-20T06:43:14.948Z nefit-easy-core cleaning up for /ecus/rrc/uiStatus
Jun 20 08:43:14 solar easy-server[8883]: Error: MAX_RETRIES_REACHED
Jun 20 08:43:14 solar easy-server[8883]:     at queueMessage.catch.e (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:245:51)
Jun 20 08:43:14 solar easy-server[8883]:     at <anonymous>
Jun 20 08:43:14 solar easy-server[8883]: 172.20.0.66 - - [20/Jun/2018:06:43:14 +0000] "GET /bridge/ecus/rrc/uiStatus HTTP/1.1" 500 169 "-" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/603.37 (KHTML, like Gecko) Chrome/54.0.32779.0 Safari/603.38"
Jun 20 08:43:27 solar easy-server[8883]: 2018-06-20T06:43:27.184Z nefit-easy-core sending ping

Internet access is working again at this point.

But after 3 pings it runs into trouble again:

Jun 20 08:43:57 solar easy-server[8883]: 2018-06-20T06:43:57.220Z nefit-easy-core sending ping
Jun 20 08:44:27 solar easy-server[8883]: 2018-06-20T06:44:27.257Z nefit-easy-core sending ping
Jun 20 08:44:45 solar easy-server[8883]: 2018-06-20T06:44:45.237Z nefit-easy-core preparing message: /ecus/rrc/uiStatus (retries = 0)
Jun 20 08:44:45 solar easy-server[8883]: 2018-06-20T06:44:45.240Z nefit-easy-core queuing request (retries = 0)
Jun 20 08:44:45 solar easy-server[8883]: 2018-06-20T06:44:45.243Z nefit-easy-core sending message
Jun 20 08:44:47 solar easy-server[8883]: 2018-06-20T06:44:47.251Z nefit-easy-core error sending message Error: REQUEST_TIMEOUT
Jun 20 08:44:47 solar easy-server[8883]:     at Timeout.setTimeout (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:175:34)
Jun 20 08:44:47 solar easy-server[8883]:     at ontimeout (timers.js:475:11)
Jun 20 08:44:47 solar easy-server[8883]:     at tryOnTimeout (timers.js:310:5)
Jun 20 08:44:47 solar easy-server[8883]:     at Timer.listOnTimeout (timers.js:270:5)
Jun 20 08:44:47 solar easy-server[8883]: 2018-06-20T06:44:47.258Z nefit-easy-core message timed out, retrying...
Jun 20 08:44:47 solar easy-server[8883]: 2018-06-20T06:44:47.263Z nefit-easy-core queuing request (retries = 1)
Jun 20 08:44:47 solar easy-server[8883]: 2018-06-20T06:44:47.263Z nefit-easy-core sending message
Jun 20 08:44:49 solar easy-server[8883]: 2018-06-20T06:44:49.269Z nefit-easy-core error sending message Error: REQUEST_TIMEOUT
Jun 20 08:44:49 solar easy-server[8883]:     at Timeout.setTimeout (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:175:34)
Jun 20 08:44:49 solar easy-server[8883]:     at ontimeout (timers.js:475:11)
Jun 20 08:44:49 solar easy-server[8883]:     at tryOnTimeout (timers.js:310:5)
Jun 20 08:44:49 solar easy-server[8883]:     at Timer.listOnTimeout (timers.js:270:5)
Jun 20 08:44:49 solar easy-server[8883]: 2018-06-20T06:44:49.279Z nefit-easy-core message timed out, retrying...
Jun 20 08:44:49 solar easy-server[8883]: 2018-06-20T06:44:49.280Z nefit-easy-core queuing request (retries = 2)
Jun 20 08:44:49 solar easy-server[8883]: 2018-06-20T06:44:49.281Z nefit-easy-core sending message
Jun 20 08:44:51 solar easy-server[8883]: 2018-06-20T06:44:51.296Z nefit-easy-core error sending message Error: REQUEST_TIMEOUT
Jun 20 08:44:51 solar easy-server[8883]:     at Timeout.setTimeout (/usr/lib/node_modules/nefit-easy-http-server/node_modules/nefit-easy-core/lib/index.js:175:34)
Jun 20 08:44:51 solar easy-server[8883]:     at ontimeout (timers.js:475:11)
Jun 20 08:44:51 solar easy-server[8883]:     at tryOnTimeout (timers.js:310:5)
Jun 20 08:44:51 solar easy-server[8883]:     at Timer.listOnTimeout (timers.js:270:5)

The Nefit app itself on my phone doesn't work either, walking upstairs to check the actual easy device shows it has no internet connection (red X on globe icon). After powercycling it nefit-easy-core picks up the connection again.

This is the best result so far!

robertklep commented 6 years ago

@koenkooi that's looking promising!

I wonder if my instructions on sideloading the core module earlier might not have worked in all situations, resulting in the newer (hopefully fixed) version not being used at all.

Let's keep it running for a day or so, if no other issues emerge I'm going to declare this a win (at least for you and me) and push a new version :D

CaptainFS commented 6 years ago

Unfortunately mine stopped again. I need some help with debugging: running Pi3 Jesse, I have nefit-easy-http-server running via pm2 (for some reason, cant remember why :)

robertklep commented 6 years ago

@CaptainFS it depends on how you start the server exactly. Do you have a separate PM2 config file for it?

As for logging, the default for PM2 is to store logs in ~/.pm2/logs (you can also show the using pm2 logs).

PietSmits commented 6 years ago

I have been following this development with interest. I had a php implementation of this (courtesy of KabouterSuper) that failed after the recent changes. I have changed my implementation (on a Synology NAS) to use the http server, but as others I have a lot of problems like sketched above. I have now upgraded to the debug version Robert has so kindly provided. As said I had similar issues. Sometimes there would be no reply (MAX_RETRIES Reached), but after that it would continue, but every other day or so it completely stopped working. I hope this will at least have solved the last problem.

vanherelj commented 6 years ago

@robertklep I did not succeed in making it run stable on de RBPi. So I installed it on a laptop with Ubuntu 16.04 LTS, with Domoticz requesting for data using the Nefit http server (4.0.1). This runs like a charm for about four days now! I discovered that when I have the laptop running and parallel to that also run it on the RBPi, the http-server on the laptop starts reporting timeouts also. Could this have anything to do with the Nefit Bosch Server side?

robertklep commented 6 years ago

@vanherelj in theory, it shouldn't matter.

I run the Nefit Easy app on my Homey (which basically does the same as the HTTP server: have a connection open to the Nefit/Bosch backend and periodically request data), and I've been running the HTTP server simultaneously on my Ubuntu server for a week or two now, and I haven't noticed any interference between those two.

Today, one of the users that had issues with Domoticz and the HTTP server posted a comment here that after upgrading to the latest stable Domoticz version, they are noticing less issues (although their problem was an increase in CPU-usage).

I'm not sure if you have checked, but it might be worthwhile to check if the problem on your RPi also comes with a high CPU-load.

Out of curiosity: what router do you use?

vanherelj commented 6 years ago

It’s a Fritzbox 7360

Op 26 jun. 2018, om 21:16 heeft Robert Klep notifications@github.com het volgende geschreven:

@vanherelj https://github.com/vanherelj in theory, it shouldn't matter.

I run the Nefit Easy app on my Homey (which basically does the same as the HTTP server: have a connection open to the Nefit/Bosch backend and periodically request data), and I've been running the HTTP server simultaneously on my Ubuntu server for a week or two now, and I haven't noticed any interference between those two.

Today, one of the users that had issues with Domoticz and the HTTP server posted a comment here https://github.com/robertklep/nefit-easy-http-server/issues/17#issuecomment-400200599 that after upgrading to the latest stable Domoticz version, they are noticing less issues (although their problem was an increase in CPU-usage).

I'm not sure if you have checked, but it might be worthwhile to check if the problem on your RPi also comes with a high CPU-load.

Out of curiosity: what router do you use?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/robertklep/nefit-easy-core/issues/14#issuecomment-400430969, or mute the thread https://github.com/notifications/unsubscribe-auth/AmfyHL209SwnMhvc-1NDra7DvruJCaAnks5uAoikgaJpZM4UXlDB.

robertklep commented 6 years ago

From what I know, that's a pretty good device. So we can probably rule out a bad router 😉

CaptainFS commented 6 years ago

@CaptainFS it depends on how you start the server exactly. Do you have a separate PM2 config file for it? As for logging, the default for PM2 is to store logs in ~/.pm2/logs (you can also show the using pm2 logs).

The logs are empty, I might drop PM2, as of today I have some time to investigate. I run a RBPi as well btw. Seems to drop the connection with the Nefit servers after a few days.