mirko / SonOTA

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

S31 does not flash #163

Closed AlphaDE closed 5 years ago

AlphaDE commented 5 years ago

Trying to flash just bought S31 with sonota, I see an uncaugt exception on my Raspberry Pi 3B and on Windows 10 Pro, sonota.exe keeps in stage 2 and the SSID "FinalStage" never appears.

S31 after some times seems to terminate flash mode, the wifi led rythm changes and the ITEAD SSID disappears.

The S31 has two pairing modes, the first one designed to directly interact with eweLink, the second one called AP mode where a manual connect to the ITEAD SSID is possible (the first one is activated after 5 secs button press, the second one after 5 secs button in the first mode).

Anybody with S31 experience who can give me some hints how to get a successful flash? I already ordered a serial converter and pin heads but I would like to avoid to open and sold heads for 10 units. Thanks.

Windows 10 debug log:

2019-01-19 14:42:02,672: DEBUG: Current IPs: ['192.168.3.88'] 2019-01-19 14:43:15,838: INFO: Using the following configuration: 2019-01-19 14:43:15,853: INFO: Server IP Address: 192.168.3.88 2019-01-19 14:43:15,853: INFO: WiFi SSID: FRITZ!Box Fon WLAN 7390 2.5 2019-01-19 14:43:15,853: INFO: WiFi Password: * 2019-01-19 14:43:15,853: INFO: Platform: win32 2019-01-19 14:43:15,953: INFO: Now connect via WiFi to your Sonoff device. 2019-01-19 14:43:15,953: INFO: Please change into the ITEAD WiFi network (ITEAD-100001XXXX). The default password is 12345678. 2019-01-19 14:43:15,953: INFO: To reset the Sonoff to defaults, press the button for 7 seconds and the light will start flashing rapidly. 2019-01-19 14:43:15,953: INFO: * This application should be kept running and will wait until connected to the Sonoff... 2019-01-19 14:44:00,389: DEBUG: Current IPs: ['10.10.7.2'] 2019-01-19 14:44:00,488: DEBUG: ~~ Connection attempt 2019-01-19 14:44:00,488: DEBUG: >> HTTP GET /10.10.7.1/device 2019-01-19 14:44:01,526: DEBUG: << { 2019-01-19 14:44:01,526: DEBUG: "apikey": "b14f4b39-e04f-4b9c-a812-bd0cc818835b", 2019-01-19 14:44:01,526: DEBUG: "accept": "post", 2019-01-19 14:44:01,526: DEBUG: "deviceid": "1000383ebf" 2019-01-19 14:44:01,526: DEBUG: } 2019-01-19 14:44:01,526: DEBUG: >> HTTP POST /10.10.7.1/ap 2019-01-19 14:44:01,526: DEBUG: >> { 2019-01-19 14:44:01,526: DEBUG: "serverName": "192.168.3.88", 2019-01-19 14:44:01,526: DEBUG: "version": 4, 2019-01-19 14:44:01,526: DEBUG: "ssid": "FRITZ!Box Fon WLAN 7390 2.5", 2019-01-19 14:44:01,526: DEBUG: "port": 443, 2019-01-19 14:44:01,526: DEBUG: "password": "" 2019-01-19 14:44:01,526: DEBUG: } 2019-01-19 14:44:01,619: DEBUG: << { 2019-01-19 14:44:01,619: DEBUG: "error": 0 2019-01-19 14:44:01,619: DEBUG: } 2019-01-19 14:44:01,619: INFO: ~~ Provisioning completed 2019-01-19 14:44:01,619: INFO: Starting stage2... 2019-01-19 14:44:01,686: INFO: The IP address of (192.168.3.88) is not assigned to any interface on this machine. 2019-01-19 14:44:01,686: INFO: Please change WiFi network to FRITZ!Box Fon WLAN 7390 2.5 and make sure 192.168.3.88 is being assigned to your WiFi interface. 2019-01-19 14:44:01,686: INFO: This application should be kept running and will wait until connected to the WiFi... 2019-01-19 14:44:10,092: DEBUG: Current IPs: ['192.168.3.88'] 2019-01-19 14:44:10,092: INFO: ~~ Starting web server (HTTP port: 8080, HTTPS port 443) 2019-01-19 14:44:10,757: INFO: ~~ Waiting for device to connect 2019-01-19 14:44:11,148: INFO: ** IMPORTANT! 2019-01-19 14:44:11,148: 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. 2019-01-19 14:44:11,163: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:44:11,163: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:44:11,163: 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. 2019-01-19 14:45:13,205: INFO: IMPORTANT! 2019-01-19 14:45:13,205: 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. 2019-01-19 14:45:13,220: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:45:13,220: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:45:13,228: 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. 2019-01-19 14:46:15,117: INFO: IMPORTANT! 2019-01-19 14:46:15,117: 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. 2019-01-19 14:46:15,117: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:46:15,117: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:46:15,117: 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. 2019-01-19 14:47:16,752: INFO: IMPORTANT! 2019-01-19 14:47:16,752: 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. 2019-01-19 14:47:16,752: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:47:16,767: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:47:16,767: 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. 2019-01-19 14:48:18,463: INFO: IMPORTANT! 2019-01-19 14:48:18,478: 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. 2019-01-19 14:48:18,478: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:48:18,478: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:48:18,478: 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. 2019-01-19 14:49:20,246: INFO: IMPORTANT! 2019-01-19 14:49:20,261: 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. 2019-01-19 14:49:20,261: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:49:20,261: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:49:20,261: 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.

