mirko / SonOTA

Flashing Itead Sonoff devices with custom firmware via original OTA mechanism
GNU General Public License v2.0
718 stars 105 forks source link

Flashing Tasmota is not working #141

Open RamiHaikal opened 5 years ago

RamiHaikal commented 5 years ago

I have tried everything but it is not working, can anyone help? Below is what I am getting.

./sonota.py --legacy Current IPs: ['192.168.1.20'] Select IP address of the WiFi interface: 0: 192.168.1.20 Select IP address [0]: 0 WiFi SSID: R&R WiFi Password: ****

Using the following configuration: Server IP Address: 192.168.1.20 WiFi SSID: R&R WiFi Password: **** Platform: darwin Now connect via WiFi to your Sonoff device. Please change into the ITEAD WiFi network (ITEAD-100001XXXX). The default password is 12345678. To reset the Sonoff to defaults, press the button for 7 seconds and the light will start flashing rapidly. ** This application should be kept running and will wait until connected to the Sonoff... ...Current IPs: [] ..Current IPs: ['10.10.7.2'] ~~ Connection attempt

HTTP GET /10.10.7.1/device << { "deviceid": "1000439fa8", "apikey": "c7d3afc6-4ddb-4d77-922c-c410502dbfa6", "accept": "post" } HTTP POST /10.10.7.1/ap { "version": 4, "ssid": "R&R", "password": "****", "serverName": "192.168.1.20", "port": 443 } << { "error": 0 } ~~ Provisioning completed Starting stage2... The IP address of (192.168.1.20) is not assigned to any interface on this machine. Please change WiFi network to R&R and make sure 192.168.1.20 is being assigned to your WiFi interface. ** This application should be kept running and will wait until connected to the WiFi... ......Current IPs: [] .....Current IPs: ['192.168.1.20'] ~~ Starting web server (HTTP port: 8080, HTTPS port 443) Using selector: KqueueSelector Traceback (most recent call last): File "./sonota.py", line 734, in main() File "./sonota.py", line 730, in main stage2() File "./sonota.py", line 660, in stage2 app_ssl.listen(DEFAULT_PORT_HTTPS) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/tcpserver.py", line 143, in listen sockets = bind_sockets(port, address=address) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/netutil.py", line 168, in bind_sockets sock.bind(sockaddr) PermissionError: [Errno 13] Permission denied

sillyfrog commented 5 years ago

Have you tried running without --legacy - it'll be an extremely old unit if you need that. If you do need legacy, run it as root (ie: sudo ./sonota...)

RamiHaikal commented 5 years ago

When I ran without --legacy it didn't work and I read somewhere that it might help, I tried sudo but also didn't work.

I ran without --legacy and here is what I am getting:

./sonota.py Current IPs: ['192.168.1.20'] Select IP address of the WiFi interface: 0: 192.168.1.20 Select IP address [0]: 0 WiFi SSID: R&R WiFi Password: *****

Using the following configuration: Server IP Address: 192.168.1.20 WiFi SSID: R&R WiFi Password: **** Platform: darwin Now connect via WiFi to your Sonoff device. Please change into the ITEAD WiFi network (ITEAD-100001XXXX). The default password is 12345678. To reset the Sonoff to defaults, press the button for 7 seconds and the light will start flashing rapidly. ** This application should be kept running and will wait until connected to the Sonoff... ...........................Current IPs: ['10.10.7.2'] ~~ Connection attempt

HTTP GET /10.10.7.1/device << { "deviceid": "1000439fa8", "apikey": "c7d3afc6-4ddb-4d77-922c-c410502dbfa6", "accept": "post" } HTTP POST /10.10.7.1/ap { "version": 4, "ssid": "R&R", "password": "****", "serverName": "192.168.1.20", "port": 8443 } << { "error": 0 } ~~ Provisioning completed Starting stage2... The IP address of (192.168.1.20) is not assigned to any interface on this machine. Please change WiFi network to R&R and make sure 192.168.1.20 is being assigned to your WiFi interface. ** This application should be kept running and will wait until connected to the WiFi... ......Current IPs: [] ..Current IPs: ['192.168.1.20'] ~~ Starting web server (HTTP port: 8080, HTTPS port 8443) Traceback (most recent call last): File "./sonota.py", line 734, in main() File "./sonota.py", line 730, in main stage2() File "./sonota.py", line 653, in stage2 app.listen(DEFAULT_PORT_HTTP) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/web.py", line 2042, in listen server.listen(port, address) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/tcpserver.py", line 143, in listen sockets = bind_sockets(port, address=address) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/netutil.py", line 168, in bind_sockets sock.bind(sockaddr) OSError: [Errno 48] Address already in use

