Closed dbrb2 closed 2 years ago
bloob00k
commented
2 years ago Interesting - I noticed my plug-in had crashed yesterday, but didn’t have to look more closely. Thanks for the info. Will investigate further when I get back next week, or a PR is always welcome :-). At first glance it looks similar to a problem in the python plug-in framework a year or two back. Or maybe badly formed json.
dbrb2
commented
2 years ago It looks like the issue may be chunked data - though I don't have any older logs to compare:
2021-10-29 20:14:11.283 Heating: (Heating) HTTP Details (3): 2021-10-29 20:14:11.283 Heating: (Heating) --->'Status':'200' 2021-10-29 20:14:11.283 Heating: (Heating) --->'Headers (3): 2021-10-29 20:14:11.283 Heating: (Heating) ------->'Connection':'close' 2021-10-29 20:14:11.284 Heating: (Heating) ------->'Content-Type':'application/json' 2021-10-29 20:14:11.284 Heating: (Heating) ------->'Transfer-Encoding':'chunked'
2021-10-29 00:47:49.042 Heating: (Heating) Pushing 'onMessageCallback' on to queue 2021-10-29 00:47:49.042 Heating: (Heating) Processing 'ReadEvent' message 2021-10-29 00:47:49.042 Heating: (Heating) Received 5 bytes of data 2021-10-29 00:47:49.043 Heating: (Heating) 30 0d 0a 0d 0a .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. 0.... 2021-10-29 00:47:49.043 Error: PluginSystem: Exception processing message.
This last line seems to be indicating the end of the chunked data - but is perhaps being parsed as if it were JSON:
"The Transfer-Encoding header is used to specify that the message body uses chunked encoding. Each chunk consists of the chunk size in bytes (in hexadecimal), followed by a newline, followed by the chunk contents. The message is terminated with a chunk of size zero."
bloob00k
commented
2 years ago Yes, again sounds very similar to the previous problem. It's the plugin framework that parses the chunked data, and it then passes the "decoded" data to the actual plug-in. There was a problem previously where it assumed that a TCP segment would always contain some actual data in addition to the chunk header, and crashed if the data was in a separate segment. This feels similar, but now that I am back I will dig deeper. If the problem is the plugin itself it's because it doesn't like the JSON after it has been extracted from the chunked data, and the end marker is a red herring. If it's the end marker itself that's causing the problem then it is in domoticz that the problem lies. A very quick look suggests that the wiser hub is sending two terminating chunks, and domoticz is tripping up on the second one, but still working on it.
bloob00k
commented
2 years ago Initial diagnosis was correct: the wiser API is returning a malformed response, by repeating the terminating chunk. The domoticz python framework treats the second 0 chunk as the start of a new message, but crashes because it tries to assumes it is a well-formed http request - which it is not. This all happens before it calls the plugin itself.
I've created a small patch for the framework, which can be found here: https://github.com/bloob00k/domoticz-1/tree/chunked-crash-fix. I will create a pull request for it tomorrow, I don't know how long it will take to get merged, but you can build a new version directly from source if you feel that way inclined.
The path prevents the current crash, but instead passes the malformed request on to the plugin. However the plugin itself is only expecting to receive responses (not requests), and so it also needs a small update to handle that correctly. The fix for that is in the devel branch currently. I expect to merge it into master tomorrow. But as I say it won't fix the current crash - for that you need a new build of domoticz itself.
dbrb2
commented
2 years ago Thanks very much for investigating. I have also raised a fault ticket with Drayton, so there is always a chance it will get fixed at their end as well
Cheers!
On Thu, Nov 4, 2021 at 11:15 PM bloob00k @.***> wrote:
Initial diagnosis was correct: the wiser API is returning a malformed response, by repeating the terminating chunk. The domoticz python framework treats the second 0 chunk as the start of a new message, but crashes because it tries to assumes it is a well-formed http request - which it is not. This all happens before it calls the plugin itself.
I've created a small patch for the framework, which can be found here: https://github.com/bloob00k/domoticz-1/tree/chunked-crash-fix. I will create a pull request for it tomorrow, I don't know how long it will take to get merged, but you can build a new version directly from source if you feel that way inclined.
The path prevents the current crash, but instead passes the malformed request on to the plugin. However the plugin itself is only expecting to receive responses (not requests), and so it also needs a small update to handle that correctly. The fix for that is in the devel branch currently. I expect to merge it into master tomorrow. But as I say it won't fix the current crash - for that you need a new build of domoticz itself.
— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/bloob00k/domoticz/issues/4#issuecomment-961502631, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABFQ45KAQEKGN5XGTEJ5JLUKMH2NANCNFSM5G6CFTEQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.
It appears that Wiser have made some changes to their API that is crashing the plugin. They started rolling out an update on the 27th October, and all plugins on domoticz started to crash for me soon after. On checking the logs we now have:
2021-10-29 00:47:49.041 Heating: (Heating) Received 1160 bytes of data 2021-10-29 00:47:49.041 Heating: (Heating) 72 61 74 75 72 65 22 3a 31 36 35 2c 22 50 65 72 63 65 6e 74 rature":165,"Percent 2021-10-29 00:47:49.041 Heating: (Heating) 61 67 65 44 65 6d 61 6e 64 22 3a 30 2c 22 57 69 6e 64 6f 77 ageDemand":0,"Window 2021-10-29 00:47:49.041 Heating: (Heating) 53 74 61 74 65 22 3a 22 43 6c 6f 73 65 64 22 7d 2c 7b 22 69 State":"Closed"},{"i 2021-10-29 00:47:49.041 Heating: (Heating) 64 22 3a 32 2c 22 4d 6f 75 6e 74 69 6e 67 4f 72 69 65 6e 74 d":2,"MountingOrient 2021-10-29 00:47:49.041 Heating: (Heating) 61 74 69 6f 6e 22 3a 22 56 65 72 74 69 63 61 6c 22 2c 22 53 ation":"Vertical","S 2021-10-29 00:47:49.041 Heating: (Heating) 65 74 50 6f 69 6e 74 22 3a 2d 32 30 30 2c 22 4d 65 61 73 75 etPoint":-200,"Measu 2021-10-29 00:47:49.041 Heating: (Heating) 72 65 64 54 65 6d 70 65 72 61 74 75 72 65 22 3a 31 36 37 2c redTemperature":167, 2021-10-29 00:47:49.041 Heating: (Heating) 22 50 65 72 63 65 6e 74 61 67 65 44 65 6d 61 6e 64 22 3a 30 "PercentageDemand":0 2021-10-29 00:47:49.041 Heating: (Heating) 2c 22 57 69 6e 64 6f 77 53 74 61 74 65 22 3a 22 43 6c 6f 73 ,"WindowState":"Clos 2021-10-29 00:47:49.041 Heating: (Heating) 65 64 22 7d 2c 7b 22 69 64 22 3a 33 2c 22 4d 6f 75 6e 74 69 ed"},{"id":3,"Mounti 2021-10-29 00:47:49.041 Heating: (Heating) 6e 67 4f 72 69 65 6e 74 61 74 69 6f 6e 22 3a 22 56 65 72 74 ngOrientation":"Vert 2021-10-29 00:47:49.041 Heating: (Heating) 69 63 61 6c 22 2c 22 53 65 74 50 0d 0a 33 39 33 0d 0a 6f 69 ical","SetP..393..oi 2021-10-29 00:47:49.041 Heating: (Heating) 6e 74 22 3a 2d 32 30 30 2c 22 4d 65 61 73 75 72 65 64 54 65 nt":-200,"MeasuredTe 2021-10-29 00:47:49.041 Heating: (Heating) 6d 70 65 72 61 74 75 72 65 22 3a 31 36 36 2c 22 50 65 72 63 mperature":166,"Perc 2021-10-29 00:47:49.041 Heating: (Heating) 65 6e 74 61 67 65 44 65 6d 61 6e 64 22 3a 30 2c 22 57 69 6e entageDemand":0,"Win 2021-10-29 00:47:49.041 Heating: (Heating) 64 6f 77 53 74 61 74 65 22 3a 22 43 6c 6f 73 65 64 22 7d 2c dowState":"Closed"}, 2021-10-29 00:47:49.041 Heating: (Heating) 7b 22 69 64 22 3a 34 2c 22 4d 6f 75 6e 74 69 6e 67 4f 72 69 {"id":4,"MountingOri 2021-10-29 00:47:49.041 Heating: (Heating) 65 6e 74 61 74 69 6f 6e 22 3a 22 56 65 72 74 69 63 61 6c 22 entation":"Vertical" 2021-10-29 00:47:49.041 Heating: (Heating) 2c 22 53 65 74 50 6f 69 6e 74 22 3a 2d 32 30 30 2c 22 4d 65 ,"SetPoint":-200,"Me 2021-10-29 00:47:49.041 Heating: (Heating) 61 73 75 72 65 64 54 65 6d 70 65 72 61 74 75 72 65 22 3a 31 asuredTemperature":1 2021-10-29 00:47:49.041 Heating: (Heating) 35 38 2c 22 50 65 72 63 65 6e 74 61 67 65 44 65 6d 61 6e 64 58,"PercentageDemand 2021-10-29 00:47:49.041 Heating: (Heating) 22 3a 30 2c 22 57 69 6e 64 6f 77 53 74 61 74 65 22 3a 22 43 ":0,"WindowState":"C 2021-10-29 00:47:49.041 Heating: (Heating) 6c 6f 73 65 64 22 7d 2c 7b 22 69 64 22 3a 35 2c 22 4d 6f 75 losed"},{"id":5,"Mou 2021-10-29 00:47:49.041 Heating: (Heating) 6e 74 69 6e 67 4f 72 69 65 6e 74 61 74 69 6f 6e 22 3a 22 56 ntingOrientation":"V 2021-10-29 00:47:49.041 Heating: (Heating) 65 72 74 69 63 61 6c 22 2c 22 53 65 74 50 6f 69 6e 74 22 3a ertical","SetPoint": 2021-10-29 00:47:49.041 Heating: (Heating) 2d 32 30 30 2c 22 4d 65 61 73 75 72 65 64 54 65 6d 70 65 72 -200,"MeasuredTemper 2021-10-29 00:47:49.041 Heating: (Heating) 61 74 75 72 65 22 3a 31 35 36 2c 22 50 65 72 63 65 6e 74 61 ature":156,"Percenta 2021-10-29 00:47:49.041 Heating: (Heating) 67 65 44 65 6d 61 6e 64 22 3a 30 2c 22 57 69 6e 64 6f 77 53 geDemand":0,"WindowS 2021-10-29 00:47:49.041 Heating: (Heating) 74 61 74 65 22 3a 22 43 6c 6f 73 65 64 22 7d 2c 7b 22 69 64 tate":"Closed"},{"id 2021-10-29 00:47:49.041 Heating: (Heating) 22 3a 36 2c 22 4d 6f 75 6e 74 69 6e 67 4f 72 69 65 6e 74 61 ":6,"MountingOrienta 2021-10-29 00:47:49.041 Heating: (Heating) 74 69 6f 6e 22 3a 22 56 65 72 74 69 63 61 6c 22 2c 22 53 65 tion":"Vertical","Se 2021-10-29 00:47:49.042 Heating: (Heating) 74 50 6f 69 6e 74 22 3a 2d 32 30 30 2c 22 4d 65 61 73 75 72 tPoint":-200,"Measur 2021-10-29 00:47:49.042 Heating: (Heating) 65 64 54 65 6d 70 65 72 61 74 75 72 65 22 3a 31 35 37 2c 22 edTemperature":157," 2021-10-29 00:47:49.042 Heating: (Heating) 50 65 72 63 65 6e 74 61 67 65 44 65 6d 61 6e 64 22 3a 30 2c PercentageDemand":0, 2021-10-29 00:47:49.042 Heating: (Heating) 22 57 69 6e 64 6f 77 53 74 61 74 65 22 3a 22 43 6c 6f 73 65 "WindowState":"Close 2021-10-29 00:47:49.042 Heating: (Heating) 64 22 7d 5d 2c 22 53 6d 61 72 74 50 6c 75 67 22 3a 5b 7b 22 d"}],"SmartPlug":[{" 2021-10-29 00:47:49.042 Heating: (Heating) 69 64 22 3a 37 2c 22 4d 61 6e 75 61 6c 53 74 61 74 65 22 3a id":7,"ManualState": 2021-10-29 00:47:49.042 Heating: (Heating) 22 4f 66 66 22 2c 22 4e 61 6d 65 22 3a 22 53 69 67 6e 61 6c "Off","Name":"Signal 2021-10-29 00:47:49.042 Heating: (Heating) 20 72 65 70 65 61 74 65 72 22 2c 22 4d 6f 64 65 22 3a 22 4d .repeater","Mode":"M 2021-10-29 00:47:49.042 Heating: (Heating) 61 6e 75 61 6c 22 2c 22 41 77 61 79 41 63 74 69 6f 6e 22 3a anual","AwayAction": 2021-10-29 00:47:49.042 Heating: (Heating) 22 4f 66 66 22 2c 22 52 6f 6f 6d 49 64 22 3a 32 2c 22 4f 75 "Off","RoomId":2,"Ou 2021-10-29 00:47:49.042 Heating: (Heating) 74 70 75 74 53 74 61 74 65 22 3a 22 4f 66 66 22 2c 22 43 6f tputState":"Off","Co 2021-10-29 00:47:49.042 Heating: (Heating) 6e 74 72 6f 6c 53 6f 75 72 63 65 22 3a 22 46 72 6f 6d 4d 61 ntrolSource":"FromMa 2021-10-29 00:47:49.042 Heating: (Heating) 6e 75 61 6c 4d 6f 64 65 22 2c 22 43 75 72 72 65 6e 74 53 75 nualMode","CurrentSu 2021-10-29 00:47:49.042 Heating: (Heating) 6d 6d 61 74 69 6f 6e 44 65 6c 69 76 65 72 65 64 22 3a 30 2c mmationDelivered":0, 2021-10-29 00:47:49.042 Heating: (Heating) 22 49 6e 73 74 61 6e 74 61 6e 65 6f 75 73 44 65 6d 61 6e 64 "InstantaneousDemand 2021-10-29 00:47:49.042 Heating: (Heating) 22 3a 30 2c 22 54 61 72 67 65 74 53 74 61 74 65 22 3a 22 4f ":0,"TargetState":"O 2021-10-29 00:47:49.042 Heating: (Heating) 66 66 22 7d 5d 2c 22 44 65 76 69 63 65 43 61 70 61 62 69 6c ff"}],"DeviceCapabil 2021-10-29 00:47:49.042 Heating: (Heating) 69 74 79 4d 61 74 72 69 78 22 3a 7b 22 52 6f 6f 6d 73 74 61 ityMatrix":{"Roomsta 2021-10-29 00:47:49.042 Heating: (Heating) 74 22 3a 74 72 75 65 2c 22 49 54 52 56 22 3a 74 72 75 65 2c t":true,"ITRV":true, 2021-10-29 00:47:49.042 Heating: (Heating) 22 53 6d 61 72 74 50 6c 75 67 22 3a 74 72 75 65 2c 22 55 46 "SmartPlug":true,"UF 2021-10-29 00:47:49.042 Heating: (Heating) 48 22 3a 74 72 75 65 2c 22 55 46 48 46 6c 6f 6f 72 54 65 6d H":true,"UFHFloorTem 2021-10-29 00:47:49.042 Heating: (Heating) 70 53 65 6e 73 6f 72 22 3a 74 72 75 65 2c 22 55 46 48 44 65 pSensor":true,"UFHDe 2021-10-29 00:47:49.042 Heating: (Heating) 77 53 65 6e 73 6f 72 22 3a 74 72 75 65 2c 22 48 41 43 54 22 wSensor":true,"HACT" 2021-10-29 00:47:49.042 Heating: (Heating) 3a 66 61 6c 73 65 2c 22 4c 41 43 54 22 3a 66 61 6c 73 65 2c :false,"LACT":false, 2021-10-29 00:47:49.042 Heating: (Heating) 22 4c 69 67 68 74 22 3a 66 61 6c 73 65 2c 22 53 68 75 74 74 "Light":false,"Shutt 2021-10-29 00:47:49.042 Heating: (Heating) 65 72 22 3a 66 61 6c 73 65 2c 22 4c 6f 61 64 43 6f 6e 74 72 er":false,"LoadContr 2021-10-29 00:47:49.042 Heating: (Heating) 6f 6c 6c 65 72 22 3a 74 72 75 65 7d 7d 0d 0a 30 0d 0a 0d 0a oller":true}}..0.... 2021-10-29 00:47:49.042 Heating: (Heating) Pushing 'onMessageCallback' on to queue 2021-10-29 00:47:49.042 Heating: (Heating) Processing 'ReadEvent' message 2021-10-29 00:47:49.042 Heating: (Heating) Received 5 bytes of data 2021-10-29 00:47:49.043 Heating: (Heating) 30 0d 0a 0d 0a .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. 0.... 2021-10-29 00:47:49.043 Error: PluginSystem: Exception processing message.