===================================================

Raspberry Pi 3B debug log

2019-01-19 14:51:53,443: DEBUG: Current IPs: ['192.168.3.90'] 2019-01-19 14:51:53,447: INFO: Using the following configuration: 2019-01-19 14:51:53,448: INFO: Server IP Address: 192.168.3.90 2019-01-19 14:51:53,448: INFO: WiFi SSID: FRITZ!Box Fon WLAN 7390 2.5 2019-01-19 14:51:53,448: INFO: WiFi Password: * 2019-01-19 14:51:53,449: INFO: Platform: linux 2019-01-19 14:51:53,451: INFO: Now connect via WiFi to your Sonoff device. 2019-01-19 14:51:53,451: INFO: Please change into the ITEAD WiFi network (ITEAD-100001XXXX). The default password is 12345678. 2019-01-19 14:51:53,451: INFO: To reset the Sonoff to defaults, press the button for 7 seconds and the light will start flashing rapidly. 2019-01-19 14:51:53,452: INFO: * This application should be kept running and will wait until connected to the Sonoff... 2019-01-19 14:53:53,776: DEBUG: Current IPs: [] 2019-01-19 14:53:59,793: DEBUG: Current IPs: ['10.10.7.2'] 2019-01-19 14:53:59,796: DEBUG: ~~ Connection attempt 2019-01-19 14:53:59,797: DEBUG: >> HTTP GET /10.10.7.1/device 2019-01-19 14:53:59,814: DEBUG: << { 2019-01-19 14:53:59,815: DEBUG: "apikey": "b14f4b39-e04f-4b9c-a812-bd0cc818835b", 2019-01-19 14:53:59,816: DEBUG: "accept": "post", 2019-01-19 14:53:59,817: DEBUG: "deviceid": "1000383ebf" 2019-01-19 14:53:59,818: DEBUG: } 2019-01-19 14:53:59,819: DEBUG: >> HTTP POST /10.10.7.1/ap 2019-01-19 14:53:59,820: DEBUG: >> { 2019-01-19 14:53:59,821: DEBUG: "password": "", 2019-01-19 14:53:59,822: DEBUG: "version": 4, 2019-01-19 14:53:59,823: DEBUG: "serverName": "192.168.3.90", 2019-01-19 14:53:59,825: DEBUG: "ssid": "FRITZ!Box Fon WLAN 7390 2.5", 2019-01-19 14:53:59,826: DEBUG: "port": 8443 2019-01-19 14:53:59,828: DEBUG: } 2019-01-19 14:53:59,915: DEBUG: << { 2019-01-19 14:53:59,916: DEBUG: "error": 0 2019-01-19 14:53:59,916: DEBUG: } 2019-01-19 14:53:59,917: INFO: ~~ Provisioning completed 2019-01-19 14:53:59,919: INFO: Starting stage2... 2019-01-19 14:53:59,928: INFO: The IP address of (192.168.3.90) is not assigned to any interface on this machine. 2019-01-19 14:53:59,929: INFO: Please change WiFi network to FRITZ!Box Fon WLAN 7390 2.5 and make sure 192.168.3.90 is being assigned to your WiFi interface. 2019-01-19 14:53:59,930: INFO: This application should be kept running and will wait until connected to the WiFi... 2019-01-19 14:54:01,935: DEBUG: Current IPs: [] 2019-01-19 14:54:32,187: DEBUG: Current IPs: ['192.168.3.90'] 2019-01-19 14:54:32,188: INFO: ~~ Starting web server (HTTP port: 8080, HTTPS port 8443) 2019-01-19 14:54:32,191: DEBUG: Using selector: EpollSelector 2019-01-19 14:54:32,209: INFO: ~~ Waiting for device to connect 2019-01-19 14:54:32,213: INFO: ** IMPORTANT! 2019-01-19 14:54:32,215: 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. 2019-01-19 14:54:32,216: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:54:32,218: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:54:32,220: 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. 2019-01-19 14:54:34,225: DEBUG: Current IPs: [] 2019-01-19 14:54:38,234: DEBUG: Current IPs: ['192.168.3.90'] 2019-01-19 14:54:52,632: ERROR: Uncaught exception, closing connection. Traceback (most recent call last): File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:54:52,648: ERROR: Exception in callback None() handle: Traceback (most recent call last): File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run self._callback(self._args) File "/usr/local/lib/python3.5/dist-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/usr/local/lib/python3.5/dist-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, kwargs) File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:05,265: ERROR: Uncaught exception, closing connection. Traceback (most recent call last): File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:05,269: ERROR: Exception in callback None() handle: Traceback (most recent call last): File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run self._callback(self._args) File "/usr/local/lib/python3.5/dist-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/usr/local/lib/python3.5/dist-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, kwargs) File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:23,298: ERROR: Uncaught exception, closing connection. Traceback (most recent call last): File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:23,302: ERROR: Exception in callback None() handle: Traceback (most recent call last): File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run self._callback(self._args) File "/usr/local/lib/python3.5/dist-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/usr/local/lib/python3.5/dist-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, kwargs) File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:32,342: INFO: ** IMPORTANT! 2019-01-19 14:55:32,343: 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. 2019-01-19 14:55:32,343: INFO: ONLY disconnect when the new "FinalStage" SSID is visible as an available WiFi network. 2019-01-19 14:55:32,344: INFO: This server should automatically be allocated the IP address: 192.168.4.2. 2019-01-19 14:55:32,345: 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. 2019-01-19 14:55:34,326: ERROR: Uncaught exception, closing connection. Traceback (most recent call last): File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:34,330: ERROR: Exception in callback None() handle: Traceback (most recent call last): File "/usr/lib/python3.5/asyncio/events.py", line 126, in _run self._callback(self._args) File "/usr/local/lib/python3.5/dist-packages/tornado/platform/asyncio.py", line 122, in _handle_events handler_func(fileobj, events) File "/usr/local/lib/python3.5/dist-packages/tornado/stack_context.py", line 300, in null_wrapper return fn(args, **kwargs) File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 709, in _handle_events self._handle_read() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1581, in _handle_read self._do_ssl_handshake() File "/usr/local/lib/python3.5/dist-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake self.socket.do_handshake() File "/usr/lib/python3.5/ssl.py", line 996, in do_handshake self._sslobj.do_handshake() File "/usr/lib/python3.5/ssl.py", line 641, in do_handshake self._sslobj.do_handshake() OSError: [Errno 0] Error 2019-01-19 14:55:42,730: INFO: Quitting.