sillyfrog commented 5 years ago

You will see the error is "Address already in use" - that means something is already running on one of the ports (eg: port 8080). Be sure to shut down all services that are listening on your Mac to be safe.

RamiHaikal commented 5 years ago

Now I am getting this error:

Starting stage2... The IP address of (192.168.1.20) is not assigned to any interface on this machine. Please change WiFi network to R&R and make sure 192.168.1.20 is being assigned to your WiFi interface. ** This application should be kept running and will wait until connected to the WiFi... ......Current IPs: ['192.168.1.20'] ~~ Starting web server (HTTP port: 8080, HTTPS port 8443) Using selector: KqueueSelector ~~ Waiting for device to connect

IMPORTANT! AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. This server should automatically be allocated the IP address: 192.168.4.2. If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. .Uncaught exception, closing connection. Traceback (most recent call last): File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1108, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error Exception in callback None() handle: Traceback (most recent call last): File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/events.py", line 88, in _run self._context.run(self._callback, self._args) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, kwargs) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1108, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error ..............Uncaught exception, closing connection. Traceback (most recent call last): File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1108, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error Exception in callback None() handle: Traceback (most recent call last): File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/events.py", line 88, in _run self._context.run(self._callback, self._args) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, kwargs) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1108, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error ...........Uncaught exception, closing connection. Traceback (most recent call last): File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1108, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error Exception in callback None() handle: Traceback (most recent call last): File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/events.py", line 88, in _run self._context.run(self._callback, self._args) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, **kwargs) File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/Users/ramihaikal/Library/Python/3.7/lib/python/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1108, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error

sillyfrog commented 5 years ago

That's.... weird... I would suggest trying Python 3.6 as it's not been tested with 3.7 on a Mac as it has only been released recently.

RamiHaikal commented 5 years ago

I installed 3.6 and I am not getting the handshake exception anymore. But Sonoff is not changing to the Finalstage SSID, I have waited for 20 minutes but still it is not switching to that SSID.

The firewall on my MAC is turned off

giovannigenna commented 5 years ago

@RamiHaikal have you resolved the issue ?

robdejonge commented 5 years ago

I get the exact same messages as @RamiHaikal as listed in the Aug 18 comment. Sonoff Basic running 2.6.0, SonOTA downloaded today.

Salsalove commented 5 years ago

Same issue...Maybe SonOTA method doesn’t work on 2.6.0 firmware...

Tom1803 commented 5 years ago

Raspian: The same issue as @RamiHaikal as listed in the Aug 18 comment. Windows: No Error Messages, but won't start downloading firmware in "Stage2" Looks like Sonoff connects brave to local update Server - but serversite crashes.

mjhartley commented 5 years ago

Python version 2.7.10 Mac O/S Majove Sonoff PoW v 2.0.2 Firewall has been disabled.

Hi. I've attempted to up date 2 PoWs and they are both in the same state now. The LED is permanently on and the relay clicks every X minutes.

When I ran through the upgrade process, stage 4 did not appear to execute

Attached is the log. "Once the firmware has been downloaded, there will be a new FinalStage SSID that you can connect to. Do this, and the device will then download the final stages of the firmware, including the Arduino image, replacing the default boot loader."

