Crasher bug in HTTP stack? #43

jpelzer · 2021-03-12T22:13:01Z

jpelzer
Mar 12, 2021

Hi there! I'm new to HASP, but I have three units... One installed, two in testing. Sadly, they are all exhibiting the same lockup behavior. They work fine until some random event causes them to become unresponsive, both at the screen via the web page (so the installed device will remain locked up until I yank it out of the wall or find the breaker).

Behavior when it stops:

Wifi subsystem is still running, as it will reconnect to the network if you knock it off... However the unit does not display any error/info/restarting screen the way it does when happy.
Screen touches flash, but don't trigger events
Web page is not accessible

I had the brainwave to enable telnet debugging and let it run on one of the units. This unit also has a clock displayed, so it was obvious to see when it stopped responding. The logs are below, and what sticks out for me is the three web hits to '/' from 192.168.2.1 (my Unifi Dream Machine Pro) and then the final 404 hit from the Dream Machine, and then the system goes wacky. I did a very simplistic set of curls to see if there was an easy way to trigger this, but simple 404s don't immediately trigger this.

Now, one question I have is... Why is my Dream Machine making multiple requests to my hasps? I assume it's trying to fingerprint them or some nonsense. But the second is, how can I help fix this crasher?

[+79843.867s] HMI OUT: 'p[1].b[4].txt="3:03 pm"'
[+79860.516s] MQTT OUT: 'hasp/kitchen_slider/sensor' : '{"espVersion":1.00,"updateEspAvailable":false,"lcdConnected":true,"lcdVersion":"3","updateLcdAvailable":false,"espUptime":79860,"signalStrength":-41,"haspName":"kitchen_slider","haspIP":"192.168.2.14","haspClientID":"kitchen_slider-e8db84988c3f","haspMac":"e8:db:84:98:8c:3f","haspManufacturer":"HASwitchPlate","haspModel":"HASPone v1.0.0","heapFree":22544,"heapFragmentation":28,"heapMaxFreeBlockSize":14560,"espCore":"2_7_4"}'
[+79868.438s] MQTT IN: 'hasp/kitchen_slider/command/p[1].b[6].txt' : '" 65.7°"'
[+79868.438s] HMI OUT: 'p[1].b[6].txt=" 65.7°"'
[+79868.609s] MQTT IN: 'hasp/kitchen_slider/command/p[1].b[7].txt' : '"Today: 66° / 41°\r\n Next: 46° / 28°"'
[+79868.609s] HMI OUT: 'p[1].b[7].txt="Today: 66° / 41°\r\n Next: 46° / 28°"'
[+79868.617s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
[+79868.617s] HMI IN: [Escape Character Invalid] 0x20
[+79868.617s] MQTT OUT: 'hasp/kitchen_slider/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
[+79903.859s] MQTT IN: 'hasp/kitchen_slider/command/p[1].b[4].txt' : '"3:04 pm"'
[+79903.867s] HMI OUT: 'p[1].b[4].txt="3:04 pm"'
[+79959.453s] HTTP: Sending root page to client connected from: 192.168.2.1
[+79959.633s] HTTP: Sending root page to client connected from: 192.168.2.1
[+79959.828s] HTTP: Sending root page to client connected from: 192.168.2.1
[+79970.023s] MQTT IN: 'hasp/kitchen_slider/command/p[1].b[4].txt' : '"3:05 pm"'
[+79970.023s] HMI OUT: 'p[1].b[4].txt="3:05 pm"'
[+79970.031s] HTTP: Sending 404 to client connected from: 192.168.2.1
[+80025.055s] MQTT IN: 'hasp/kitchen_slider/command/p[1].b[4].txt' : '"3:06 pm"'
[+80025.063s] HMI OUT: 'p[1].b[4].txt="3:06 pm"'
[+80035.063s] HMI ERROR: nextionHandleInput timeout
[+80045.063s] HMI ERROR: nextionHandleInput timeout
[+80055.070s] HMI ERROR: nextionHandleInput timeout
[+80065.070s] HMI ERROR: nextionHandleInput timeout

ielbury · 2021-03-12T22:43:42Z

ielbury
Mar 12, 2021

Try setting a HASP Username and Password. Because of the ~150ms time between requests, maybe the ESP runs out of resources???? Might be a workaround?

Edit: I am proposing this because when you look at the code, the path is different and not a lot of data is transmitted if you have a Username and Password.

44 replies

jpelzer Apr 30, 2021
Author

Haven't forgotten about this. The hasp that had been locking up has been stable the past two weeks (after removing all automations except for a clock). I've been adding automations back to my hasp at my desk. No lockup yet, so sort of a head-scratcher so far. I finally added the last two automations today, so hopefully I'll get a crash soon!

jpelzer May 3, 2021
Author

SUCCESS! The Hasp has failed!

[+748337.563s] HMI OUT: 'p[1].b[7].txt="Today: 61¬∞ / 55¬∞\r Next: 71¬∞ / 55¬∞"'
[+748337.500s] MQTT IN: 'hasp/office/command/p[1].b[7].txt' : '"Today: 61¬∞ / 55¬∞\r Next: 71¬∞ / 55¬∞"'
[+748320.188s] MQTT IN: 'hasp/office/command/p[1].b[6].txt' : '"Ôãâ 56.8¬∞"'
[+748320.188s] HMI OUT: 'p[1].b[6].txt="Ôãâ 56.8¬∞"'
[+748299.063s] HMI OUT: 'p[1].b[4].txt="7:26 am"'
[+748299.063s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"7:26 am"'
[+748260.563s] MQTT OUT: 'hasp/office/sensor' : '{"espVersion":1.01,"updateEspAvailable":false,"lcdConnected":true,"lcdVersion":"3","updateLcdAvailable":false,"espUptime":748260,"signalStrength":-40,"haspName":"office","haspIP":"192.168.2.155","haspClientID":"office-e8db84987b51","haspMac":"e8:db:84:98:7b:51","haspManufacturer":"HASwitchPlate","haspModel":"HASPone v1.0.0","heapFree":22160,"heapFragmentation":27,"heapMaxFreeBlockSize":14896,"espCore":"5ac64ffa"}'
[+748239.125s] HMI OUT: 'p[1].b[4].txt="7:25 am"'
[+748239.125s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"7:25 am"'
[+748180.125s] HMI IN: [Escape Character Invalid] 0x20
[+748180.125s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
[+748180.125s] MQTT OUT: 'hasp/office/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
[+748180.125s] HMI OUT: 'p[1].b[5].txt="Sunrise: 5:50 AM\rSunset: 7:54 PM"'
[+748180.125s] MQTT IN: 'hasp/office/command/p[1].b[5].txt' : '"Sunrise: 5:50 AM\rSunset: 7:54 PM"'
[+748179.063s] HMI OUT: 'p[1].b[4].txt="7:24 am"'
[+748179.063s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"7:24 am"'
[+748132.938s] MQTT IN: 'hasp/office/command/p[1].b[6].txt' : '"Ôãâ 56.5¬∞"'
[+748132.938s] HMI OUT: 'p[1].b[6].txt="Ôãâ 56.5¬∞"'
[+748119.125s] HMI OUT: 'p[1].b[4].txt="7:23 am"'
[+748119.125s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"7:23 am"'
[+748059.063s] HMI OUT: 'p[1].b[4].txt="7:22 am"'
[+748059.063s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"7:22 am"'
[+747999.125s] HMI OUT: 'p[1].b[4].txt="7:21 am"'
[+747999.125s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"7:21 am"'

Tapping the screen does result in logging, but updates to not appear to resume:

[+762384.500s] HMI IN: [Button OFF] 'p[1].b[4]'
[+762384.500s] HMI IN: [7 bytes]: 0x65 0x01 0x04 0x00 0xff 0xff 0xff
[+762384.375s] HMI IN: [Button ON] 'p[1].b[4]'
[+762384.375s] HMI IN: [7 bytes]: 0x65 0x01 0x04 0x01 0xff 0xff 0xff

When I get a chance I'll try and walk through what could be causing this. The HASP is using the updated blueprints. There are only three in use: Core, Display a clock, Display a template. Display a template is used three times for p[1]b[5,6,7].

jpelzer May 3, 2021
Author

Since the logs have unicode in them, here's a picture of the device to show the icons that are getting sent across:

jpelzer May 3, 2021
Author

And hopefully this is helpful as well: The last two logs show b[7] being set to a new value, but the screen didn't update to match the incoming data.

jpelzer May 12, 2021
Author

Another lockup, putting the log here just for documentation's sake:

May 12 17:54:29.676 | office_hasp | hasp | [+636712.625s] HMI OUT: 'p[1].b[7].txt="Today: 64° / 40°\r Next: 66° / 43°"'
-- | -- | -- | --
  | May 12 17:54:29.659 | office_hasp | hasp | [+636712.625s] MQTT IN: 'hasp/office/command/p[1].b[7].txt' : '"Today: 64° / 40°\r Next: 66° / 43°"'
  | May 12 17:54:00.159 | office_hasp | hasp | [+636683.125s] HMI OUT: 'p[1].b[4].txt="5:54 pm"'
  | May 12 17:54:00.155 | office_hasp | hasp | [+636683.125s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"5:54 pm"'
  | May 12 17:53:37.577 | office_hasp | hasp | [+636660.563s] MQTT OUT: 'hasp/office/sensor' : '{"espVersion":1.01,"updateEspAvailable":true,"lcdConnected":true,"lcdVersion":"3","updateLcdAvailable":false,"espUptime":636660,"signalStrength":-37,"haspName":"office","haspIP":"192.168.2.155","haspClientID":"office-e8db84987b51","haspMac":"e8:db:84:98:7b:51","haspManufacturer":"HASwitchPlate","haspModel":"HASPone v1.0.0","heapFree":22224,"heapFragmentation":29,"heapMaxFreeBlockSize":14480,"espCore":"5ac64ffa"}'
  | May 12 17:53:16.518 | office_hasp | hasp | [+636639.500s] MQTT IN: 'hasp/office/command/p[1].b[6].txt' : '" 64.4°"'
  | May 12 17:53:16.515 | office_hasp | hasp | [+636639.500s] HMI OUT: 'p[1].b[6].txt=" 64.4°"'
  | May 12 17:53:00.155 | office_hasp | hasp | [+636623.188s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"5:53 pm"'
  | May 12 17:53:00.149 | office_hasp | hasp | [+636623.188s] HMI OUT: 'p[1].b[4].txt="5:53 pm"'
  | May 12 17:52:41.231 | office_hasp | hasp | [+636604.250s] HMI IN: [Escape Character Invalid] 0x20
  | May 12 17:52:41.226 | office_hasp | hasp | [+636604.250s] MQTT OUT: 'hasp/office/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
  | May 12 17:52:41.221 | office_hasp | hasp | [+636604.250s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
  | May 12 17:52:41.213 | office_hasp | hasp | [+636604.250s] HMI OUT: 'p[1].b[5].txt="Sunrise: 5:40 AM\r Sunset: 8:04 PM"'
  | May 12 17:52:41.192 | office_hasp | hasp | [+636604.250s] MQTT IN: 'hasp/office/command/p[1].b[5].txt' : '"Sunrise: 5:40 AM\r Sunset: 8:04 PM"'
  | May 12 17:52:20.723 | office_hasp | hasp | [+636583.688s] HMI OUT: 'p[1].b[6].txt=" 64°"'
  | May 12 17:52:20.710 | office_hasp | hasp | [+636583.688s] MQTT IN: 'hasp/office/command/p[1].b[6].txt' : '" 64°"'
  | May 12 17:52:00.183 | office_hasp | hasp | [+636563.188s] HMI OUT: 'p[1].b[4].txt="5:52 pm"'
  | May 12 17:52:00.180 | office_hasp | hasp | [+636563.188s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"5:52 pm"'
  | May 12 17:51:00.154 | office_hasp | hasp | [+636503.188s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"5:51 pm"'

jpelzer · 2021-05-27T17:25:25Z

jpelzer
May 27, 2021
Author

Running smoothly for about two weeks, then locked up again. Right now the "Today/Next" pane is hardcoded (not a dynamic template) as I was trying to cause the crash, so pretty odd.

[+1141755.875s] HMI OUT: 'p[1].b[7].txt="Today: 64¬∞ / 40¬∞\r&nbsp;Next: 66¬∞ / 43¬∞"'
[+1141755.875s] MQTT IN: 'hasp/office/command/p[1].b[7].txt' : '"Today: 64¬∞ / 40¬∞\r&nbsp;Next: 66¬∞ / 43¬∞"'
[+1141729.500s] HMI IN: [Escape Character Invalid] 0x20
[+1141729.500s] MQTT OUT: 'hasp/office/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
[+1141729.500s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
[+1141729.500s] HMI OUT: 'p[1].b[5].txt="Sunrise: 5:29 AM\rSunset: 8:17 PM"'
[+1141729.375s] MQTT IN: 'hasp/office/command/p[1].b[5].txt' : '"Sunrise: 5:29 AM\rSunset: 8:17 PM"'
[+1141709.500s] HMI OUT: 'p[1].b[4].txt="6:05 pm"'
[+1141709.500s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:05 pm"'
[+1141649.375s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:04 pm"'
[+1141649.375s] HMI OUT: 'p[1].b[4].txt="6:04 pm"'
[+1141589.375s] HMI OUT: 'p[1].b[4].txt="6:03 pm"'
[+1141589.375s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:03 pm"'
[+1141560.500s] MQTT OUT: 'hasp/office/sensor' : '{"espVersion":1.01,"updateEspAvailable":true,"lcdConnected":true,"lcdVersion":"3","updateLcdAvailable":false,"espUptime":1141560,"signalStrength":-39,"haspName":"office","haspIP":"192.168.2.155","haspClientID":"office-e8db84987b51","haspMac":"e8:db:84:98:7b:51","haspManufacturer":"HASwitchPlate","haspModel":"HASPone v1.0.0","heapFree":22576,"heapFragmentation":19,"heapMaxFreeBlockSize":18200,"espCore":"5ac64ffa"}'
[+1141529.375s] HMI OUT: 'p[1].b[4].txt="6:02 pm"'
[+1141529.375s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:02 pm"'
[+1141489.500s] MQTT OUT: 'hasp/office/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
[+1141489.500s] HMI IN: [Escape Character Invalid] 0x20
[+1141489.500s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
[+1141489.500s] HMI OUT: 'p[1].b[5].txt="Sunrise: 5:29 AM\rSunset: 8:17 PM"'
[+1141489.375s] MQTT IN: 'hasp/office/command/p[1].b[5].txt' : '"Sunrise: 5:29 AM\rSunset: 8:17 PM"'
[+1141469.500s] HMI OUT: 'p[1].b[4].txt="6:01 pm"'
[+1141469.500s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:01 pm"'

0 replies

jpelzer · 2021-06-06T02:09:08Z

jpelzer
Jun 6, 2021
Author

Removed Today/Next panel, it ran fine and then crashed the other day. Capturing here:

Jun 04 18:02:38.646 office_hasp hasp [+705766.938s] HMI ERROR: nextionHandleInput timeout
Jun 04 18:02:38.542 office_hasp hasp [+705766.875s] HMI IN: [Escape Character Invalid] 0x20
Jun 04 18:02:38.540 office_hasp hasp [+705766.938s] MQTT OUT: 'hasp/office/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
Jun 04 18:02:36.465 office_hasp hasp [+705766.750s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
Jun 04 18:02:36.436 office_hasp hasp [+705766.625s] HMI OUT: 'p[1].b[5].txt="Sunrise: 5:25 AM\r Sunset: 8:24 PM"'
Jun 04 18:02:36.420 office_hasp hasp [+705766.625s] MQTT IN: 'hasp/office/command/p[1].b[5].txt' : '"Sunrise: 5:25 AM\r Sunset: 8:24 PM"'
Jun 04 18:02:00.213 office_hasp hasp [+705730.563s] HMI OUT: 'p[1].b[4].txt="6:02 pm"'
Jun 04 18:02:00.199 office_hasp hasp [+705730.500s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:02 pm"'
Jun 04 18:00:00.148 office_hasp hasp [+705610.500s] HMI OUT: 'p[1].b[4].txt="6:00 pm"'
Jun 04 18:00:00.131 office_hasp hasp [+705610.500s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"6:00 pm"'
Jun 04 17:59:00.172 office_hasp hasp [+705550.500s] HMI OUT: 'p[1].b[4].txt="5:59 pm"'
Jun 04 17:59:00.159 office_hasp hasp [+705550.438s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"5:59 pm"'
Jun 04 17:58:36.235 office_hasp hasp [+705526.563s] HMI IN: [Escape Character Invalid] 0x20
Jun 04 17:58:36.231 office_hasp hasp [+705526.563s] HMI IN: [4 bytes]: 0x20 0xff 0xff 0xff
Jun 04 17:58:36.227 office_hasp hasp [+705526.563s] MQTT OUT: 'hasp/office/state/json' : '{"event":"nextion_return_data","return_code":"0x20","return_code_description":"Escape Character Invalid"}'
Jun 04 17:58:36.222 office_hasp hasp [+705526.500s] HMI OUT: 'p[1].b[5].txt="Sunrise: 5:25 AM\r Sunset: 8:24 PM"'
Jun 04 17:58:36.201 office_hasp hasp [+705526.500s] MQTT IN: 'hasp/office/command/p[1].b[5].txt' : '"Sunrise: 5:25 AM\r Sunset: 8:24 PM"'
Jun 04 17:58:00.168 office_hasp hasp [+705490.500s] MQTT IN: 'hasp/office/command/p[1].b[4].txt' : '"5:58 pm"'
Jun 04 17:58:00.166 office_hasp hasp [+705490.500s] HMI OUT: 'p[1].b[4].txt="5:58 pm"'
Jun 04 17:57:40.776 office_hasp hasp [+705471.188s] HMI OUT: 'p[1].b[6].txt=" 65.8°"'
Jun 04 17:57:40.767 office_hasp hasp [+705471.125s] MQTT IN: 'hasp/office/command/p[1].b[6].txt' : '" 65.8°"'

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Crasher bug in HTTP stack? #43

{{title}}

Replies: 3 comments 44 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Crasher bug in HTTP stack? #43

jpelzer Mar 12, 2021

Replies: 3 comments · 44 replies

ielbury Mar 12, 2021

jpelzer Apr 30, 2021 Author

jpelzer May 3, 2021 Author

jpelzer May 3, 2021 Author

jpelzer May 3, 2021 Author

jpelzer May 12, 2021 Author

jpelzer May 27, 2021 Author

jpelzer Jun 6, 2021 Author

jpelzer
Mar 12, 2021

Replies: 3 comments 44 replies

ielbury
Mar 12, 2021

jpelzer Apr 30, 2021
Author

jpelzer May 3, 2021
Author

jpelzer May 3, 2021
Author

jpelzer May 3, 2021
Author

jpelzer May 12, 2021
Author

jpelzer
May 27, 2021
Author

jpelzer
Jun 6, 2021
Author