jgalak commented 5 years ago

Without thinking about it, I upgraded my S31 to 2.8.0 and am getting basically the same result - endless looping with errors in do_handshake at this exact stage of the process. Really hoping there's a fix, as soldering to the S31's board is a bit more annoying than I expected.

AlphaDE commented 5 years ago

To avoid the soldering I create a sort of connector... a piece of thin wood, an 8 pin header connector (used for soldering) and a small cable tie. I short the inner 6 shorter connectors so they keep inside the solding spots, bend the right connector which helps aligning and cut the left connector. Then I drill a holl into the wood so the pin header connector fits well between the edge of the wood and that hole and fix the ping header connector with the cable tie. That way, I can plug the construction just onto the ESP8266 connector area. It's quick and dirty, but it works... and it's cheap and avoids soldering many, many contacts in a tiny area. And the S31 is easy to open (in opposite to my HEYGO_02 where I yet did not find a way to open without damaging the case).

See picture (looks like I cannot attach one):

https://www.akxnet.de/S31Connector.jpg

Material from Amazon and some tools:

Hotop 50 Pack Single Row 40 Pin 2.54 mm Male Pin Header Connector ($7) USB to TTL Adapter, USB to Serial Converter for Development Projects ($12.50)

jgalak commented 5 years ago

To avoid the soldering I create a sort of connector... a piece of thin wood, an 8 pin header connector (used for soldering) and a small cable tie.

Well, clearly I'm overthinking my approach a good bit - I'm designing a 3-D printed jig for doing this type of connection (not restricted to the S31). It's close to being done, I've been iterating the design for a few weeks, to make it work well.

The "proper" solution would involve pogo pins, but I didn't want to deal with that...

But flashing OTA would still be much nicer.

sillyfrog commented 5 years ago

@AlphaDE This is just the issue as per #58 - I think as it's a newer device v1 must also have this issue. Until Sonoff provides a way to do, you'll be stuck with pulling it apart unfortunately.