pysonofflanr3 - Unknown message received from device

[edric4github]

• pySonoffLAN version: pysonofflanr3 1.1.4
• Python version: 3.8.5
• Operating System: Ubuntu 20.04.1 LTS

Description

1. Describe what you were trying to get done.
   i am trying to toggle on/off sonoff micro (FW CKA-DM4-GL) with version 3.7.1 firmware.
   (see link for model https://www.itead.cc/sonoff-micro-5v-usb-smart-adaptor.html)

2. Tell us what happened, what went wrong, and what you expected to happen.
   pysonofflanr3 --host {LAN IP address} --api_key {device API key} --device_id {device ID no} on
   ( device API is obtained using the following script https://github.com/Philiptpp/sonoff_registered_devices)

the command return :
021-02-07 13:13:31,769 - info: Initialising SonoffSwitch with host {LAN IP address}:8081
2021-02-07 13:13:32,074 - info: Service type _ewelink._tcp.local. of name eWeLink_1000f54b35._ewelink._tcp.local. added
2021-02-07 13:13:32,076 - error: Unknown message received from device:
2021-02-07 13:13:32,078 - error: Unexpected error in handle_message() for device {device ID no}: Unknown message received from device Traceback (most recent call last):
2021-02-07 13:13:32,078 - error: File "/home/edric/.local/lib/python3.8/site-packages/pysonofflanr3/sonoffdevice.py", line 330, in handle_message
2021-02-07 13:13:32,078 - error: raise Exception("Unknown message received from device")
2021-02-07 13:13:32,078 - error: Exception: Unknown message received from device

then the script just hangs there until i abort it

What I Did

here is a debug output (ran with pysonofflanr3 --host {LAN IP address} --api_key {device API key} --device_id {device id} -l DEBUG on
2021-02-07 13:24:11,721 - info: Initialising SonoffSwitch with host {LAN IP address}:8081
2021-02-07 13:24:11,722 - debug: Initializing SonoffLANModeClient class in SonoffDevice
2021-02-07 13:24:11,723 - debug: enter send_availability_loop()
2021-02-07 13:24:11,723 - debug: waiting for connection
2021-02-07 13:24:11,723 - debug: send_updated_params_loop is active on the event loop
2021-02-07 13:24:11,723 - debug: Starting loop waiting for device params to change
2021-02-07 13:24:11,723 - debug: send_updated_params_loop now awaiting event
2021-02-07 13:24:11,971 - info: Service type _ewelink._tcp.local. of name eWeLink_1000f54b35._ewelink._tcp.local. added
2021-02-07 13:24:11,973 - debug: service is at http://{LAN IP address}:8081
2021-02-07 13:24:11,973 - debug: properties: {b'data4': b'Ew4EHClpy0i7BZYWm/Fr7Zk33MJF4nvqpOEafpeTuvlS1/arhSeoBiLFQZB+zt6ILPYw6n/pUJqp9V0Um/s4/6aL96yorJg2/MQPTtXZK53KUNzuBKpkuvH5ZmWRaLvpE2lYbg=', b'data3': b'BQm+X/xKP4WRbQfuKy7Dp2cggk9QCP+jK1Ygh6QsFpoi8O8rRB2DKPwEnp+V5k6wLRrl/9JQ+/JU2qhtsH71jrqhzjsjD/aOVMyP1efutQGd9bUdXOsGrizUcleCAwdTKjO+zcZG99OUaH2j6/3LZUWxMxoc+Xwrj7U8UOjcFqalOrnxQ7y5BrWHu147dOF1KLAAfPWYENOhGrx+TR3je3asJbS8Muq5YnmJ3dvyoW5K6IwxRpMFRFl', b'data2': b'GNDHtx+7mjVEi7HFinSFtzu3YNVn891A1AyQIYdiFNBKhizbmRh6PxPdAJFVy+nPsRn+/cmNB/5JZpyQDU6gFwzMQc2kkguZa7e0yASvlZuqLiSB2lRjmKfiWQfwOLhR0GdjvWOqpghZ3mHwLRbumAiDEEz4uE5rxvYeD4lxl9nW9ibr8ePu7iSvhsnxGFJEp/LRi913Y76c6ZOtsfY2Rv6sqxkeSPGwgUVhtIelC2DuY2/pbKzH7Ue', b'data1': b'yjEHINDfBk5avN756SJF+oE7LrkzZxpO3inwOoH8nf2WqqjzaoY+srs1DWAdgDfTpOMMyp/1p3+kPXIevBFLZ8LkqYvy7IlFGtHKXYBrXyNb3hz5TkmwT1X/ojssX+l1pr+Ke7xeToyGWtmNK0GBrnQZb/YMIXO9LiKmPsKn5iuOl92AFsiIo9q0N0K+API6jLyxuGlo3Ttc5bABiCxwunP1ymaAmw5zwbQC21XAXtWGcjlfXTQ76iU', b'seq': b'8', b'iv': b'NjM1OTIzNzU1MTk0NjAxNA==', b'encrypt': b'true', b'apivers': b'1', b'type': b'switch_radar', b'id': b'{device id}', b'txtvers': b'1'}
2021-02-07 13:24:11,973 - debug: type: b'switch_radar'
2021-02-07 13:24:11,975 - debug: decrypted data: b'{"switches":[{"switch":"off","outlet":0},{"switch":"off","outlet":1},{"switch":"off","outlet":2},{"switch":"off","outlet":3}],"configure":[{"startup":"off","outlet":0},{"startup":"off","outlet":1},{"startup":"off","outlet":2},{"startup":"off","outlet":3}],"pulses":[{"pulse":"off","width":1000,"outlet":0},{"pulse":"off","width":1000,"outlet":1},{"pulse":"off","width":1000,"outlet":2},{"pulse":"off","width":1000,"outlet":3}],"sledOnline":"on","staMac":"44:5D:5E:01:45:8C","rssi":-62,"senMode":{"enabled":0,"dTime":10,"tUnit":"s","outlets":[0,1,2,3]},"savMode":{"enabled":0,"dTime":1,"tUnit":"m","outlets":[0,1,2,3]},"alertMode":{"enabled":0}}'
2021-02-07 13:24:11,976 - debug: enter handle_message() b'{"switches":[{"switch":"off","outlet":0},{"switch":"off","outlet":1},{"switch":"off","outlet":2},{"switch":"off","outlet":3}],"configure":[{"startup":"off","outlet":0},{"startup":"off","outlet":1},{"startup":"off","outlet":2},{"startup":"off","outlet":3}],"pulses":[{"pulse":"off","width":1000,"outlet":0},{"pulse":"off","width":1000,"outlet":1},{"pulse":"off","width":1000,"outlet":2},{"pulse":"off","width":1000,"outlet":3}],"sledOnline":"on","staMac":"44:5D:5E:01:45:8C","rssi":-62,"senMode":{"enabled":0,"dTime":10,"tUnit":"s","outlets":[0,1,2,3]},"savMode":{"enabled":0,"dTime":1,"tUnit":"m","outlets":[0,1,2,3]},"alertMode":{"enabled":0}}'
2021-02-07 13:24:11,977 - error: Unknown message received from device:
2021-02-07 13:24:11,981 - error: Unexpected error in handle_message() for device {device id}: Unknown message received from device Traceback (most recent call last):
2021-02-07 13:24:11,981 - error: File "/home/{home user folder}/.local/lib/python3.8/site-packages/pysonofflanr3/sonoffdevice.py", line 330, in handle_message
2021-02-07 13:24:11,981 - error: raise Exception("Unknown message received from device")
2021-02-07 13:24:11,981 - error: Exception: Unknown message received from device

[dauheeIRL]

Yeah you might need to fork and handle type "switch_radar"

you could include OUTLET flag also as it appears your device has 4

[dauheeIRL]

ah yes line 330 https://github.com/mattsaxon/pysonofflan/blob/V3-Firmware/pysonofflanr3/sonoffdevice.py

you will need to add into the elif on line 317 for switch_radar. I can cludge into my fork if you wish as this is no longer maintained

[edric4github]

you will need to add into the elif on line 317 for switch_radar.

in simple term, do you mean i need to edit the file by copying elif from line 317 of sonoffdevice.py ? thank you for replying. i didnt realized the library is no longer maintained. i can edit it, but the instuction is a little vague

[dauheeIRL]

Hi, here is my fork:
https://github.com/dauheeIRL/pysonofflan

you would need to uninstall your pysonofflanr3
then download my fork
then install my fork with sudo python3 setup.py install

You can see I just commited small change to handle switch_radar device, maybe it works

[edric4github]

thank you so much. i just downloaded it and tried. Howeverm it threw a new error

2021-02-07 18:29:28,881 - info: Initialising SonoffSwitch with host {device IP}
2021-02-07 18:29:30,030 - info: Service type _ewelink._tcp.local. of name eWeLink_1000f54b35._ewelink._tcp.local. added
2021-02-07 18:29:30,034 - error: Unexpected error in handle_message() for device 1000f54b35: 'switch' Traceback (most recent call last):
2021-02-07 18:29:30,034 - error: File "/home/{user account}/.local/lib/python3.8/site-packages/pysonofflanr3/sonoffdevice.py", line 325, in handle_message
2021-02-07 18:29:30,034 - error: switch_status = response["switch"]
2021-02-07 18:29:30,034 - error: KeyError: 'switch'

[dauheeIRL]

apologies, I moved switch_radar to the strip type handler as your device has multiple outlets - hopefully this update will work for you

[edric4github]

please dont apologize, especially that you have been so helpful and responsive. With the latest update, there is some positive progress: i am able to get the "state" of the device. Yay!

problem: i am still unable to toggle device "on" or "off"

here is the output when i try turning on:
2021-02-07 21:45:20,355 - info: Initialising SonoffSwitch with host {host ip}
2021-02-07 21:45:20,681 - info: Service type _ewelink.tcp.local. of name eWeLink{device id}._ewelink._tcp.local. added
2021-02-07 21:45:20,685 - info: None: Connected event, sending 'available' update
2021-02-07 21:45:20,685 - info: unsolicited update received from switch: off
2021-02-07 21:45:20,686 - info: == Device: {device id} ({device IP}) ==
2021-02-07 21:45:20,686 - info: State: OFF
2021-02-07 21:45:20,686 - info: None: Connected event, waiting for disconnect
2021-02-07 21:45:20,819 - warning: error received: None, b'{"sequence":"1612705520686","seq":2,"error":400}'
2021-02-07 21:45:22,823 - warning: Device: 1000f54b35. Update message not received in timeout period, retry
2021-02-07 21:45:22,892 - warning: error received: None, b'{"sequence":"1612705522823","seq":2,"error":400}'
2021-02-07 21:45:27,899 - warning: Device: 1000f54b35. Update message not received in timeout period, retry
2021-02-07 21:45:27,967 - warning: error received: None, b'{"sequence":"1612705527899","seq":2,"error":400}'
2021-02-07 21:45:37,975 - warning: Device: 1000f54b35. Update message not received in timeout period, retry
2021-02-07 21:45:38,045 - warning: error received: None, b'{"sequence":"1612705537975","seq":2,"error":400}'
^C
Aborted!

similar error when i try to turn off the device:
021-02-07 21:47:18,748 - info: Initialising SonoffSwitch with host {device ip}
2021-02-07 21:47:18,980 - info: Service type _ewelink.tcp.local. of name eWeLink{device id}._ewelink._tcp.local. added
2021-02-07 21:47:18,983 - info: {device id}: Connected event, sending 'available' update
2021-02-07 21:47:18,984 - info: unsolicited update received from switch: on
2021-02-07 21:47:18,984 - info: == Device: {device id} ({device ip}) ==
2021-02-07 21:47:18,984 - info: State: ON
2021-02-07 21:47:18,985 - info: {device id}: Connected event, waiting for disconnect
2021-02-07 21:47:19,110 - warning: error received: {device id}, b'{"sequence":"1612705638985","seq":4,"error":400}'
2021-02-07 21:47:21,114 - warning: Device: {device id}. Update message not received in timeout period, retry
2021-02-07 21:47:21,750 - warning: error received: {device id}, b'{"sequence":"1612705641114","seq":4,"error":400}'
2021-02-07 21:47:26,757 - warning: Device: {device id}. Update message not received in timeout period, retry
2021-02-07 21:47:26,836 - warning: error received: {device id}, b'{"sequence":"1612705646758","seq":4,"error":400}'
2021-02-07 21:47:36,847 - warning: Device: {device id}. Update message not received in timeout period, retry
2021-02-07 21:47:36,934 - warning: error received: {device id}, b'{"sequence":"1612705656847","seq":4,"error":400}'

here is a debug info:
2021-02-07 21:52:20,566 - info: Initialising SonoffSwitch with host {device ip}
2021-02-07 21:52:20,566 - debug: Initializing SonoffLANModeClient class in SonoffDevice
2021-02-07 21:52:20,567 - debug: enter send_availability_loop()
2021-02-07 21:52:20,567 - debug: waiting for connection
2021-02-07 21:52:20,567 - debug: send_updated_params_loop is active on the event loop
2021-02-07 21:52:20,567 - debug: Starting loop waiting for device params to change
2021-02-07 21:52:20,568 - debug: send_updated_params_loop now awaiting event
2021-02-07 21:52:20,871 - info: Service type _ewelink.tcp.local. of name eWeLink{device id}._ewelink._tcp.local. added
2021-02-07 21:52:20,872 - debug: service is at http://{device ip}:8081
2021-02-07 21:52:20,873 - debug: properties: {b'data4': b'XztpnIeNTo5cy9pk2vW7hNcDugXioAZ9TFTZQkaVY/8OEMt6yxLRBUG98RtDgDftcQfUt8ugjkz780HiTqc/t5M9aJHSQt8NrKtjfOhLB0VGkAdxXuYDTu8TNkR6i823rkeoDo=', b'data3': b'3V18FNmGeofww6SkAhsyOgfMf4WtkJqDWNl+3wbMrwPuozm0C9JOzD+s88iZqphbcX2mqsxeQNJDS0R8sfg0cUje5XkQ6uJcSq7R+LmXESRA7KEsNJAdgDXuQJRzHXWbhCFVYECAOnnetFdSPlbs82ls1fY3J4hpMUZGO0ZCdcuZb2LMDXa432QX2qpTIUF8NFaOyisqh0k5w3w/zo2fIQmAZT5WH3ReTUfxxRvsrIx2gdd/IQGBFtc', b'data2': b'erwxCvPigT9LEL1NZGDgtYMT7ACsgs5/wU15Dnwmo61sqRH2fvMoqAQhWGpb8r2tabTogwaawO9OJNOYe01gLqKW9FKwFXzWnCytrSYh3uymYU3OPmxkVgqb7sKj7G4yPaI8QTPX0Kgc9ldxhze1qvWMjaqnQ2DKoqRY0o0RpseDRuinr0vY9e2prK1e9GdsCDeShE8hJuvBB/PhKSuqBJgOwwduKPexWr8Ss13v5PL14uNjh9KtspE', b'data1': b'QvW9lEkeXDGFpHaHuBJyCvrCumD2GpajX1RnuoI631o9BiTRfOx+zzeeiKOgHN3IlAbFnLISEJwjqbax/ugTcmfKwpaMJsWWeXJDPSfWJaGw6gdvZxM/KqqIxPBcldW4QuZU0XvB54nKnqx2R/5bnGJmVpR1I0FvNLgkx8K92utE0n9m2/KZcjDiiYt/lTG1JocQZtjCmqnbg6gSspM5Zfq+QTtQbByl+J7ARmB9Aeq1laNBwaTbsCA', b'seq': b'3', b'iv': b'Mzg4NDQzMzQ5NDc4MTkyMw==', b'encrypt': b'true', b'apivers': b'1', b'type': b'switch_radar', b'id': b'{device id}', b'txtvers': b'1'}
2021-02-07 21:52:20,873 - debug: type: b'switch_radar'
2021-02-07 21:52:20,875 - debug: decrypted data: b'{"switches":[{"switch":"on","outlet":0},{"switch":"off","outlet":1},{"switch":"off","outlet":2},{"switch":"off","outlet":3}],"configure":[{"startup":"off","outlet":0},{"startup":"off","outlet":1},{"startup":"off","outlet":2},{"startup":"off","outlet":3}],"pulses":[{"pulse":"off","width":1000,"outlet":0},{"pulse":"off","width":1000,"outlet":1},{"pulse":"off","width":1000,"outlet":2},{"pulse":"off","width":1000,"outlet":3}],"sledOnline":"on","staMac":"44:5D:5E:01:45:8C","rssi":-52,"senMode":{"enabled":0,"dTime":10,"tUnit":"s","outlets":[0,1,2,3]},"savMode":{"enabled":0,"dTime":1,"tUnit":"m","outlets":[0,1,2,3]},"alertMode":{"enabled":0}}'
2021-02-07 21:52:20,875 - debug: enter handle_message() b'{"switches":[{"switch":"on","outlet":0},{"switch":"off","outlet":1},{"switch":"off","outlet":2},{"switch":"off","outlet":3}],"configure":[{"startup":"off","outlet":0},{"startup":"off","outlet":1},{"startup":"off","outlet":2},{"startup":"off","outlet":3}],"pulses":[{"pulse":"off","width":1000,"outlet":0},{"pulse":"off","width":1000,"outlet":1},{"pulse":"off","width":1000,"outlet":2},{"pulse":"off","width":1000,"outlet":3}],"sledOnline":"on","staMac":"44:5D:5E:01:45:8C","rssi":-52,"senMode":{"enabled":0,"dTime":10,"tUnit":"s","outlets":[0,1,2,3]},"savMode":{"enabled":0,"dTime":1,"tUnit":"m","outlets":[0,1,2,3]},"alertMode":{"enabled":0}}'
2021-02-07 21:52:20,876 - debug: Message: Received status from device, storing in instance
2021-02-07 21:52:20,876 - info: {device id}: Connected event, sending 'available' update
2021-02-07 21:52:20,876 - info: unsolicited update received from switch: on
2021-02-07 21:52:20,876 - debug: Switch update pre-callback filter running
2021-02-07 21:52:20,876 - debug: Not inching switch, calling parent callback
2021-02-07 21:52:20,876 - info: == Device: {device id} ({device ip}) ==
2021-02-07 21:52:20,876 - info: State: ON
2021-02-07 21:52:20,876 - debug: Switch turn_off called.
2021-02-07 21:52:20,876 - debug: Scheduling params update message to device: {'switch': 'off'}
2021-02-07 21:52:20,876 - info: {device id}: Connected event, waiting for disconnect
2021-02-07 21:52:20,876 - debug: Connected!
2021-02-07 21:52:20,876 - debug: params: {'switch': 'off'}
2021-02-07 21:52:20,876 - debug: encrypted: {'sequence': '1612705940876', 'deviceid': '{device id}', 'selfApikey': '123', 'iv': '0xDA4jqgzXLetC3SsQk4UQ==', 'encrypt': True, 'data': 'uZDFGEJ349ePizXzny+cFlrhXk1Pua98dObI9ckp7pw='}
2021-02-07 21:52:20,877 - debug: Sending http message to http://{device ip}:8081/zeroconf/switch: {"sequence":"1612705940876","deviceid":"{device id}","selfApikey":"123","iv":"0xDA4jqgzXLetC3SsQk4UQ==","encrypt":true,"data":"uZDFGEJ349ePizXzny+cFlrhXk1Pua98dObI9ckp7pw="}
2021-02-07 21:52:20,947 - debug: response received: <Response [200]> b'{"sequence":"1612705940876","seq":4,"error":400}'
2021-02-07 21:52:20,948 - warning: error received: {device id}, b'{"sequence":"1612705940876","seq":4,"error":400}'
2021-02-07 21:52:22,950 - warning: Device: {device id}. Update message not received in timeout period, retry
2021-02-07 21:52:22,951 - debug: send_updated_params_loop now awaiting event
2021-02-07 21:52:22,951 - debug: Connected!
2021-02-07 21:52:22,951 - debug: params: {'switch': 'off'}
2021-02-07 21:52:22,952 - debug: encrypted: {'sequence': '1612705942951', 'deviceid': '{device id}', 'selfApikey': '123', 'iv': '3GezDqlg5CH94XcTDXph/Q==', 'encrypt': True, 'data': 'lxjZJhTBR2wWNvYv9j8MhKfheOhy21WkigbYzmVRVWk='}
2021-02-07 21:52:22,953 - debug: Sending http message to http://{device ip}:8081/zeroconf/switch: {"sequence":"1612705942951","deviceid":"{device id}","selfApikey":"123","iv":"3GezDqlg5CH94XcTDXph/Q==","encrypt":true,"data":"lxjZJhTBR2wWNvYv9j8MhKfheOhy21WkigbYzmVRVWk="}
2021-02-07 21:52:23,023 - debug: response received: <Response [200]> b'{"sequence":"1612705942951","seq":4,"error":400}'
2021-02-07 21:52:23,023 - warning: error received: {device id}, b'{"sequence":"1612705942951","seq":4,"error":400}'

thanks a million!

[dauheeIRL]

I'm out of my capabilities zone here, but the sequence issue seems to be a time sync thing not accepted. I wonder could the time on your Mac be off compared to your sonoff - the sequence is generated via

 sequence": str(
                int(time.time() * 1000)
            )

this is in client.py line 359. maybe it different, would you need to have the same timezone on your Mac as to what ewelink expects

[dauheeIRL]

on http://developers.sonoff.tech/sonoff-diy-mode-api-protocol.html it says that error 400:

The operation failed and the request was formatted incorrectly. The request body is not a valid JSON format.

I think device is expecting differently formatted JSON to what is being sent in the command, maybe you could try include the -OUTLET flag and use 0 or 1 or 2 or 3

[edric4github]

thank you for going way out to help me figure this out. i shall tinker with what u said and see where it brings me.

i am using linux. i will check and see if there is a need to sync the internal clock with device. but i think maybe the outlet flag is the issue. i'll keep trying. thank u

[dauheeIRL]

no problem. the more I look at it, sequence is just used to track responses so it wouldn't cause an error as long as is unique which is the case.

I think the smart adapter expects something else to be included in the JSON, although that error code 400 is for bad JSON format which it isn't. Looks like error 422 would be for a param that was sent but not required

If its not the outlet flag, would need to wireshark the network traffic to see what is being transmitted when using the ewelink app.

[edric4github]

exactly what i am thinking, will sniff out the transmission with ewelink app and see whats up.