2018-12-02 20:31:35,118: DEBUG: Current IPs: ['192.168.1.15', '10.6.6.152'] 2018-12-02 20:32:31,232: INFO: Using the following configuration: 2018-12-02 20:32:31,232: INFO: Server IP Address: 192.168.1.15 2018-12-02 20:32:31,232: INFO: WiFi SSID: belkin.7fd_front 2018-12-02 20:32:31,232: INFO: WiFi Password: ** 2018-12-02 20:32:31,232: INFO: Platform: darwin 2018-12-02 20:32:31,243: INFO: Now connect via WiFi to your Sonoff device. 2018-12-02 20:32:31,243: INFO: Please change into the ITEAD WiFi network (ITEAD-100001XXXX). The default password is 12345678. 2018-12-02 20:32:31,243: INFO: To reset the Sonoff to defaults, press the button for 7 seconds and the light will start flashing rapidly. 2018-12-02 20:32:31,243: INFO: This application should be kept running and will wait until connected to the Sonoff... 2018-12-02 20:32:59,382: DEBUG: Current IPs: [] 2018-12-02 20:33:03,397: DEBUG: Current IPs: ['10.10.7.3'] 2018-12-02 20:33:03,404: DEBUG: ~~ Connection attempt 2018-12-02 20:33:03,404: DEBUG: >> HTTP GET /10.10.7.1/device 2018-12-02 20:33:03,432: DEBUG: << { 2018-12-02 20:33:03,432: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:03,432: DEBUG: "apikey": "747c979d-a2ed-4952-a34b-fc622b64d572", 2018-12-02 20:33:03,432: DEBUG: "accept": "post" 2018-12-02 20:33:03,432: DEBUG: } 2018-12-02 20:33:03,432: DEBUG: >> HTTP POST /10.10.7.1/ap 2018-12-02 20:33:03,433: DEBUG: >> { 2018-12-02 20:33:03,433: DEBUG: "version": 4, 2018-12-02 20:33:03,433: DEBUG: "ssid": "belkin.7fd_front", 2018-12-02 20:33:03,434: DEBUG: "password": "****", 2018-12-02 20:33:03,434: DEBUG: "serverName": "192.168.1.15", 2018-12-02 20:33:03,434: DEBUG: "port": 443 2018-12-02 20:33:03,434: DEBUG: } 2018-12-02 20:33:03,542: DEBUG: << { 2018-12-02 20:33:03,543: DEBUG: "error": 0 2018-12-02 20:33:03,543: DEBUG: } 2018-12-02 20:33:03,543: INFO: ~~ Provisioning completed 2018-12-02 20:33:03,543: INFO: Starting stage2... 2018-12-02 20:33:03,549: INFO: The IP address of (192.168.1.15) is not assigned to any interface on this machine. 2018-12-02 20:33:03,549: INFO: Please change WiFi network to belkin.7fd_front and make sure 192.168.1.15 is being assigned to your WiFi interface. 2018-12-02 20:33:03,549: INFO: This application should be kept running and will wait until connected to the WiFi... 2018-12-02 20:33:41,635: DEBUG: Current IPs: [] 2018-12-02 20:33:43,638: DEBUG: Current IPs: ['192.168.1.15'] 2018-12-02 20:33:43,639: INFO: ~~ Starting web server (HTTP port: 8080, HTTPS port 443) 2018-12-02 20:33:43,641: DEBUG: Using selector: KqueueSelector 2018-12-02 20:33:43,643: INFO: ~~ Waiting for device to connect 2018-12-02 20:33:43,647: INFO: ** IMPORTANT! 2018-12-02 20:33:43,647: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:33:43,648: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:33:43,648: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:33:43,648: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:33:45,652: DEBUG: Current IPs: ['192.168.1.15', '10.6.6.152'] 2018-12-02 20:33:53,395: DEBUG: << HTTP POST /dispatch/device 2018-12-02 20:33:53,396: DEBUG: >> /dispatch/device 2018-12-02 20:33:53,396: DEBUG: >> { 2018-12-02 20:33:53,396: DEBUG: "error": 0, 2018-12-02 20:33:53,396: DEBUG: "reason": "ok", 2018-12-02 20:33:53,396: DEBUG: "IP": "192.168.1.15", 2018-12-02 20:33:53,396: DEBUG: "port": 443 2018-12-02 20:33:53,396: DEBUG: } 2018-12-02 20:33:53,397: INFO: 200 POST /dispatch/device (192.168.1.48) 4.14ms 2018-12-02 20:33:53,409: INFO: 101 GET /api/ws (192.168.1.48) 0.97ms 2018-12-02 20:33:53,409: DEBUG: << WEBSOCKET OPEN 2018-12-02 20:33:53,413: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:33:53,413: DEBUG: << { 2018-12-02 20:33:53,413: DEBUG: "userAgent": "device", 2018-12-02 20:33:53,414: DEBUG: "apikey": "747c979d-a2ed-4952-a34b-fc622b64d572", 2018-12-02 20:33:53,414: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,414: DEBUG: "action": "register", 2018-12-02 20:33:53,414: DEBUG: "version": 2, 2018-12-02 20:33:53,414: DEBUG: "romVersion": "2.0.2", 2018-12-02 20:33:53,414: DEBUG: "model": "PSC-B01-GL", 2018-12-02 20:33:53,414: DEBUG: "ts": 374 2018-12-02 20:33:53,414: DEBUG: } 2018-12-02 20:33:53,414: DEBUG: ~~~ device sent action request, acknowledging / answering... 2018-12-02 20:33:53,415: INFO: We are dealing with a PSC-B01-GL model. 2018-12-02 20:33:53,415: DEBUG: ~~~~ register 2018-12-02 20:33:53,415: DEBUG: >> { 2018-12-02 20:33:53,415: DEBUG: "error": 0, 2018-12-02 20:33:53,415: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,415: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,415: DEBUG: "config": { 2018-12-02 20:33:53,415: DEBUG: "hb": 1, 2018-12-02 20:33:53,415: DEBUG: "hbInterval": 145 2018-12-02 20:33:53,416: DEBUG: } 2018-12-02 20:33:53,416: DEBUG: } 2018-12-02 20:33:53,420: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:33:53,421: DEBUG: << { 2018-12-02 20:33:53,421: DEBUG: "userAgent": "device", 2018-12-02 20:33:53,421: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,421: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,421: DEBUG: "action": "date" 2018-12-02 20:33:53,421: DEBUG: } 2018-12-02 20:33:53,422: DEBUG: ~~~ device sent action request, acknowledging / answering... 2018-12-02 20:33:53,422: DEBUG: ~~~~ date 2018-12-02 20:33:53,422: DEBUG: >> { 2018-12-02 20:33:53,422: DEBUG: "error": 0, 2018-12-02 20:33:53,422: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,422: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,422: DEBUG: "date": "2018-12-02T20:33:53.422Z" 2018-12-02 20:33:53,422: DEBUG: } 2018-12-02 20:33:53,426: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:33:53,426: DEBUG: << { 2018-12-02 20:33:53,427: DEBUG: "userAgent": "device", 2018-12-02 20:33:53,427: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,427: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,427: DEBUG: "action": "update", 2018-12-02 20:33:53,427: DEBUG: "params": { 2018-12-02 20:33:53,427: DEBUG: "switch": "off", 2018-12-02 20:33:53,427: DEBUG: "power": "0", 2018-12-02 20:33:53,427: DEBUG: "fwVersion": "2.0.2", 2018-12-02 20:33:53,428: DEBUG: "rssi": -54, 2018-12-02 20:33:53,428: DEBUG: "staMac": "D0:27:00:07:56:7C" 2018-12-02 20:33:53,428: DEBUG: } 2018-12-02 20:33:53,428: DEBUG: } 2018-12-02 20:33:53,428: DEBUG: ~~~ device sent action request, acknowledging / answering... 2018-12-02 20:33:53,428: DEBUG: ~~~~ update 2018-12-02 20:33:53,428: DEBUG: >> { 2018-12-02 20:33:53,428: DEBUG: "error": 0, 2018-12-02 20:33:53,428: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,429: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668" 2018-12-02 20:33:53,429: DEBUG: } 2018-12-02 20:33:53,429: DEBUG: >> { 2018-12-02 20:33:53,429: DEBUG: "action": "update", 2018-12-02 20:33:53,430: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,430: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,430: DEBUG: "userAgent": "app", 2018-12-02 20:33:53,430: DEBUG: "sequence": "1543782833429", 2018-12-02 20:33:53,430: DEBUG: "ts": 0, 2018-12-02 20:33:53,430: DEBUG: "params": { 2018-12-02 20:33:53,430: DEBUG: "switch": "off" 2018-12-02 20:33:53,430: DEBUG: }, 2018-12-02 20:33:53,430: DEBUG: "from": "hackepeter" 2018-12-02 20:33:53,431: DEBUG: } 2018-12-02 20:33:53,431: DEBUG: >> { 2018-12-02 20:33:53,431: DEBUG: "action": "update", 2018-12-02 20:33:53,431: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,431: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,432: DEBUG: "userAgent": "app", 2018-12-02 20:33:53,432: DEBUG: "sequence": "1543782833431", 2018-12-02 20:33:53,432: DEBUG: "ts": 0, 2018-12-02 20:33:53,432: DEBUG: "params": { 2018-12-02 20:33:53,432: DEBUG: "switch": "on" 2018-12-02 20:33:53,432: DEBUG: }, 2018-12-02 20:33:53,432: DEBUG: "from": "hackepeter" 2018-12-02 20:33:53,432: DEBUG: } 2018-12-02 20:33:53,433: DEBUG: >> { 2018-12-02 20:33:53,433: DEBUG: "action": "update", 2018-12-02 20:33:53,433: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,433: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,433: DEBUG: "userAgent": "app", 2018-12-02 20:33:53,433: DEBUG: "sequence": "1543782833433", 2018-12-02 20:33:53,433: DEBUG: "ts": 0, 2018-12-02 20:33:53,433: DEBUG: "params": { 2018-12-02 20:33:53,433: DEBUG: "switch": "off" 2018-12-02 20:33:53,434: DEBUG: }, 2018-12-02 20:33:53,434: DEBUG: "from": "hackepeter" 2018-12-02 20:33:53,434: DEBUG: } 2018-12-02 20:33:53,434: DEBUG: >> { 2018-12-02 20:33:53,434: DEBUG: "action": "update", 2018-12-02 20:33:53,434: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,435: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,435: DEBUG: "userAgent": "app", 2018-12-02 20:33:53,435: DEBUG: "sequence": "1543782833434", 2018-12-02 20:33:53,435: DEBUG: "ts": 0, 2018-12-02 20:33:53,435: DEBUG: "params": { 2018-12-02 20:33:53,435: DEBUG: "switch": "on" 2018-12-02 20:33:53,435: DEBUG: }, 2018-12-02 20:33:53,435: DEBUG: "from": "hackepeter" 2018-12-02 20:33:53,435: DEBUG: } 2018-12-02 20:33:53,436: DEBUG: >> { 2018-12-02 20:33:53,436: DEBUG: "action": "update", 2018-12-02 20:33:53,436: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,436: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,436: DEBUG: "userAgent": "app", 2018-12-02 20:33:53,436: DEBUG: "sequence": "1543782833436", 2018-12-02 20:33:53,436: DEBUG: "ts": 0, 2018-12-02 20:33:53,437: DEBUG: "params": { 2018-12-02 20:33:53,437: DEBUG: "switch": "off" 2018-12-02 20:33:53,437: DEBUG: }, 2018-12-02 20:33:53,437: DEBUG: "from": "hackepeter" 2018-12-02 20:33:53,437: DEBUG: } 2018-12-02 20:33:53,441: DEBUG: >> { 2018-12-02 20:33:53,442: DEBUG: "action": "upgrade", 2018-12-02 20:33:53,442: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,442: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,442: DEBUG: "userAgent": "app", 2018-12-02 20:33:53,442: DEBUG: "sequence": "1543782833441", 2018-12-02 20:33:53,442: DEBUG: "ts": 0, 2018-12-02 20:33:53,443: DEBUG: "params": { 2018-12-02 20:33:53,443: DEBUG: "binList": [ 2018-12-02 20:33:53,443: DEBUG: { 2018-12-02 20:33:53,443: DEBUG: "downloadUrl": "http://192.168.1.15:8080/slowota/image_user1-0x01000.bin", 2018-12-02 20:33:53,443: DEBUG: "digest": "e9b6b18c9905834ec39f88d2ee64362dcc676d13be308460e4a9877f6ddefb0e", 2018-12-02 20:33:53,444: DEBUG: "name": "user1.bin" 2018-12-02 20:33:53,444: DEBUG: }, 2018-12-02 20:33:53,444: DEBUG: { 2018-12-02 20:33:53,444: DEBUG: "downloadUrl": "http://192.168.1.15:8080/slowota/image_user2-0x81000.bin", 2018-12-02 20:33:53,444: DEBUG: "digest": "fb4753bea76a37d8ce83204593d5d91ade05250e70c34b92f82136ad2e946c31", 2018-12-02 20:33:53,444: DEBUG: "name": "user2.bin" 2018-12-02 20:33:53,444: DEBUG: } 2018-12-02 20:33:53,445: DEBUG: ], 2018-12-02 20:33:53,445: DEBUG: "model": "PSC-B01-GL", 2018-12-02 20:33:53,445: DEBUG: "version": "23.42.5" 2018-12-02 20:33:53,445: DEBUG: } 2018-12-02 20:33:53,445: DEBUG: } 2018-12-02 20:33:53,446: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:33:53,446: DEBUG: << { 2018-12-02 20:33:53,446: DEBUG: "userAgent": "device", 2018-12-02 20:33:53,446: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,447: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,447: DEBUG: "action": "query", 2018-12-02 20:33:53,447: DEBUG: "params": [ 2018-12-02 20:33:53,447: DEBUG: "timers", 2018-12-02 20:33:53,447: DEBUG: "timeZone" 2018-12-02 20:33:53,447: DEBUG: ] 2018-12-02 20:33:53,447: DEBUG: } 2018-12-02 20:33:53,447: DEBUG: ~~~ device sent action request, acknowledging / answering... 2018-12-02 20:33:53,448: DEBUG: ~~~~ query 2018-12-02 20:33:53,448: DEBUG: >> { 2018-12-02 20:33:53,448: DEBUG: "error": 0, 2018-12-02 20:33:53,448: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,448: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,448: DEBUG: "params": 0 2018-12-02 20:33:53,448: DEBUG: } 2018-12-02 20:33:53,449: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:33:53,449: DEBUG: << { 2018-12-02 20:33:53,449: DEBUG: "error": 0, 2018-12-02 20:33:53,449: DEBUG: "userAgent": "device", 2018-12-02 20:33:53,449: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:33:53,450: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:33:53,450: DEBUG: "sequence": "1543782833433" 2018-12-02 20:33:53,450: DEBUG: } 2018-12-02 20:33:53,450: DEBUG: ~~~ device acknowledged our action request (seq 1543782833433) with error code 0 2018-12-02 20:33:53,459: DEBUG: Slow Sending file: /slowota/image_user2-0x81000.bin (This may take several minutes) 2018-12-02 20:34:43,810: INFO: IMPORTANT! 2018-12-02 20:34:43,811: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:34:43,811: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:34:43,811: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:34:43,811: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:34:45,845: INFO: 200 GET /slowota/image_user2-0x81000.bin?deviceid=100003ac96&ts=1979932169&sign=8c98389e6eb29be00fc9f31447bc1c6da9fc7d661f8b39403ba433339dd41d8b (192.168.1.48) 52387.10ms 2018-12-02 20:34:45,876: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:34:45,877: DEBUG: << { 2018-12-02 20:34:45,877: DEBUG: "error": 0, 2018-12-02 20:34:45,877: DEBUG: "userAgent": "device", 2018-12-02 20:34:45,877: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:34:45,877: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:34:45,877: DEBUG: "sequence": "1543782833441" 2018-12-02 20:34:45,877: DEBUG: } 2018-12-02 20:34:45,878: DEBUG: ~~~ device acknowledged our action request (seq 1543782833441) with error code 0 2018-12-02 20:34:50,637: DEBUG: << WEBSOCKET INPUT 2018-12-02 20:34:50,637: DEBUG: << { 2018-12-02 20:34:50,638: DEBUG: "userAgent": "device", 2018-12-02 20:34:50,638: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668", 2018-12-02 20:34:50,638: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:34:50,638: DEBUG: "action": "update", 2018-12-02 20:34:50,638: DEBUG: "params": { 2018-12-02 20:34:50,638: DEBUG: "switch": "off", 2018-12-02 20:34:50,638: DEBUG: "power": "0", 2018-12-02 20:34:50,639: DEBUG: "rssi": -54 2018-12-02 20:34:50,639: DEBUG: } 2018-12-02 20:34:50,639: DEBUG: } 2018-12-02 20:34:50,639: DEBUG: ~~~ device sent action request, acknowledging / answering... 2018-12-02 20:34:50,639: DEBUG: ~~~~ update 2018-12-02 20:34:50,640: DEBUG: >> { 2018-12-02 20:34:50,640: DEBUG: "error": 0, 2018-12-02 20:34:50,640: DEBUG: "deviceid": "100003ac96", 2018-12-02 20:34:50,640: DEBUG: "apikey": "49f0a4d8-625c-46fd-b696-8991bc298668" 2018-12-02 20:34:50,640: DEBUG: } 2018-12-02 20:35:43,972: INFO: IMPORTANT! 2018-12-02 20:35:43,973: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:35:43,973: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:35:43,973: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:35:43,973: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:36:44,125: INFO: IMPORTANT! 2018-12-02 20:36:44,127: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:36:44,127: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:36:44,127: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:36:44,127: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:37:44,325: INFO: IMPORTANT! 2018-12-02 20:37:44,326: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:37:44,326: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:37:44,327: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:37:44,327: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:38:44,649: INFO: IMPORTANT! 2018-12-02 20:38:44,649: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:38:44,650: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:38:44,650: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:38:44,650: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:39:44,976: INFO: IMPORTANT! 2018-12-02 20:39:44,978: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:39:44,978: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:39:44,979: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:39:44,979: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:40:45,292: INFO: IMPORTANT! 2018-12-02 20:40:45,293: INFO: AFTER the first download is COMPLETE, with in a minute or so you should connect to the new SSID "FinalStage" to finish the process. 2018-12-02 20:40:45,294: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2018-12-02 20:40:45,294: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2018-12-02 20:40:45,294: INFO: If you have successfully connected to "FinalStage" and this is not the IP Address you were allocated, please ensure no other device has connected, and reboot your Sonoff. 2018-12-02 20:41:03,382: DEBUG: Current IPs: ['192.168.4.2'] 2018-12-02 20:41:03,388: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:41:03,389: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:42:03,625: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:42:03,627: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:43:03,926: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:43:03,928: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:44:04,171: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:44:04,173: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:45:04,398: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:45:04,400: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:45:52,542: DEBUG: Current IPs: [] 2018-12-02 20:45:52,542: INFO: It appears we have been disconnected from the "FinalStage" SSID, however the final image has not been downloaded. Reconnect to "FinalStage" when it returns to continue the process (this may require a power cycle of your Sonoff device)... 2018-12-02 20:46:18,600: DEBUG: Current IPs: ['192.168.4.2'] 2018-12-02 20:46:24,622: DEBUG: Current IPs: [] 2018-12-02 20:46:24,623: INFO: It appears we have been disconnected from the "FinalStage" SSID, however the final image has not been downloaded. Reconnect to "FinalStage" when it returns to continue the process (this may require a power cycle of your Sonoff device)... 2018-12-02 20:46:48,687: DEBUG: Current IPs: ['192.168.4.2'] 2018-12-02 20:46:54,716: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:46:54,717: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:47:54,931: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:47:54,931: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:48:55,161: INFO: The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed. 2018-12-02 20:48:55,162: INFO: If there is no "Sending file: /ota/image_arduino.bin" log entry, ensure all firewalls have been COMPLETELY disabled on your system. 2018-12-02 20:49:09,210: DEBUG: Current IPs: [] 2018-12-02 20:49:09,211: INFO: It appears we have been disconnected from the "FinalStage" SSID, however the final image has not been downloaded. Reconnect to "FinalStage" when it returns to continue the process (this may require a power cycle of your Sonoff device)... 2018-12-02 20:49:13,236: DEBUG: Current IPs: ['192.168.1.15'] 2018-12-02 20:49:15,244: DEBUG: Current IPs: ['192.168.1.15', '10.6.6.173'] 2018-12-02 21:28:00,956: DEBUG: Current IPs: [] 2018-12-02 21:28:11,015: DEBUG: Current IPs: ['192.168.1.15'] 2018-12-02 21:28:17,086: DEBUG: Current IPs: ['192.168.1.15', '10.6.6.197'] 2018-12-02 21:58:19,579: INFO: Quitting.

Please advise. Thanks

pererikl commented 5 years ago

Since fw 2.6 on sonoff ota is no longer working. Seems to work 2> <2.6 Make shure you disabled all firewalls including windows defender for public networks.

sushenmathur commented 5 years ago

debug_1548842483.log Getting the issue with Sonoff fw : 2.6.1 and Python 3.7 is any body else facing this issue

visstro commented 5 years ago

@sushenmathur Looks exactly the same for me.

heiderich commented 5 years ago

The issue reported by by @RamiHaikal in https://github.com/mirko/SonOTA/issues/141#issuecomment-414009618 might be due to the following issue: https://github.com/tornadoweb/tornado/issues/2504

See also https://github.com/mirko/SonOTA/issues/67.