Getting `"error": 404` and FinalStage SSID Never Comes

[CoderBlue]

I'm using a sonoff basic. When I get to step #4, when I'm supposed to connect to FinalStage SSID, FinalStage never comes. The firmware never seems to flash since I am able to continue to use the switch to turn on/off the outlet and I can repeat the first few steps starting the ITEAD server and connecting, etc. Anybody have this problem and any suggestions ? Using the latest commit. Thanks.

[donoo]

hi,

I too am not seeing the finalstag SSID. I m trying this on Window 10.

Sonoff Basic - Version 1.5.5 Python Version 3.5.4

Logs below: ` D:\HomeAuto\SonOTA-master>python sonota.py Select IP address of the WiFi interface: 0: 192.168.1.13 0: 192.168.1.4 Select IP address [0]: 1 WiFi SSID: Mad WiFi Password: XXXXXXXX

Using the following configuration: Server IP Address: 192.168.1.4 WiFi SSID: Mad WiFi Password: XXXXXXXXX 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... .............~~ Connection attempt

HTTP GET /10.10.7.1/device << { "apikey": "0311c7fd-dca4-46ed-8e61-19f5219455d8", "accept": "post", "deviceid": "10000cba99" } HTTP POST /10.10.7.1/ap %s { "port": 8443, "ssid": "Mad", "version": 4, "serverName": "192.168.1.4", "password": "XXXXXXXXXX" } << { "error": 0 } ~~ Provisioning completed Starting stage2... The IP address of (192.168.1.4) is not assigned to any interface on this machine. Please change WiFi network to Mad and make sure 192.168.1.4 is being assigned to your WiFi interface. ** This application should be kept running and will wait until connected to the WiFi... .....~~ Starting web server (HTTP port: 8080, HTTPS port 8443) ~~ 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. ..........

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. ..........

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. ..........

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 Sonof

`

[sillyfrog]

First thing to do is pull the latest from github. I had forgotten to push a fix for the display of IP addresses (which is there now).

But based on the above logs, the correct IP is selected.

I didn’t have this issue on my Sonoff Basic on v1.5.5, but worth trying with the ‘- -legacy’ option as the Sonoff is not connecting at all when it should be on the WiFi.

Another check worth trying is that the Sonoff does connect to your WiFi by checking your DHCP server logs when on stage 2.

[donoo]

Hi,

I tried with --legacy flag but still same results. One thing i noticed, when i used --legacy flag green light on sonoff stopped blinking after sometime and stayed on solid.

[AlessandroEmm]

~~ Provisioning completed Starting stage2... The IP address of (10.0.1.3) is not assigned to any interface on this machine. Please change WiFi network to B and make sure 10.0.1.3 is being assigned to your WiFi interface. ** This application should be kept running and will wait until connected to the WiFi... ........~~ Starting web server (HTTP port: 8080, HTTPS port 8443) ~~ 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. .<< HTTP POST /dispatch/device

/dispatch/device { "error": 0, "reason": "ok", "IP": "10.0.1.3", "port": 8443 } 2017-09-23 09:20:11,769 (INFO) 200 POST /dispatch/device (10.0.1.21) 1.44ms 2017-09-23 09:20:11,938 (INFO) 101 GET /api/ws (10.0.1.21) 0.81ms 2017-09-23 09:20:11,938 (DEBUG) << WEBSOCKET OPEN 2017-09-23 09:20:11,945 (DEBUG) << WEBSOCKET INPUT 2017-09-23 09:20:11,945 (DEBUG) << { "userAgent": "device", "apikey": "207dc417-67dc-46a7-baa2-bca51e462afb", "deviceid": "1000087794", "action": "register", "version": 2, "romVersion": "1.3.0", "model": "PSB-B04-GL", "ts": 530 }

2017-09-23 09:20:11,945 (INFO) We are dealing with a PSB-B04-GL model.
~~~~ register
{
"error": 0,
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"config": {
"hb": 1,
"hbInterval": 145
}
}
2017-09-23 09:20:11,954 (DEBUG) << WEBSOCKET INPUT
2017-09-23 09:20:11,955 (DEBUG) << {
"userAgent": "device",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"deviceid": "1000087794",
"action": "date"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ date
{
"error": 0,
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"date": "2017-09-23T09:20:11.955Z"
}
2017-09-23 09:20:11,963 (DEBUG) << WEBSOCKET INPUT
2017-09-23 09:20:11,964 (DEBUG) << {
"userAgent": "device",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"deviceid": "1000087794",
"action": "update",
"params": {
"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
}
],
"fwVersion": "1.3.0",
"rssi": -74
}
}
~~~ device sent action request,  acknowledging / answering...
~~~~ update
{
"error": 0,
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae"
}
{
"action": "update",
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"userAgent": "app",
"sequence": "1506151211964",
"ts": 0,
"params": {
"switch": "off"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"userAgent": "app",
"sequence": "1506151211964",
"ts": 0,
"params": {
"switch": "on"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"userAgent": "app",
"sequence": "1506151211964",
"ts": 0,
"params": {
"switch": "off"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"userAgent": "app",
"sequence": "1506151211965",
"ts": 0,
"params": {
"switch": "on"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"userAgent": "app",
"sequence": "1506151211965",
"ts": 0,
"params": {
"switch": "off"
},
"from": "hackepeter"
}
{
"action": "upgrade",
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"userAgent": "app",
"sequence": "1506151211968",
"ts": 0,
"params": {
"binList": [
{
"downloadUrl": "http://10.0.1.3:8080/ota/image_user1-0x01000.bin",
"digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616",
"name": "user1.bin"
},
{
"downloadUrl": "http://10.0.1.3:8080/ota/image_user2-0x81000.bin",
"digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc",
"name": "user2.bin"
}
],
"model": "PSB-B04-GL",
"version": "23.42.5"
}
}
2017-09-23 09:20:11,971 (DEBUG) << WEBSOCKET INPUT
2017-09-23 09:20:11,971 (DEBUG) << {
"userAgent": "device",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"deviceid": "1000087794",
"action": "query",
"params": [
"timers"
]
}
~~~ device sent action request,  acknowledging / answering...
~~~~ query
{
"error": 0,
"deviceid": "1000087794",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"params": 0
}
2017-09-23 09:20:12,012 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=1000087794&ts=812669700&sign=809e3fe6005d3ab1120719f5164ccab701611997f0ba4fe28985d50c6e8b00b3 (10.0.1.21) 15.57ms
2017-09-23 09:20:12,013 (DEBUG) << WEBSOCKET INPUT
2017-09-23 09:20:12,013 (DEBUG) << {
"error": 404,
"userAgent": "device",
"apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
"deviceid": "1000087794",
"sequence": "1506151211968"
}
2017-09-23 09:20:12,013 (DEBUG) ~~~ device acknowledged our action request (seq 1506151211968) with error code 404
.........

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. ..........

Same issue here - I think...

[AlessandroEmm]

the 404 is probably the interesting bit here, any way I can help?

It's a Sonoff Dual built on 15. of March.

I'm on a Mac with Py 3.6.2.

What I did:

• connect to my regular network
• run the sonota.py, give it the IP/Interface from my regular Network.
• Enter SSID and PW
• Connect to the ITead network
• Wait...
• Switch back to my regular network.
• Wait...
• Eventually this is the output (404) that i got.

[08-15at]

same here, Sonoff Dual, python 3.6.2 Mac, image_user2-0x81000.bin seems to get loaded, but then Final Stage never showing.

2017-09-23 14:21:51,817 (INFO) We are dealing with a PSB-B04-GL model.
~~~~ register
>> {
    "error": 0,
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "config": {
        "hb": 1,
        "hbInterval": 145
    }
}
2017-09-23 14:21:51,826 (DEBUG) << WEBSOCKET INPUT
2017-09-23 14:21:51,826 (DEBUG) << {
    "userAgent": "device",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "deviceid": "10000624d3",
    "action": "date"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ date
>> {
    "error": 0,
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "date": "2017-09-23T14:21:51.826Z"
}
2017-09-23 14:21:51,831 (DEBUG) << WEBSOCKET INPUT
2017-09-23 14:21:51,831 (DEBUG) << {
    "userAgent": "device",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "deviceid": "10000624d3",
    "action": "update",
    "params": {
        "switches": [
            {
                "switch": "off",
                "outlet": 0
            },
            {
                "switch": "off",
                "outlet": 1
            },
            {
                "switch": "off",
                "outlet": 2
            },
            {
                "switch": "off",
                "outlet": 3
            }
        ],
        "fwVersion": "1.1.0"
    }
}
~~~ device sent action request,  acknowledging / answering...
~~~~ update
>> {
    "error": 0,
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2"
}
>> {
    "action": "update",
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "userAgent": "app",
    "sequence": "1506169311832",
    "ts": 0,
    "params": {
        "switch": "off"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "userAgent": "app",
    "sequence": "1506169311832",
    "ts": 0,
    "params": {
        "switch": "on"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "userAgent": "app",
    "sequence": "1506169311833",
    "ts": 0,
    "params": {
        "switch": "off"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "userAgent": "app",
    "sequence": "1506169311833",
    "ts": 0,
    "params": {
        "switch": "on"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "userAgent": "app",
    "sequence": "1506169311834",
    "ts": 0,
    "params": {
        "switch": "off"
    },
    "from": "hackepeter"
}
>> {
    "action": "upgrade",
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "userAgent": "app",
    "sequence": "1506169311838",
    "ts": 0,
    "params": {
        "binList": [
            {
                "downloadUrl": "http://10.0.0.9:8080/ota/image_user1-0x01000.bin",
                "digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616",
                "name": "user1.bin"
            },
            {
                "downloadUrl": "http://10.0.0.9:8080/ota/image_user2-0x81000.bin",
                "digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc",
                "name": "user2.bin"
            }
        ],
        "model": "PSB-B04-GL",
        "version": "23.42.5"
    }
}
2017-09-23 14:21:51,844 (DEBUG) << WEBSOCKET INPUT
2017-09-23 14:21:51,844 (DEBUG) << {
    "userAgent": "device",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "deviceid": "10000624d3",
    "action": "query",
    "params": [
        "timers"
    ]
}
~~~ device sent action request,  acknowledging / answering...
~~~~ query
>> {
    "error": 0,
    "deviceid": "10000624d3",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "params": 0
}
2017-09-23 14:21:51,902 (DEBUG) << WEBSOCKET INPUT
2017-09-23 14:21:51,903 (DEBUG) << {
    "error": 404,
    "userAgent": "device",
    "apikey": "5fa9ee5b-d5f2-4421-b3fc-cd828d70c9e2",
    "deviceid": "10000624d3",
    "sequence": "1506169311838"
}
2017-09-23 14:21:51,907 (DEBUG) ~~~ device acknowledged our action request (seq 1506169311838) with error code 404
2017-09-23 14:21:51,908 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=10000624d3&ts=1681643301&sign=3bc9dac0bffcbdb7172ee5cc05df43477394aa355785f94197a047a9aaa056a6 (10.0.0.10) 32.67ms
........

*** 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.
..........
*** 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.

[donoo]

Hi ,

Tried multiple systems but sonoff never connects back. It connected couple of times but final stage ssid never showed up.

Not sure what's is wrong.

[sillyfrog]

Thanks for the above, comparing the above to what I have on a Dual with the same firmware, I do not have this request come through:

2017-09-23 09:20:11,971 (DEBUG) << {
    "userAgent": "device",
    "apikey": "f561d76b-d794-4dc2-b4d2-63455b6900ae",
    "deviceid": "1000087794",
    "action": "query",
    "params": [
        "timers"
    ]
}

So for some reason, yours is requesting an update to it's internal timers. To help narrow this down (and for others), did you ever set a timer in the EWeLink app before flashing?

As I have never seen this, I'm going to hazard a guess as to some possible fixes based on some of the other responses the App gives.

The first to try is applying the following diff (changing the 0 to an empty list []):

index 7d0295b..1108b91 100755
--- a/sonota.py
+++ b/sonota.py
@@ -171,7 +171,7 @@ class WebSocketHandler(tornado.websocket.WebSocketHandler):
                     "error": 0,
                     "deviceid": dct['deviceid'],
                     "apikey": self.uuid,
-                    "params": 0
+                    "params": []
                 }
                 print(">> %s" % json.dumps(data, indent=4))
                 self.write_message(data)

And then if that does not work, try an empty dict (object):

index 7d0295b..5f99d24 100755
--- a/sonota.py
+++ b/sonota.py
@@ -171,7 +171,7 @@ class WebSocketHandler(tornado.websocket.WebSocketHandler):
                     "error": 0,
                     "deviceid": dct['deviceid'],
                     "apikey": self.uuid,
-                    "params": 0
+                    "params": {}
                 }
                 print(">> %s" % json.dumps(data, indent=4))
                 self.write_message(data)

Let me know how you get on and I'll commit the update if one of the above works.

[AlessandroEmm]

@sillyfrog Nope i never set a timer - and i tested one Sonoff Dual that has been setup through the app and one that has never been touched before.

Will try your changes - thanks!

[AlessandroEmm]

I just tested it the behaviour didn't change much.

The only thing that happened to me this time was that after the 404 i had gotten this:

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. .......2017-09-24 09:50:58,771 (DEBUG) << WEBSOCKET INPUT 2017-09-24 09:50:58,772 (DEBUG) << { "userAgent": "device", "apikey": "2842912d-6ce5-470e-898b-ae1af8ae0558", "deviceid": "1000087893", "action": "update", "params": { "switches": [ { "switch": "off", "outlet": 0 }, { "switch": "off", "outlet": 1 }, { "switch": "off", "outlet": 2 }, { "switch": "off", "outlet": 3 } ], "fwVersion": "1.3.0", "rssi": -69 } }

~~~~ update
>> {
    "error": 0,
    "deviceid": "1000087893",
    "apikey": "2842912d-6ce5-470e-898b-ae1af8ae0558"
}
...

*** 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.
..........

[AlessandroEmm]

Btw - I noticed that line 171 is different on master branch - are you maybe working on some other branch? I had to change line 174 to implement your changes.

[AlessandroEmm]

And here the most recent Full output

`...<< HTTP POST /dispatch/device

/dispatch/device { "error": 0, "reason": "ok", "IP": "10.0.1.3", "port": 8443 } 2017-09-24 10:01:40,794 (INFO) 200 POST /dispatch/device (10.0.1.22) 1.47ms 2017-09-24 10:01:40,961 (INFO) 101 GET /api/ws (10.0.1.22) 0.47ms 2017-09-24 10:01:40,961 (DEBUG) << WEBSOCKET OPEN 2017-09-24 10:01:40,968 (DEBUG) << WEBSOCKET INPUT 2017-09-24 10:01:40,968 (DEBUG) << { "userAgent": "device", "apikey": "b6378a58-3421-4de5-87c8-5b69654d5912", "deviceid": "1000087893", "action": "register", "version": 2, "romVersion": "1.3.0", "model": "PSB-B04-GL", "ts": 530 }

2017-09-24 10:01:40,968 (INFO) We are dealing with a PSB-B04-GL model.
~~~~ register
{
"error": 0,
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"config": {
"hb": 1,
"hbInterval": 145
}
}
2017-09-24 10:01:40,975 (DEBUG) << WEBSOCKET INPUT
2017-09-24 10:01:40,975 (DEBUG) << {
"userAgent": "device",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"deviceid": "1000087893",
"action": "date"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ date
{
"error": 0,
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"date": "2017-09-24T10:01:40.975Z"
}
.2017-09-24 10:01:40,984 (DEBUG) << WEBSOCKET INPUT
2017-09-24 10:01:40,984 (DEBUG) << {
"userAgent": "device",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"deviceid": "1000087893",
"action": "update",
"params": {
"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
}
],
"fwVersion": "1.3.0",
"rssi": -73
}
}
~~~ device sent action request,  acknowledging / answering...
~~~~ update
{
"error": 0,
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22"
}
{
"action": "update",
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"userAgent": "app",
"sequence": "1506240100984",
"ts": 0,
"params": {
"switch": "off"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"userAgent": "app",
"sequence": "1506240100985",
"ts": 0,
"params": {
"switch": "on"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"userAgent": "app",
"sequence": "1506240100985",
"ts": 0,
"params": {
"switch": "off"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"userAgent": "app",
"sequence": "1506240100985",
"ts": 0,
"params": {
"switch": "on"
},
"from": "hackepeter"
}
{
"action": "update",
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"userAgent": "app",
"sequence": "1506240100985",
"ts": 0,
"params": {
"switch": "off"
},
"from": "hackepeter"
}
{
"action": "upgrade",
"deviceid": "1000087893",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"userAgent": "app",
"sequence": "1506240100987",
"ts": 0,
"params": {
"binList": [
{
"downloadUrl": "http://10.0.1.3:8080/ota/image_user1-0x01000.bin",
"digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616",
"name": "user1.bin"
},
{
"downloadUrl": "http://10.0.1.3:8080/ota/image_user2-0x81000.bin",
"digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc",
"name": "user2.bin"
}
],
"model": "PSB-B04-GL",
"version": "23.42.5"
}
}
2017-09-24 10:01:41,022 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=1000087893&ts=812669700&sign=53d52a3062e467e27f413aacda365d9228c929f4ad5918c0c2bdbf7f8157380b (10.0.1.22) 10.59ms
2017-09-24 10:01:41,025 (DEBUG) << WEBSOCKET INPUT
2017-09-24 10:01:41,025 (DEBUG) << {
"error": 404,
"userAgent": "device",
"apikey": "7d6b91b4-cb8e-4e98-bc9d-7432cc7d6f22",
"deviceid": "1000087893",
"sequence": "1506240100987"
}
`

[donoo]

Hi,

for me it seems device is not able to connect back. as per the comment in the code

# listening on HTTPS port to catch initial POST request to eu-disp.coolkit.cc
app_ssl.listen(DEFAULT_PORT_HTTPS)

I think this request is not picked up or there is delay or this request is send out too quickly by device.

Any thing I can change in code so that I can make it connect to do stage 2 stuff.

[donoo]

Hello , I was finally able to free my sonoff. I used Personal HotSpot to do this. Seems my Home Router was messing up something. Also , I changed params :[]. But I m not sure if this had any effect.

Here is the full log of my run:

`

D:\HomeAuto\SonOTA-master>python sonota.py Select IP address of the WiFi interface: 0: 192.168.137.254 Select IP address [0]: 0 WiFi SSID: MAD WiFi Password: XXXXXXX

Using the following configuration: Server IP Address: 192.168.137.254 WiFi SSID: MAD WiFi Password: XXXXXXX 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... .................~~ Connection attempt

HTTP GET /10.10.7.1/device timed out HTTP GET /10.10.7.1/device << { "apikey": "0311c7fd-dca4-46ed-8e61-19f5219455d8", "accept": "post", "deviceid": "10000cba99" } HTTP POST /10.10.7.1/ap %s { "password": "XXXXXXX", "port": 8443, "version": 4, "serverName": "192.168.137.254", "ssid": "MAD" } << { "error": 0 } ~~ Provisioning completed Starting stage2... The IP address of (192.168.137.254) is not assigned to any interface on this machine. Please change WiFi network to MAD and make sure 192.168.137.254 is being assigned to your WiFi interface. ** This application should be kept running and will wait until connected to the WiFi... ........~~ Starting web server (HTTP port: 8080, HTTPS port 8443) ~~ 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. << HTTP POST /dispatch/device

/dispatch/device { "error": 0, "reason": "ok", "port": 8443, "IP": "192.168.137.254" } 2017-09-24 16:09:15,614 (INFO) 200 POST /dispatch/device (192.168.137.66) 13.50ms 2017-09-24 16:09:16,066 (INFO) 101 GET /api/ws (192.168.137.66) 99.51ms 2017-09-24 16:09:16,066 (DEBUG) << WEBSOCKET OPEN 2017-09-24 16:09:16,167 (DEBUG) << WEBSOCKET INPUT 2017-09-24 16:09:16,167 (DEBUG) << { "userAgent": "device", "apikey": "0311c7fd-dca4-46ed-8e61-19f5219455d8", "ts": 654, "action": "register", "romVersion": "1.5.5", "deviceid": "10000cba99", "version": 2, "model": "ITA-GZ1-GL" }

2017-09-24 16:09:16,167 (INFO) We are dealing with a ITA-GZ1-GL model.
~~~~ register
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"error": 0,
"config": {
"hb": 1,
"hbInterval": 145
},
"deviceid": "10000cba99"
}
2017-09-24 16:09:16,199 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:16,204 (DEBUG) << {
"userAgent": "device",
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"action": "date",
"deviceid": "10000cba99"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ date
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"error": 0,
"date": "2017-09-24T16:09:16.204Z",
"deviceid": "10000cba99"
}
2017-09-24 16:09:16,220 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:16,220 (DEBUG) << {
"userAgent": "device",
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"action": "update",
"params": {
"startup": "off",
"switch": "on",
"rssi": -50,
"staMac": "2C:3A:E8:05:69:9A",
"fwVersion": "1.5.5"
},
"deviceid": "10000cba99"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ update
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"error": 0,
"deviceid": "10000cba99"
}
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249556220",
"from": "hackepeter",
"params": {
"switch": "off"
}
}
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249556236",
"from": "hackepeter",
"params": {
"switch": "on"
}
}
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249556236",
"from": "hackepeter",
"params": {
"switch": "off"
}
}
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249556251",
"from": "hackepeter",
"params": {
"switch": "on"
}
}
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249556251",
"from": "hackepeter",
"params": {
"switch": "off"
}
}
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"userAgent": "app",
"ts": 0,
"sequence": "1506249556282",
"deviceid": "10000cba99",
"action": "upgrade",
"params": {
"version": "24.42.5",
"model": "ITA-GZ1-GL",
"binList": [
{
"downloadUrl": "http://192.168.137.254:8080/ota/image_user1-0x01000.bin",
"name": "user1.bin",
"digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616"
},
{
"downloadUrl": "http://192.168.137.254:8080/ota/image_user2-0x81000.bin",
"name": "user2.bin",
"digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc"
}
]
}
}
.2017-09-24 16:09:16,888 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:16,888 (DEBUG) << {
"userAgent": "device",
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"action": "query",
"params": [
"timers"
],
"deviceid": "10000cba99"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ query
{
"apikey": "e3343a7b-b405-41e9-9d79-84751927291a",
"error": 0,
"params": [],
"deviceid": "10000cba99"
}
2017-09-24 16:09:17,846 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=134707445&sign=8be0c50a374c10dadb70e0999a12d93d433210f95e42ab82f46ff94b620c0a81 (192.168.137.66) 656.94ms
...<< HTTP POST /dispatch/device
/dispatch/device
{
"error": 0,
"reason": "ok",
"port": 8443,
"IP": "192.168.137.254"
}
2017-09-24 16:09:23,966 (INFO) 200 POST /dispatch/device (192.168.137.66) 15.64ms
2017-09-24 16:09:24,182 (INFO) 101 GET /api/ws (192.168.137.66) 0.00ms
2017-09-24 16:09:24,182 (DEBUG) << WEBSOCKET OPEN
2017-09-24 16:09:24,198 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:24,198 (DEBUG) << {
"userAgent": "device",
"apikey": "0311c7fd-dca4-46ed-8e61-19f5219455d8",
"ts": 744,
"action": "register",
"romVersion": "1.5.5",
"deviceid": "10000cba99",
"version": 2,
"model": "ITA-GZ1-GL"
}
~~~ device sent action request,  acknowledging / answering...
2017-09-24 16:09:24,198 (INFO) We are dealing with a ITA-GZ1-GL model.
~~~~ register
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"error": 0,
"config": {
"hb": 1,
"hbInterval": 145
},
"deviceid": "10000cba99"
}
2017-09-24 16:09:24,229 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:24,229 (DEBUG) << {
"userAgent": "device",
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"action": "date",
"deviceid": "10000cba99"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ date
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"error": 0,
"date": "2017-09-24T16:09:24.246Z",
"deviceid": "10000cba99"
}
2017-09-24 16:09:24,270 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:24,271 (DEBUG) << {
"userAgent": "device",
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"action": "update",
"params": {
"startup": "off",
"switch": "off",
"rssi": -53,
"staMac": "2C:3A:E8:05:69:9A",
"fwVersion": "1.5.5"
},
"deviceid": "10000cba99"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ update
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"error": 0,
"deviceid": "10000cba99"
}
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249564281",
"from": "hackepeter",
"params": {
"switch": "off"
}
}
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249564285",
"from": "hackepeter",
"params": {
"switch": "on"
}
}
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249564287",
"from": "hackepeter",
"params": {
"switch": "off"
}
}
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249564290",
"from": "hackepeter",
"params": {
"switch": "on"
}
}
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"userAgent": "app",
"ts": 0,
"action": "update",
"deviceid": "10000cba99",
"sequence": "1506249564302",
"from": "hackepeter",
"params": {
"switch": "off"
}
}
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"userAgent": "app",
"ts": 0,
"sequence": "1506249564308",
"deviceid": "10000cba99",
"action": "upgrade",
"params": {
"version": "24.42.5",
"model": "ITA-GZ1-GL",
"binList": [
{
"downloadUrl": "http://192.168.137.254:8080/ota/image_user1-0x01000.bin",
"name": "user1.bin",
"digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616"
},
{
"downloadUrl": "http://192.168.137.254:8080/ota/image_user2-0x81000.bin",
"name": "user2.bin",
"digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc"
}
]
}
}
2017-09-24 16:09:24,310 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:24,311 (DEBUG) << {
"userAgent": "device",
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"action": "query",
"params": [
"timers"
],
"deviceid": "10000cba99"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ query
{
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"error": 0,
"params": [],
"deviceid": "10000cba99"
}
2017-09-24 16:09:24,854 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1270216262&sign=7fdfa137fbeeb5468a8752f41c97a4b6d8315464d1f1d08ac7421dfb139b40d7 (192.168.137.66) 0.00ms
.2017-09-24 16:09:24,970 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1191391529&sign=a90472ed052e834192bc10ebacc26b6330da4e1166c06ffa9a9bc69e3a27520e (192.168.137.66) 0.00ms
2017-09-24 16:09:25,101 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=812669700&sign=283e322011d92ed781c184a23a91d6f92db13394735ba4a6f53e0ac5e7995095 (192.168.137.66) 15.46ms
2017-09-24 16:09:25,170 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=553475508&sign=f2788dca0dfa8eccb477f84a835d603e54cd5d4da3fd1b58e868265eae89297e (192.168.137.66) 0.00ms
2017-09-24 16:09:25,254 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=445349752&sign=839a4c5ca1ceef9cae1c4f166dcde099e3d7c97cc359c45f328de023f155753f (192.168.137.66) 15.45ms
2017-09-24 16:09:25,339 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1344887256&sign=1cf6d472244b08d0b74dec5294d1da258502bfd4151b2aec82c0c75dbd35148c (192.168.137.66) 0.00ms
2017-09-24 16:09:25,439 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=730417256&sign=0bc396187a3fb3ede475fdecc841a471a8ae171da5cb380cf1f5b64dfdff2b30 (192.168.137.66) 0.00ms
2017-09-24 16:09:25,523 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1812158119&sign=0b7d30c15d2fb114b20bf6183346a4377582813c8f98024a702993450ebbe722 (192.168.137.66) 0.00ms
2017-09-24 16:09:25,601 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=147699711&sign=dd3c1dce58740cde1eadbb0f62f15f6b2720bc53c9453fc50635284f7663b021 (192.168.137.66) 0.00ms
2017-09-24 16:09:25,723 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=880268351&sign=957876c77ab50f36c9b1a3ab91188cd796ffb80d6e45d30531d90e4d8ee16be3 (192.168.137.66) 0.00ms
2017-09-24 16:09:25,823 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1889772843&sign=8575936d30d14a9448c79092b782d753ab91f96d6b1182f48f7fc585a98f42b4 (192.168.137.66) 0.00ms
2017-09-24 16:09:25,902 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=686078705&sign=5672b751836aa0cea55cd00b68ba1313febe06c56866bbc877841a3d396971af (192.168.137.66) 0.00ms
2017-09-24 16:09:25,970 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=2105754108&sign=1fa6870285c86f663cb6115419b5c1d653eba6a34573ed0df2e8433ce1fac922 (192.168.137.66) 0.00ms
2017-09-24 16:09:26,071 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=182546393&sign=fc693d7d4ff817509b7bbb6e430abed54d78b43d0fec382f78df7596d913f556 (192.168.137.66) 0.00ms
2017-09-24 16:09:26,186 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1949118330&sign=3159ba987dfd0e7eaf38e6248eb045dd846c319e46a7b9d81503081e7576a9bc (192.168.137.66) 0.00ms
2017-09-24 16:09:26,271 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=220137366&sign=8161d9e808244cb01a66d8561cd329244bf55efff8780d9da61f8c7f92de1f09 (192.168.137.66) 0.00ms
2017-09-24 16:09:26,340 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1979932169&sign=5180fd24a9693fc53e0cfd5be251ada3d5207cb78091f911c4478ba36d431073 (192.168.137.66) 0.00ms
2017-09-24 16:09:26,455 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1089957932&sign=567564ba5aae9c5d4e4f21531d4269843915037b17b8d45baf34464ed937cfea (192.168.137.66) 0.00ms
2017-09-24 16:09:26,571 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1873226917&sign=12cc25ac95af4434fd16839d63d7c6fa29d39bb5920da0b9fc5da5575b1492d8 (192.168.137.66) 0.00ms
2017-09-24 16:09:26,640 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=715669847&sign=a5386aac75bf8b289383a0713f488127071f8696ea01619cfb93f3d940aaf08d (192.168.137.66) 0.00ms
2017-09-24 16:09:26,702 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1486937972&sign=3c1c824a2e90c43c5a605b2cad0a7ba772bfa64ebbb7ef22fc044655f2dac7a0 (192.168.137.66) 0.00ms
2017-09-24 16:09:26,820 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1196032868&sign=2e867f33104309b209aae2da4ac7d873c5fe07f1be16e880f788f1ca68473ddf (192.168.137.66) 2.01ms
2017-09-24 16:09:26,923 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=777206980&sign=7cdaf945aa1f82b10316cbf80a700aaa1d54e38a478f4eccda35b0e9054ee68d (192.168.137.66) 2.00ms
.2017-09-24 16:09:26,987 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=68706223&sign=eac1fcac324b19507ed586aeb39a45fe615033c60ae3d27a40b8d64bcea59311 (192.168.137.66) 0.00ms
2017-09-24 16:09:27,055 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1843638549&sign=42f0e625ff4f9bdc264d84eb538936dbf6d47a89488babafe7c9f1554bd0d695 (192.168.137.66) 0.00ms
2017-09-24 16:09:27,155 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=212567592&sign=f2b47369d825c79e0357f990846f9e078adc87730fad270c7ff2cfe3890def7b (192.168.137.66) 0.00ms
2017-09-24 16:09:27,255 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1883488164&sign=4fa82c25d36ef27c25bc043a0bcbcf493b0d709da426a9e38cc4ec39b44b956b (192.168.137.66) 0.00ms
2017-09-24 16:09:27,340 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=964776169&sign=bc3c508d9f5e2c532bdeec1aad0c39bf5e66b18b82e8db6d7796da171021cd94 (192.168.137.66) 0.00ms
2017-09-24 16:09:27,404 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=928126551&sign=cd913d4d9764a2268b47bc2ddef6137d19328ca06c6333a9177a2ac8e01ff249 (192.168.137.66) 0.00ms
2017-09-24 16:09:27,522 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1301950427&sign=940049fd638091e889ea37ab38ba6287b3b435793f4ad74eefc86960387a4234 (192.168.137.66) 1.99ms
2017-09-24 16:09:27,620 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1992516190&sign=4f32d62b3b546d52881b1fe267c97188db760bbe42523b00f97a2bf3fbef01bd (192.168.137.66) 17.08ms
2017-09-24 16:09:27,688 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1426542624&sign=1e2c0d4709212843b04b22dc3aca2ec0e98cb2d97cbc04a321993f42c6f051e6 (192.168.137.66) 0.00ms
2017-09-24 16:09:27,756 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=849040635&sign=df10dcbe7b34b5a89dfa3df3a0dcaeca4838fd9c9fdbae1ed2b376feaff9ab2f (192.168.137.66) 0.00ms
2017-09-24 16:09:27,872 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=941604920&sign=0adf15a8fd25d1a2528b88fa0112ac24df352d0bd977b1b4c2871e5b5c13162b (192.168.137.66) 15.45ms
2017-09-24 16:09:27,972 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1400427944&sign=1c743298f05e13d450549b54910b892b507bbebf44b417580c1566e58e532b1e (192.168.137.66) 0.00ms
2017-09-24 16:09:28,056 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1994719310&sign=55a7754129aaeca2f46a1f7cf52349ab4d8941c2f5195f198d553b73b6607712 (192.168.137.66) 15.62ms
2017-09-24 16:09:28,123 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=2038269862&sign=aacdc271aaf96ca142e12ceaed63c06efe55effb56b5b1cf5ecd0d8fc03aecba (192.168.137.66) 1.99ms
2017-09-24 16:09:28,225 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=659998484&sign=0d5f44d1f19c9ec6ffb1a9eeb88d3d9085f9d1e99bc249044717cd57e4035c8a (192.168.137.66) 0.00ms
2017-09-24 16:09:28,325 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1280937363&sign=e525ad414e3c5beebb1e11a4741c9cd27c1132b92348fe17cb0b7c10f262d846 (192.168.137.66) 0.00ms
2017-09-24 16:09:28,541 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1681643301&sign=3a26fd9db5141e686cccfa02de3a97362ac9bb9e3d94ae1488617bfc094af400 (192.168.137.66) 0.00ms
2017-09-24 16:09:28,656 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=725914710&sign=3e125381e16f166efd836c384b22f4988e8b55bd1534386aa51db818af489b7e (192.168.137.66) 0.00ms
2017-09-24 16:09:28,741 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1729267236&sign=8ae351087f662cde23ffb65d647d895747138d61722620d2d616a4ca8961b6a6 (192.168.137.66) 0.00ms
2017-09-24 16:09:28,803 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=2023351876&sign=d1c6c2e72f939dd7d936bdeb4d1a7e600dc5284c2df906fc844400b18ad11406 (192.168.137.66) 0.00ms
2017-09-24 16:09:28,903 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=142750431&sign=6461a728263d8b00929d8c88ede3717b16030a19405814660877fb9f385610f3 (192.168.137.66) 0.00ms
.2017-09-24 16:09:29,022 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1840579929&sign=f239f04564494a6572b621113f9dcd1fefc238f27b5396b1bcef4d5bcf86fda4 (192.168.137.66) 2.00ms
2017-09-24 16:09:29,104 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=2098560397&sign=c52a14cb42146b4795bf936dcfe6e2f304ddcc3a5891800629bd8fc490cd84aa (192.168.137.66) 0.00ms
2017-09-24 16:09:29,188 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1910500675&sign=26bfe8b2c9d0660df9dfc5949c13049b222dca4f55627030ef479884c772c2fb (192.168.137.66) 0.00ms
2017-09-24 16:09:29,288 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1170970491&sign=0b43b7cfe3660bc0d5c4aeca584976d3edb5c8a82dbc4a0f08b121ed0cb678d4 (192.168.137.66) 0.00ms
2017-09-24 16:09:29,389 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1856224190&sign=f561fb82d11667fb51a55050b0eef7d208a81e4c5fc98db89c1f80c4bc464790 (192.168.137.66) 0.00ms
2017-09-24 16:09:29,488 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=983059344&sign=39910ea1e10bd819fe50a32995d639bc82e16c7eab9da343d3a19fabdf23bf04 (192.168.137.66) 0.00ms
2017-09-24 16:09:29,572 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1718458134&sign=ec036dccdb8898c47619dd3d44b47c72d7d395a761900c68510e94bc2b9a955c (192.168.137.66) 0.00ms
2017-09-24 16:09:29,672 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1876268425&sign=017ce7d941de086ed86fc5c8dad7581c422d93b6328dc9805dd46c096a82d31e (192.168.137.66) 0.00ms
2017-09-24 16:09:29,772 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1764841629&sign=3edfa10c9aa231165b3752884c0915f9ecb621dce43e46438de02fab3b554fb5 (192.168.137.66) 0.00ms
2017-09-24 16:09:29,888 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=398844030&sign=5fa85abbf3e7dd51ec587595af7b7737543ec07cd4e416f8094a970081f8171e (192.168.137.66) 0.00ms
2017-09-24 16:09:29,972 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=185252727&sign=a0b40c23652d5dec8f81aeaab65d15efadc3c112c717e275d93e310b80b98f5e (192.168.137.66) 15.45ms
2017-09-24 16:09:30,056 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=1370429126&sign=65c770402352be00f6ad296bd61e6977b8457166c7b857e2f7cbb8d3121ff62d (192.168.137.66) 0.00ms
2017-09-24 16:09:30,172 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=502141743&sign=ee7fbb5261be59cc8bf009c8ce1c2ba00faa9c0bfa26a5cae9c50bb9d1b8db46 (192.168.137.66) 0.00ms
2017-09-24 16:09:30,272 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=993687334&sign=97fb731700cd8c69053135bf4886ff6f6fcc71cac41fbf68c0b2a7dc7de47bec (192.168.137.66) 0.00ms
2017-09-24 16:09:30,373 (INFO) 206 GET /ota/image_user2-0x81000.bin?deviceid=10000cba99&ts=15934104&sign=5d8038fa3b8fd5d16c9b8d3a78fd200f99171b49a668f1fedaa8c36602b75a2c (192.168.137.66) 0.00ms
2017-09-24 16:09:30,688 (DEBUG) << WEBSOCKET INPUT
2017-09-24 16:09:30,688 (DEBUG) << {
"userAgent": "device",
"error": 0,
"sequence": "1506249564308",
"apikey": "20129ede-500d-4e10-97e1-cd4b1d21f468",
"deviceid": "10000cba99"
}
2017-09-24 16:09:30,688 (DEBUG) ~~~ device acknowledged our action request (seq 1506249564308) with error code 0
...

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. ..........

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. ........2017-09-24 16:10:12,807 (DEBUG) ~~ websocket close 2017-09-24 16:10:12,827 (DEBUG) ~~ websocket close .

The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed Once "FinalStage" has gone away, you can stop this program 2017-09-24 16:10:33,763 (INFO) 200 GET /ota/image_arduino.bin (192.168.4.1) 20500.15ms

The "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed Once "FinalStage" has gone away, you can stop this program No longer on "FinalStage" SSID, all done!

`

[kryten01]

Hi all. Getting the same 404 error on the second image here on an S20 straight out of the box:

2017-09-24 22:26:33,400 (DEBUG) << WEBSOCKET INPUT
2017-09-24 22:26:33,401 (DEBUG) << {
    "error": 404,
    "userAgent": "device",
    "apikey": "55315186-1e9c-4ef1-83b9-253c5041bedc",
    "deviceid": "10000a6814",
    "sequence": "1506255992591"
}
2017-09-24 22:26:33,402 (DEBUG) ~~~ device acknowledged our action request (seq 1506255992591) with error code 404

Tried the personal hotspot trick above but it didn't work for me - still got the same 404 error. Sonota.py is definitely serving this image ok as I was able to d/l it from a browser, so not sure why the 404 response. Will check I've got the latest commit and try the params tweak shortly.

[donoo]

@sillyfrog will this work for Sonoff RF Bridge 433 too? I m going to try this next. And thanks for this amazing tool.

[kryten01]

The params tweaks didn't work for me either, but interestingly a wireshark packet capture shows that the image seems to be downloaded correctly:

Host: dl.itead.cn
User-Agent: itead-device

HTTP/1.1 200 OK
Server: TornadoServer/4.5.2
Content-Type: application/octet-stream
Date: Sun, 24 Sep 2017 14:50:22 GMT
Accept-Ranges: bytes
Etag: "765cd97234173d90f52449c3791f5b2a"
Last-Modified: Sun, 24 Sep 2017 13:40:57 GMT
Content-Length: 238672

<followed by binary data>

Oddly, the http response appears when you follow the tcp stream in wireshark, but not the http stream. In a normal transaction the response will be visible in the http stream. I guess this means that the response is being sent, but it isn't recognised as completely compliant http. There are a couple of TCP window full ACK packets from port 8080 on the server back to the Sonoff 20. Not sure if that is an issue. Also not surprisingly when you view the raw data there are some 404 strings in what should be the http response section - which could explain the bogus 404 response (?).

Digging a bit deeper I also found this - note that this is normal port 80 http not port 8080. I did not see any port 80 attempts from the Sonoff S20 though:

[Full request URI: http://dl.itead.cn/ota/image_user2-0x81000.bin?deviceid=10000a6814&ts=1185694319&sign=a21058d4ade0f8c2f831234f8cb76aa58048b152d258d8712002b98fc5327acb]

[AlessandroEmm]

@donoo Am I assuming right that you arent using a Sonoff Dual?

[donoo]

@AlessandroEmm No, I did successful run on sonoff basic ,version 1.5.5

[AlessandroEmm]

Then, I guess, we have the difference, the duals are behaving differently.

[kryten01]

Tried replacing tornado.web.StaticFileHandler with the otherwise unused OTAUpdate function to get more debug output.

Note the following:

tornado.httputil.HTTPOutputError: Tried to write 42064 bytes less than Content-Length 2017-09-25 22:19:15,675 (ERROR) Cannot send error response after headers written

That figure of 42064 bytes less than the Content-Length header value seems to be consistent.

Content-Length: 238672 - 42064 = 196608 bytes sent before the HTTP output error.

.<< HTTP GET /ota/image_user2-0x81000.bin
>> image_user2-0x81000.bin
2017-09-25 22:19:15,474 (ERROR) Uncaught exception GET /ota/image_user2-0x81000.bin?deviceid=10000a6814&ts=1270216262&sign=166445a4337b71259bda59abd729a615baa5c28859d8f4e3e7f2ace4f7dd50ed (10.2.2.198)
HTTPServerRequest(protocol='http', host='dl.itead.cn', method='GET', uri='/ota/image_user2-0x81000.bin?deviceid=10000a6814&ts=1270216262&sign=166445a4337b71259bda59abd729a615baa5c28859d8f4e3e7f2ace4f7dd50ed', version='HTTP/1.1', remote_ip='10.2.2.198', headers={'Host': 'dl.itead.cn', 'User-Agent': 'itead-device'})
Traceback (most recent call last):
  File "C:\Users\Peter\AppData\Roaming\Python\Python36\site-packages\tornado\web.py", line 1513, in _execute
    self.finish()
  File "C:\Users\Peter\AppData\Roaming\Python\Python36\site-packages\tornado\web.py", line 992, in finish
    self.request.finish()
  File "C:\Users\Peter\AppData\Roaming\Python\Python36\site-packages\tornado\httputil.py", line 419, in finish
    self.connection.finish()
  File "C:\Users\Peter\AppData\Roaming\Python\Python36\site-packages\tornado\http1connection.py", line 448, in finish
    self._expected_content_remaining)
tornado.httputil.HTTPOutputError: Tried to write 42064 bytes less than Content-Length
2017-09-25 22:19:15,675 (ERROR) Cannot send error response after headers written
2017-09-25 22:19:15,675 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=10000a6814&ts=1270216262&sign=166445a4337b71259bda59abd729a615baa5c28859d8f4e3e7f2ace4f7dd50ed (10.2.2.198) 394.02ms
2017-09-25 22:19:15,677 (DEBUG) ~~ websocket close
2017-09-25 22:19:15,677 (DEBUG) << WEBSOCKET INPUT
2017-09-25 22:19:15,677 (DEBUG) << {
    "error": 404,
    "userAgent": "device",
    "apikey": "4642239f-04c6-4f19-8d75-82c1a77c7a62",
    "deviceid": "10000a6814",
    "sequence": "1506341954699"
}
2017-09-25 22:19:15,678 (DEBUG) ~~~ device acknowledged our action request (seq 1506341954699) with error code 404

[08-15at]

@kryton good point, 196608 = 192KBytes, so maybe some buffer size/limit issue ?

[kryten01]

@08-15at could be something like that.

I managed to get past that stage by running sonota.py on a raspberry pi with USB wireless. So if anyone is having this 404 / http output error problem and you are running on windows, try using Linux instead.

I have a different issue now - something screwed up at the final stage and sonota.py quit before completing the final d/l. I connected but didn't get an IP address. Now the S20 is stuck in finalstage mode and I have another challenge..

[AlessandroEmm]

@kryten01 did you try to set the IP manually?

[sillyfrog]

@kryten01 : If you are getting the FinalStage SSID coming up, then I'm 99% sure the flash is fine. If you run it with --no-prov --no-check-ip, that should allow it to go to stage3, so when you connect to the FinalStage SSID, things should just work (it can take a minute or two - assuming you do get an IP address, again, this can take a while). I have not tested this, but a quick manual inspection suggests it should be OK.

And that tornado.httputil.HTTPOutputError: Tried to write 42064 bytes less than Content-Length error is weird as I would have thought that error would come up either way and be visible in the output (I don't think it's catching any errors from tornado, but it could make sense as I have flashed the Duals with same firmware without issue, but from a Mac).

[kryten01]

@AlessandroEmm I had settings for each of the wireless SSIDs in wpa_supplicant.conf ready to go and just switched between them with wpa_cli select_network x. For some reason I didn't connect properly to FinalStage the first time and by the time I discovered this and stuffed around trying to fix it, sonota.py had quit.

@sillyfrog -Thanks I tried the --no-prov --no-check-ip args but no luck. It looks like the S20 is just dropping off the network in the middle of trying to d/l the last image. 192.168.4.1 disappears from my arp table. I don't have time tonight, but in the next few days I will grab a packet capture and try to work out what's going on. I'll start another thread for this issue rather than hijack this thread.

The HTTP output / 404 error resulting in not getting to FinalStage I'm attributing to winfail in my case. There's a fair chance that others may have the same problem running python on windows too.

[08-15at]

@kryton01, @sillyfrog I got he 404 error on OS X, so doesn't seem to be an Windows only issue. Haven't tested with using StaticFileHandler to see if I get the same last chunk error, yet.

@sillyfrog btw. just noticed, that the device should switch relay before going to upgrade. Should this happen on he dual as well, as I can't see which relay it should switch? Switching never happened here, so I tried to remove the relay switching altogether (or modifying it adding outlet number) but no changes. Did put a sleep before the upgrade command, the timer request comes right after the upgrade command, Tried 0, [], or {} params. Can this be causing some harm regarding the sequence numbers? thanks

2017-09-26 17:27:30,170 (DEBUG) self_setup and self_test done now sleeping ..2017-09-26 17:27:35,174 (DEBUG) sleeping done

{ "action": "upgrade", "deviceid": "10000624d3", "apikey": "21ca1fd0-7094-4fee-bc5c-307a7e876c92", "userAgent": "app", "sequence": "1506439655187", "ts": 0, "params": { "binList": [ { "downloadUrl": "http://10.0.0.9:8080/ota/image_user1-0x01000.bin", "digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616", "name": "user1.bin" }, { "downloadUrl": "http://10.0.0.9:8080/ota/image_user2-0x81000.bin", "digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc", "name": "user2.bin" } ], "model": "PSB-B04-GL", "version": "23.42.5" } } 2017-09-26 17:27:35,189 (DEBUG) << WEBSOCKET INPUT 2017-09-26 17:27:35,189 (DEBUG) << { "userAgent": "device", "apikey": "21ca1fd0-7094-4fee-bc5c-307a7e876c92", "deviceid": "10000624d3", "action": "query", "params": [ "timers" ] }

~~~~ query
{
"error": 0,
"deviceid": "10000624d3",
"apikey": "21ca1fd0-7094-4fee-bc5c-307a7e876c92",
"params": {}
}
2017-09-26 17:27:35,327 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=10000624d3&ts=155562330&sign=2e53add2a5bc8751fc82efe94ed33837534cd870ce2a463c4edd6a96453a41bc (10.0.0.3) 31.19ms
2017-09-26 17:27:35,328 (DEBUG) << WEBSOCKET INPUT
2017-09-26 17:27:35,328 (DEBUG) << {
"error": 404,
"userAgent": "device",
"apikey": "21ca1fd0-7094-4fee-bc5c-307a7e876c92",
"deviceid": "10000624d3",
"sequence": "1506439655187"
}
2017-09-26 17:27:35,329 (DEBUG) ~~~ device acknowledged our action request (seq 1506439655187) with error code 404
.......

[AlessandroEmm]

I tested it and i get the same error (on OS X). I briefly looked into tornados staticfileserving code, but nothing looked like it was specific to the OS as far as i can tell.

[LarsNorgaard]

For me the FinalStage SSID is set to public when I connect to it. Changing it to a private network under properties allows me to flash the finalstage bin.

[kryten01]

Keeping this in the same thread because failures when downloading the finalstage image seems to have the same underlying problem.

Using the OTAUpdate function again, I get this output when running the final stage:

he "FinalStage" SSID will disappear when the device has been fully flashed and image_arduino.bin has been installed
Once "FinalStage" has gone away, you can stop this program
<< HTTP GET /ota/image_arduino.bin
>> image_arduino.bin
2017-09-27 12:08:21,113 (ERROR) Uncaught exception GET /ota/image_arduino.bin (192.168.4.1)
HTTPServerRequest(protocol='http', host='192.168.4.2:8080', method='GET', uri='/ota/image_arduino.bin', version='HTTP/1.0', remote_ip='192.168.4.1', headers={'Host': '192.168.4.2:8080', 'Connection': 'close', 'User-Agent': 'ESP8266HTTPClient'})
Traceback (most recent call last):
  File "/root/.local/lib/python3.5/site-packages/tornado/web.py", line 1513, in _execute
    self.finish()
  File "/root/.local/lib/python3.5/site-packages/tornado/web.py", line 992, in finish
    self.request.finish()
  File "/root/.local/lib/python3.5/site-packages/tornado/httputil.py", line 419, in finish
    self.connection.finish()
  File "/root/.local/lib/python3.5/site-packages/tornado/http1connection.py", line 448, in finish
    self._expected_content_remaining)
tornado.httputil.HTTPOutputError: Tried to write 420224 bytes less than Content-Length
2017-09-27 12:08:21,301 (ERROR) Cannot send error response after headers written
2017-09-27 12:08:21,324 (INFO) 200 GET /ota/image_arduino.bin (192.168.4.1) 1447.14ms

Capturing this with tcpdump and replaying in wireshark:

ET /ota/image_arduino.bin HTTP/1.0
Host: 192.168.4.2:8080
User-Agent: ESP8266HTTPClient
Connection: close

HTTP/1.1 200 OK
Date: Wed, 27 Sep 2017 12:11:05 GMT
Last-Modified: Sun, 24 Sep 2017 04:25:59 GMT
Content-Type: application/octet-stream
Accept-Ranges: bytes
Etag: "50665408ec274b6f73eb70ca762bdd55"
Content-Length: 485760
Server: TornadoServer/4.5.2

... ...@...@h.......P..@.K.@.$.@...?...@...@..._...?.......@.J.@LJ.@...`.....+.@.0.@./.@.......`....|..`... .....)O8O!..*#K?.D.......R.......!..).(.(.)/(.(.)?8../................0
<snip>

Content length: = 485760 485760 - 420224 = 65536 = 64K

So tornado appears to be sending 64K and then dies with the http output error. As @08-15at mentioned above, this looks like some sort of buffer or size limit issue again. It is also interesting to note that class HTTP1ConnectionParameters(object) in http1connection.py sets the following default parameter: self.chunk_size = chunk_size or 65536

The image_arduino.bin file is only 476KB. Is there any reason why we couldn't just set the chunk size to something like 512K so it can read the whole thing into memory in one go?

[08-15at]

@kryton01 can't imagine that a 512K chunk size could work with the esp

Right now I am considering, if it may have to do something with wrong formats/checksums or timeouts. In my case it looks like the device somehow does reset after getting upgrade command and then just asks for timer. Similar in your case, it just stops reading after first chunk.

Maybe I'm way off with my speculation as I haven't looked into the whole OTA thing deep enough: However there have been some changes in the Sonoff lately regarding normal flash procedure. It has to do with changing Upload Mode from DIO to DOUT, see here: https://tech.scargill.net/a-flashing-esp-chips-surprise/ Have tried compiling normal Tasmota image changing these options. In that case also the .bin file changes on more locations than simple built date as this needs to know how to read the flash. No idea if building the binaries 1 and 2 and the arduino.bin would also be affected by that option ? As said before, this may have nothing to do with OTA, so I could be terribly wrong with this idea.

[khcnz]

DOUT does work - you can compile Espressif2Arduino and/or tasmota with DOUT.

If something is failing with the flash, you need to get the serial output from the device, E2A prints a lot of debug information to the console while trying to flash. I don't think changing the chunk size will make a difference, the file is buffered into 1024byte chunks.

[sillyfrog]

I’m away for a little bit, but have realized that I have not pushed the actual .ino files I built (there are the ones referenced in the readme), I’ll do this when I can for reference. To triple check, this is on more than just Windows? I have done a number of different devices (from Mac) and not seen this, trying to figure out a common thread.

[08-15at]

@sillyfrog, happens on Mac OS X 10.x with python 3.6.2, too. Have tried with different routers including above mentioned personal hotspot method. I've been using the binaries from your repository, didn't built them myself. Don't hurry, as I've flashed quite some units using the HW-method, just found this a much nicer way and would really like to use it in the future.

[sillyfrog]

I have now committed my changes to Espressif2Arduino for those that wanted to mess with it and put up a readme at: https://github.com/mirko/SonOTA/tree/master/static

I think this is everything that you should need to rebuild the binary files - I wish I knew what has happening as well as so far I have done Basics, Duals and the TH's without issue. I'm open to PR's and happy to throw around any ideas people may have.

The only other thought I have had is some sort of AntiVirus software or firewall dropping the connection early. Looking at the Tornado code it'll do this if the connection is closed - so (my guess) is something is closing the connection for what ever reason.

@ kryten01 If you have saved that tcpdump I could also take a look, or if you can post the full output including the TCP section as I would be keen to see if there was a FIN or RST coming from the Sonoff forcing it to close early.

[AlessandroEmm]

@sillyfrog

I'm running into this on my mac that I develop on, so daily HTTP Servers running without a hitch. The only thing I could think of being a little different is that I'm using High Sierra already, is someone else doing that as well. What about you @sillyfrog ?

In other news I tried to flash from an old Ubuntu Machine, but I can't even connect to the ITEAD Network for whatever reason - is there a trick to this?

[sillyfrog]

@AlessandroEmm I'm on OS X 10.12.6, Python 3.5.2 is what I have been running for the updates.

I have had it take a while from several devices connecting to the ITEAD, but it always eventually got there (should be nothing special aside from the default password).

[andyfitter]

I'm on High Sierra 10.13 and Python 3.6.2 and seeing similar problems with a Sonoff Dual. This is the only host platform I've tried so far though. Might give it a go on a Pi later and report back.

[iMarkus]

I tested it using Mac OS High Sierra and Python 3.5.2. After upgrading to Python 3.6.2 everything worked fine.

[kryten01]

@sillyfrog I've attached the relevant TCP stream in a zipped .pcap file here: packet-capture.zip

No FIN or RST from the sonoff. It just disappears off the network and eventually I see some ARP broadcasts from the pi looking for 192.161.4.1.

I also tried serving /ota/image_arduino.bin from apache and got exactly the same result.

[AlessandroEmm]

I have given up for now and made use of my soldering iron.

@iMarkus i've been on 3.6.2 all the time.

@kryten01 it's interesting that you made it past the first 404 sounds like a timing issue, race-condition...

[czyz]

I'm on OS X 10.12.5, running a copy of SonOTA-master downloaded as a zip today, and running it using Python 3.6.2 (also downloaded and installed today). I'm running into the same issue with the FinalStage SSID never showing up. The 404 error that appears in the debug output and is described by others above looks like a possible culprit. I've attached the debug output below just in case it's of use.

I've tried the process many times now, with and without '--legacy', and with and without running the script as sudo root (figured it was worth a try). The outcome is always the same.

test-upload-sonota.txt

[andyfitter]

I've now tried both on a 'normal' wifi network and also setting my Mac up as an AP via Wifi Internet sharing. Also tried both a Sonoff Dual and two UK Sonoff T1's. All give me the same result, the above mentioned '404'. Mac High Sierra, Python 3.6.2. Previously, I did manage to successfully Reflash a Sonoff Touch.

[czyz]

Since kryten01 reported managing to get the Sonoff programmed OTA on a raspberry pi, I gave that a try. I had a raspberry pi model B and a USB wifi dongle handy. I installed python 3.6.2 and the requirements on it and gave it a whirl. It appears to run into the same exact 404 error at the same point in the process. The Sonoff s20_us never ends up creating a 'FinalStage' SSID.

For what it's worth, I tried accessing the URL presented as downloadUrl via a web browser and it does look like the python script is serving up a little binary. Also I do hear the plug turning its relay on and off at the '"switch": "off"' and '"switch": "on"' bits that go by in the debug output. Just as on OS X, the process seems to derail around here, I think. Is "GET /ota/image_user2-0x81000.bin?deviceid=10000a751c&ts=1486937972&sign=a2a3dd4d824537b5215a6df07845903811cdca95d84454d4fc625076d8b16b47" malformed in some way?

2017-09-29 21:49:40,301 (DEBUG) << WEBSOCKET INPUT
2017-09-29 21:49:40,314 (DEBUG) << {
    "userAgent": "device",
    "apikey": "b9dd274c-54b6-4578-b0b1-043bc10ce370",
    "deviceid": "10000a751c",
    "action": "query",
    "params": [
        "timers"
    ]
}
~~~ device sent action request,  acknowledging / answering...
~~~~ query
>> {
    "error": 0,
    "deviceid": "10000a751c",
    "apikey": "b9dd274c-54b6-4578-b0b1-043bc10ce370",
    "params": 0
}
2017-09-29 21:49:41,201 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=10000a751c&ts=1486937972&sign=a2a3dd4d824537b5215a6df07845903811cdca95d84454d4fc625076d8b16b47 (10.0.1.148) 419.12ms
2017-09-29 21:49:41,225 (DEBUG) << WEBSOCKET INPUT
2017-09-29 21:49:41,236 (DEBUG) << {
    "error": 404,
    "userAgent": "device",
    "apikey": "b9dd274c-54b6-4578-b0b1-043bc10ce370",
    "deviceid": "10000a751c",
    "sequence": "1506721780251"
}
2017-09-29 21:49:41,255 (DEBUG) ~~~ device acknowledged our action request (seq 1506721780251) with error code 404

test-upload-sonota-from-raspberry-pi.txt

[czyz]

Did a some further digging. It seems that part of the process did work -- the s20 is sitting there on my network, connected via wifi, and has an IP address of 10.0.1.148. I tried connecting to it using the 'Simple Websocket Client' chrome extension at /api/ws, but had no luck.

The s20 no longer creates an ITEAD-* wifi network (though it will if I hold down its button for 7 seconds).

I tried running sonota.py on the raspberry pi with the --no-prov argument. I was expecting it to not ask for wifi credentials since I thought the idea of that argument was to skip that part of the process, but it asked for them and I gave 'em. Then it found the sonoff s20 on the network and started communicating with it, the relay switched on and off, and the 404 error was encountered.

I guess maybe either the firmware required to get to FinalStage is never installed on the plug or the command to flash it isn't being received or acted upon or -- maybe I'd better stop speculating and hope that more knowledgeable folk will see something obvious in this debug output. For now, my S20_us sonoff plug is just sitting there on the network as 10.0.1.148, taunting me with its inscrutable presence.

python3.6 sonota.py --no-prov
Select IP address of the WiFi interface:
    0: 10.0.1.150
Select IP address [0]: 
WiFi SSID: my wifi SSID
WiFi Password: that password

Using the following configuration:
    Server IP Address: 10.0.1.150
    WiFi SSID: asdf
    WiFi Password: asdf
Starting stage2...
~~ Starting web server (HTTP port: 8080, HTTPS port 8443)
~~ 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.
.......<< HTTP POST /dispatch/device
>> /dispatch/device
>> {
    "error": 0,
    "reason": "ok",
    "IP": "10.0.1.150",
    "port": 8443
}
2017-09-29 22:20:51,908 (INFO) 200 POST /dispatch/device (10.0.1.148) 40.63ms
2017-09-29 22:20:52,275 (INFO) 101 GET /api/ws (10.0.1.148) 23.35ms
2017-09-29 22:20:52,281 (DEBUG) << WEBSOCKET OPEN
2017-09-29 22:20:52,306 (DEBUG) << WEBSOCKET INPUT
2017-09-29 22:20:52,314 (DEBUG) << {
    "userAgent": "device",
    "apikey": "406c833f-db53-42e9-964d-1b762915b359",
    "deviceid": "10000a751c",
    "action": "register",
    "version": 2,
    "romVersion": "1.5.2",
    "model": "PSA-B01-GL",
    "ts": 257
}
~~~ device sent action request,  acknowledging / answering...
2017-09-29 22:20:52,326 (INFO) We are dealing with a PSA-B01-GL model.
~~~~ register
>> {
    "error": 0,
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "config": {
        "hb": 1,
        "hbInterval": 145
    }
}
2017-09-29 22:20:52,361 (DEBUG) << WEBSOCKET INPUT
2017-09-29 22:20:52,367 (DEBUG) << {
    "userAgent": "device",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "deviceid": "10000a751c",
    "action": "date"
}
~~~ device sent action request,  acknowledging / answering...
~~~~ date
>> {
    "error": 0,
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "date": "2017-09-29T22:20:52.377Z"
}
2017-09-29 22:20:52,412 (DEBUG) << WEBSOCKET INPUT
2017-09-29 22:20:52,421 (DEBUG) << {
    "userAgent": "device",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "deviceid": "10000a751c",
    "action": "update",
    "params": {
        "switch": "off",
        "fwVersion": "1.5.2",
        "rssi": -45,
        "startup": "off"
    }
}
~~~ device sent action request,  acknowledging / answering...
~~~~ update
>> {
    "error": 0,
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809"
}
>> {
    "action": "update",
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "userAgent": "app",
    "sequence": "1506723652447",
    "ts": 0,
    "params": {
        "switch": "off"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "userAgent": "app",
    "sequence": "1506723652460",
    "ts": 0,
    "params": {
        "switch": "on"
    },
    "from": "hackepeter"
}.
>> {
    "action": "update",
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "userAgent": "app",
    "sequence": "1506723652486",
    "ts": 0,
    "params": {
        "switch": "off"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "userAgent": "app",
    "sequence": "1506723652500",
    "ts": 0,
    "params": {
        "switch": "on"
    },
    "from": "hackepeter"
}
>> {
    "action": "update",
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "userAgent": "app",
    "sequence": "1506723652520",
    "ts": 0,
    "params": {
        "switch": "off"
    },
    "from": "hackepeter"
}
>> {
    "action": "upgrade",
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "userAgent": "app",
    "sequence": "1506723652577",
    "ts": 0,
    "params": {
        "binList": [
            {
                "downloadUrl": "http://10.0.1.150:8080/ota/image_user1-0x01000.bin",
                "digest": "97fe70d737390bbde7b8d208c79d590e29fc76962623c7bd198ee210210ea616",
                "name": "user1.bin"
            },
            {
                "downloadUrl": "http://10.0.1.150:8080/ota/image_user2-0x81000.bin",
                "digest": "e6d0cbb641542bd0a27e6c4628fc9331f1f5d3ac3afa42c9307569cf4d70fcdc",
                "name": "user2.bin"
            }
        ],
        "model": "PSA-B01-GL",
        "version": "23.42.5"
    }
}
2017-09-29 22:20:52,612 (DEBUG) << WEBSOCKET INPUT
2017-09-29 22:20:52,621 (DEBUG) << {
    "userAgent": "device",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "deviceid": "10000a751c",
    "action": "query",
    "params": [
        "timers"
    ]
}
~~~ device sent action request,  acknowledging / answering...
~~~~ query
>> {
    "error": 0,
    "deviceid": "10000a751c",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "params": 0
}
2017-09-29 22:20:53,088 (DEBUG) << WEBSOCKET INPUT
2017-09-29 22:20:53,097 (DEBUG) << {
    "error": 0,
    "userAgent": "device",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "deviceid": "10000a751c",
    "sequence": "1506723652520"
}
2017-09-29 22:20:53,106 (DEBUG) ~~~ device acknowledged our action request (seq 1506723652520) with error code 0
2017-09-29 22:20:53,547 (INFO) 200 GET /ota/image_user2-0x81000.bin?deviceid=10000a751c&ts=1812158119&sign=af8983eb3d7437055bb47e0fc76a8f8c474a6e6ed48df29453489c325107fcf1 (10.0.1.148) 417.56ms
2017-09-29 22:20:53,570 (DEBUG) << WEBSOCKET INPUT
2017-09-29 22:20:53,578 (DEBUG) << {
    "error": 404,
    "userAgent": "device",
    "apikey": "81f97c21-c2d1-4a29-aa6a-363db095e809",
    "deviceid": "10000a751c",
    "sequence": "1506723652577"
}
2017-09-29 22:20:53,588 (DEBUG) ~~~ device acknowledged our action request (seq 1506723652577) with error code 404
..

*** 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.
..........

[sillyfrog]

@czyz re the 404, this is a response coming from the Sonoff via the Websocket connection, not an actual 404. My best guess is it’s something to do with the “timers” request as that’s something I don’t see when I flash mine (no idea why, but I’m pretty sure that’s the cause). Another idea I have had is the try making the response to the timers call a no-op (ie: just a ‘pass’ in the code). I have never seen this issue so can’t test it.

Re getting prompted for WiFi username and password with no-prov, that’s just me not thinking about it when I put in the steps asking for username and password. You are right, they are never used. I’ll sort that out when I next have a chance.

[czyz]

Hmm, regarding "timers", for what it's worth, I've never run the EWeLink app. The first time I plugged in the s20_us was to flash it using SonOTA.

[08-15at]

@czyz first I tried SonOta on a device fresh out of the box as well. So I initially thought, not registering via Ewelink could cause the problem. Unfortunately using Ewelink before SonOta doesn't help.

[czyz]

So I guess maybe that means sonoff devices are now shipping with a newer version of firmware that requires timers be set? If so, I found some syntax for setting them up on this page.

The relevant portion seems to be:

{action: 'update', value: {timers : d.timers} Format for timer setup is

{
    enabled : true,
    type : 'once' OR 'repeat',
    at : time,
    do : {
     switch : 'on' OR 'off'
    }
 }

So maybe we insert a timer configured to 'enabled: false' and it'll let us continue on to installing or switching to the SonOTA-uploaded firmware?

edit -- (If I knew Python I'd have tried this by now)

[andyfitter]

What I don't understand is that it seems that things have 'just suddenly' stopped working for lots of people. I find it hard to be believe that new firmware has made its way through the supply chain and hit all of us at this point.

A suggestion. At the point that the device connects to your 'real' Wifi, could it be making a request to some other external server and the response it gets is changing its behaviour from previously, and stopping the Flash proceeding? Maybe I'll take a shot at Flashing whilst my internet connection is down.

[EDIT] Tried flashing whilst internet connection was down and still the same '404'