search

ruuvi / ruuvi.gateway_esp.c

Ruuvi Gateway ESP32 code
BSD 3-Clause "New" or "Revised" License
24 stars 15 forks source link

Gateway reboots with IntegerDivideByZero when trying to update firmware from server that does not return 'Content-length' #1022

Open TheSomeMan opened 2 months ago

TheSomeMan commented 2 months ago 
I (566687) transport_base: [fw_update_task] [<NULL>] Configure size of TLS I/O buffers: in_content_len=16384, out_content_len=4096
I (566700) esp-tls: [fw_update_task] esp_tls_init: tls=0x3ffe0b04
I (566758) esp-tls: [fw_update_task] Hostname 'my-https-server.local' resolved to 192.168.1.145
I (566809) esp-tls: [fw_update_task] esp_tls_tcp_connect: Open socket 54 for 192.168.1.145:8000
I (566814) http_download: [fw_update_task/1] HTTP_EVENT_ON_CONNECTED
I (566817) http_download: [fw_update_task/1] HTTP_EVENT_HEADER_SENT
I (566824) http_download: [fw_update_task/1] HTTP_EVENT_ON_HEADER, key=Content-type, value=application/octet-stream
I (566833) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 7
I (566839) http_download: [fw_update_task/1] HTTP_EVENT_ON_HEADER, key=Cache-Control, value=no-store, no-cache, must-revalidate, max-age=0
I (566852) http_download: [fw_update_task/1] HTTP_EVENT_ON_HEADER, key=Pragma, value=no-cache
I (566861) fw_update: [fw_update_task/1] Write to OTA-partition ota_1, offset 0, size 1908
Guru Meditation Error: Core  0 panic'ed (IntegerDivideByZero). Exception was unhandled.

Core  0 register dump:
PC      : 0x400e093a  PS      : 0x00060630  A0      : 0x800ed36a  A1      : 0x3ffe9dd0  
A2      : 0x3ffe6f80  A3      : 0x00000774  A4      : 0x0000ba54  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x3ffea1ec  A8      : 0x00009510  A9      : 0x3ffe9d80  
A10     : 0x00000003  A11     : 0x000174a8  A12     : 0x3f408dcc  A13     : 0x8ed73ab6  
A14     : 0x3ffe9d80  A15     : 0x3ffe60a0  SAR     : 0x00000004  EXCCAUSE: 0x00000006  
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffe  

Backtrace:0x400e0937:0x3ffe9dd0 0x400ed367:0x3ffe9e40 0x4017efd5:0x3ffe9e90 0x4017f30d:0x3ffe9ec0 0x40175f21:0x3ffe9ef0 0x4017f949:0x3ffe9f60 0x40180b9a:0x3ffe9f90 0x400eb97f:0x3ffe9fe0 0x400ed6b7:0x3ffea050 0x400edc69:0x3ffea0c0 0x400edd29:0x3ffea140 0x400eddb3:0x3ffea170 0x400e0340:0x3ffea1c0 0x400e070c:0x3ffea240 0x400e081d:0x3ffea290 0x400e143c:0x3ffea2e0 0x400e1718:0x3ffea330 0x401770bd:0x3ffea370 0x4008ad72:0x3ffea3a0

ELF file SHA256: 13a1e234fe494f6a

Rebooting...
E (566870) reset_info: __wrap_panic_restart: PANIC: Guru Meditation Error: Core  0 panic'ed (IntegerDivideByZero). Exception was unhandled.

Core  0 register dump:
PC      : 0x400e093a  PS      : 0x00060630  A0      : 0x800ed36a  A1      : 0x3ffe9dd0  
A2      : 0x3ffe6f80  A3      : 0x00000774  A4      : 0x0000ba54  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x3ffea1ec  A8      : 0x00009510  A9      : 0x3ffe9d80  
A10     : 0x00000003  A11     : 0x000174a8  A12     : 0x3f408dcc  A13     : 0x8ed73ab6  
A14     : 0x3ffe9d80  A15     : 0x3ffe60a0  SAR     : 0x00000004  EXCCAUSE: 0x00000006  
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffe  

Backtrace:0x400e0937:0x3ffe9dd0 0x400ed367:0x3ffe9e40 0x4017efd5:0x3ffe9e90 0x4017f30d:0x3ffe9ec0 0x40175f21:0x3ffe9ef0 0x4017f949:0x3ffe9f60 0x40180b9a:0x3ffe9f90 0x400eb97f:0x3ffe9fe0 0x400ed6b7:0x3ffea050 0x400edc69:0x3ffea0c0 0x400edd29:0x3ffea140 0x400eddb3:0x3ffea170 0x400e0340:0x3ffea1c0 0x400e070c:0x3ffea240 0x400e081d:0x3ffea290 0x400e143c:0x3ffea2e0 0x400e1718:0x3ffea330 0x401770bd:0x3ffea370 0x4008ad72:0x3ffea3a0

ELF file SHA256: 13a1e234fe494f6a

Rebooting...
TheSomeMan commented 2 months ago

To test it you need to use this script ruuvi_gw_flash.py to download firmware v1.15.0:

python3 ruuvi_gw_flash.py v1.15.0 --download_only

And this script to run local HTTP server script:

python3 http_server_auth.py --port 8000

After that open the gateway configuration wizard, navigate to "Software Update" page, open "Advanced settings", check the checkbox "Don't use the software update provided by Ruuvi" and enter URL: http://:8000/.releases/v1.15.0 and click the "Update" button.

ojousima commented 2 months ago

The update failed, I can download the files using another PC in same network. GW version Jenkins/latest, v1.15.0-41-g5d34e62｜v1.0.0 Logs:

 I (112592) http_server: [http_server/1] Json resp: code=200, content:
{"ssid":"Telia12674E","ip":"192.168.1.203","netmask":"255.255.255.0","gw":"192.168.1.1","dhcp":"192.168.1.1","urc":0}

I (112609) http_server: [http_server/1] Response: OK
I (113274) http_server: [http_server/1] Request from 192.168.1.243 to 192.168.1.203 (Host: ruuvigw.saarvahtra.ojousima.net): POST /fw_update.json
I (113278) http_server: [http_server/1] POST /fw_update.json, params=
I (113286) gw_status: [http_server/1] SUSPEND RELAYING
I (113287) ADV_POST_TASK: [adv_post_task/5] Got ADV_POST_SIG_RETRANSMIT2
I (113291) http_download: [http_server/5] HTTP download/check: Method=HEAD, URL: 'http://192.168.1.98:8000/.releases/v1.15.0/ruuvi_gateway_esp.bin'
I (113308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 14
I (113312) gw_status: [http_server/5] SUSPEND HTTP RELAYING
I (113324) transport_base: [http_server] [<NULL>] Configure size of TLS I/O buffers: in_content_len=16384, out_content_len=4096
I (113337) esp-tls: [http_server] esp_tls_init: tls=0x3fff8f4c
I (113343) esp-tls: [http_server] Hostname '192.168.1.98' resolved to 192.168.1.98
I (113351) esp-tls: [http_server] esp_tls_tcp_connect: Open socket 54 for 192.168.1.98:8000
I (113466) http_download: [http_server/5] HTTP_EVENT_ON_CONNECTED
I (113470) http_download: [http_server/5] HTTP_EVENT_HEADER_SENT
I (113522) http_download: [http_server/5] HTTP_EVENT_ON_HEADER, key=Server, value=SimpleHTTP/0.6 Python/3.11.2
I (113523) http_download: [http_server/5] HTTP_EVENT_ON_HEADER, key=Date, value=Tue, 30 Apr 2024 20:37:04 GMT
I (113533) http_download: [http_server/5] HTTP_EVENT_ON_HEADER, key=Content-type, value=application/octet-stream
I (113811) ruuvi_gateway: [main/1] free heap: 101888 .. 113868
I (114308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 14
I (115308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 11
I (116308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 13
I (117308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 7
I (118308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 10
I (119308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 11
I (120308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 12
I (121308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 9
I (122308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 9
I (123308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 12
I (123811) ruuvi_gateway: [main/1] free heap: 101580 .. 102276
I (124308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 8
I (125308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 12
I (125809) ADV_POST_TASK: [adv_post_task/5] Got ADV_POST_SIG_RETRANSMIT
I (126308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 9
I (126713) runtime_stat: [main/1] ======== totalTime 29999997 ==============================================================
I (126714) runtime_stat: [main/1] |  #  |    Task name     | Pri | Stat|    cnt    |  %  |        Stack       | Stack free |
I (126726) runtime_stat: [main/1] |-----|------------------|-----|-----|-----------|-----|--------------------|------------|
I (126738) runtime_stat: [main/1] |   3 | IDLE0            |   0 | Rdy |  27222060 | 91% |  732 of  1532 (47%)|      800   |
I (126750) runtime_stat: [main/1] |   2 | main             |   1 | Rdy |    260542 |  1% | 3028 of  3964 (76%)|      936   |
I (126761) runtime_stat: [main/1] |   6 | reset_task       |   1 | Sus |      3421 | <1% | 2024 of  2812 (71%)|      788   |
I (126773) runtime_stat: [main/1] |  10 | time_task        |   1 | Sus |         0 |  0% | 2080 of  3068 (67%)|      988   |
I (126785) runtime_stat: [main/1] |  13 | http_server      |   1 | Blk |   1116044 |  4% | 5872 of  7676 (76%)|     1804   |
I (126797) runtime_stat: [main/1] |  18 | mdns             |   1 | Blk |         0 |  0% | 2168 of  3068 (70%)|      900   |
I (126809) runtime_stat: [main/1] |   8 | adv_post_task    |   5 | Sus |     57246 | <1% | 4464 of  6140 (72%)|     1676   |
I (126821) runtime_stat: [main/1] |  15 | wifi_manager     |   5 | Blk |      3404 | <1% | 2320 of  4092 (56%)|     1772   |
I (126833) runtime_stat: [main/1] |   7 | adv_mqtt_task    |   6 | Sus |     15743 | <1% | 2500 of  4092 (61%)|     1592   |
I (126845) runtime_stat: [main/1] |   5 | leds_task        |   8 | Sus |     94092 | <1% | 2084 of  3068 (67%)|      984   |
I (126857) runtime_stat: [main/1] |   9 | uart_rx_task     |   9 | Blk |    306552 |  1% | 2276 of  4092 (55%)|     1816   |
I (126868) runtime_stat: [main/1] |  16 | emac_rx          |  15 | Sus |         0 |  0% |  628 of  3068 (20%)|     2440   |
I (126880) runtime_stat: [main/1] |  12 | tiT              |  18 | Blk |    329245 |  1% | 2332 of  3836 (60%)|     1504   |
I (126892) runtime_stat: [main/1] |  11 | sys_evt          |  20 | Blk |         0 |  0% | 2120 of  2812 (75%)|      692   |
I (126904) runtime_stat: [main/1] |   1 | esp_timer        |  22 | Blk |     76819 | <1% |  892 of  2556 (34%)|     1664   |
I (126916) runtime_stat: [main/1] |  14 | wifi             |  23 | Blk |    463150 |  2% | 2692 of  6652 (40%)|     3960   |
I (126928) runtime_stat: [main/1] |   4 | Tmr Svc          |  24 | Blk |     51682 | <1% | 2084 of  3068 (67%)|      984   |
I (126940) runtime_stat: [main/1] ==========================================================================================
I (127308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 10
I (128308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 10
I (129308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 12
I (130308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 7
I (131308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 8
I (132308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 13
I (133308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 9
I (133911) ruuvi_gateway: [main/1] free heap: 100888 .. 101580
I (134308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 11
I (135308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 9
I (136308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 11
I (137308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 12
I (138308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 11
E (138398) http: [http_server/5] ../main/http.c:331 {http_wait_until_async_req_completed}: timeout (25 seconds)
I (138398) http_download: [http_server/5] HTTP_EVENT_DISCONNECTED
I (138405) esp-tls: [http_server] esp_tls_conn_destroy: [sock=54][192.168.1.98] Close socket
I (138417) gw_status: [http_server/5] RESUME HTTP RELAYING
E (138420) http_download: [http_server/5] ../main/http_download.c:630 {http_check}: http_check failed for URL: http://192.168.1.98:8000/.releases/v1.15.0/ruuvi_gateway_esp.bin
I (138436) http_download: [http_server/5] http_check: completed within 25145 ticks
E (138444) http_server: [http_server/5] ../main/http_server_cb.c:755 {http_server_check_fw_update_binary_files}: Failed to download ruuvi_gateway_esp.bin, HTTP error: 502
I (138460) gw_status: [http_server/5] RESUME RELAYING
I (139308) ADV_POST_TASK: [adv_post_task/5] Advs cnt: 10
I (139468) http_server: [http_server/5] Json resp: code=200, content:
{
        "status":       502,
        "message":      "Failed to download ruuvi_gateway_esp.bin"
}
I (139471) http_server: [http_server/5] Response: OK
I (139488) http_server: [http_server/1] Request from 192.168.1.243 to 192.168.1.203 (Host: 192.168.1.203): GET /history
I (139492) http_server: [http_server/1] Requested /history on 60 seconds interval
I (139493) ruuvi_gateway: [main/1] MAIN_TASK_SIG_ON_GET_HISTORY
I (139508) LEDS: [main/1] Notify: HTTP_Poll ok
I (139510) LEDS: [leds_task/8] LEDS_TASK_SIG_ON_EV_HTTP_POLL_OK (ready=1)
I (139547) http_server: [http_server/1] Response: OK
E (139555) http_server: [http_server/1] ../components/esp32-wifi-manager/src/http_server_accept_and_handle_conn.c:213 {http_server_netconn_write}: netconn_write_partly failed (Connection reset), offset=0, size=720, err=-14 (BIGNUM - The input arguments are not acceptable)
E (139570) http_server: [http_server/1] ../components/esp32-wifi-manager/src/http_server_accept_and_handle_conn.c:440 {write_content_from_json_generator}: http_server_netconn_write failed
E (139588) http_server: [http_server/1] ../components/esp32-wifi-manager/src/http_server_accept_and_handle_conn.c:1072 {http_server_accept_and_handle_conn}: netconn_close failed (Not connected), err=-11 (OID - output buffer is too small)
I (139611) http_server: [http_server/1] Request from 192.168.1.243 to 192.168.1.203 (Host: 192.168.1.203): GET /history
I (139622) http_server: [http_server/1] Requested /history on 60 seconds interval
I (139623) ruuvi_gateway: [main/1] MAIN_TASK_SIG_ON_GET_HISTORY
I (139638) LEDS: [main/1] Notify: HTTP_Poll ok
I (139640) LEDS: [leds_task/8] LEDS_TASK_SIG_ON_EV_HTTP_POLL_OK (ready=1)
I (139672) http_server: [http_server/1] Response: OK
E (139681) http_server: [http_server/1] ../components/esp32-wifi-manager/src/http_server_accept_and_handle_conn.c:213 {http_server_netconn_write}: netconn_write_partly failed (Connection reset), offset=0, size=720, err=-14 (BIGNUM - The input arguments are not acceptable)
E (139695) http_server: [http_server/1] ../components/esp32-wifi-manager/src/http_server_accept_and_handle_conn.c:440 {write_content_from_json_generator}: http_server_netconn_write failed
E (139713) http_server: [http_server/1] ../components/esp32-wifi-manager/src/http_server_accept_and_handle_conn.c:1072 {http_server_accept_and_handle_conn}: netconn_close failed (Not connected), err=-11 (OID - output buffer is too small)
I (139736) http_server: [http_server/1] Request from 192.168.1.243 to 192.168.1.203 (Host: 192.168.1.203): GET /history
I (139749) http_server: [http_server/1] Requested /history on 60 seconds interval
I (139750) ruuvi_gateway: [main/1] MAIN_TASK_SIG_ON_GET_HISTORY
I (139762) LEDS: [main/1] Notify: HTTP_Poll ok
I (139766) LEDS: [leds_task/8] LEDS_TASK_SIG_ON_EV_HTTP_POLL_OK (ready=1)
I (139798) http_server: [http_server/1] Response: OK
I (139936) http_server: [http_server/1] Request from 192.168.1.243 to 192.168.1.203 (Host: ruuvigw.saarvahtra.ojousima.net): GET /status.json
I (139940) network: [http_server/1] callback: cb_on_request_status_json
I (139946) ruuvi_gateway: [http_server/1] ### Start timer for deactivation of configuration mode after timeout (60 seconds)
I (139958) http_server: [http_server/1] Json resp: code=200, content:
{"ssid":"Telia12674E","ip":"192.168.1.203","netmask":"255.255.255.0","gw":"192.168.1.1","dhcp":"192.168.1.1","urc":0}
TheSomeMan commented 2 months ago

I tested it again and didn't find any issues. Here is my log:

I (3895665) http_server: [http_server/1] Request from 192.168.1.145 to 192.168.1.127 (Host: ruuvigateway9c2c.local): POST /fw_update.json
I (3895668) http_server: [http_server/1] POST /fw_update.json, params=
I (3895676) gw_status: [http_server/1] SUSPEND RELAYING
I (3895681) http_download: [http_server/1] HTTP download/check: Method=HEAD, URL: 'http://192.168.1.145:8000/.releases/v1.15.0/ruuvi_gateway_esp.bin'
I (3895694) gw_status: [http_server/1] SUSPEND HTTP RELAYING
I (3895701) transport_base: [http_server] [<NULL>] Configure size of TLS I/O buffers: in_content_len=16384, out_content_len=4096
I (3895715) esp-tls: [http_server] esp_tls_init: tls=0x3ffe96c0
I (3895720) esp-tls: [http_server] Hostname '192.168.1.145' resolved to 192.168.1.145
I (3895729) esp-tls: [http_server] esp_tls_tcp_connect: Open socket 54 for 192.168.1.145:8000
I (3895742) http_download: [http_server/1] HTTP_EVENT_ON_CONNECTED
I (3895746) http_download: [http_server/1] HTTP_EVENT_HEADER_SENT
I (3895752) http_download: [http_server/1] HTTP_EVENT_ON_HEADER, key=Server, value=SimpleHTTP/0.6 Python/3.10.12
I (3895762) http_download: [http_server/1] HTTP_EVENT_ON_HEADER, key=Date, value=Wed, 01 May 2024 07:53:43 GMT
I (3895773) http_download: [http_server/1] HTTP_EVENT_ON_HEADER, key=Content-type, value=application/octet-stream
I (3895784) http_download: [http_server/1] HTTP_EVENT_ON_FINISH
I (3895790) http_download: [http_server/1] HTTP_EVENT_DISCONNECTED
I (3895797) esp-tls: [http_server] esp_tls_conn_destroy: [sock=54][192.168.1.145] Close socket
I (3895809) http_download: [http_server/1] HTTP_EVENT_DISCONNECTED
I (3895813) gw_status: [http_server/1] RESUME HTTP RELAYING
I (3895819) http_download: [http_server/1] http_check: completed within 138 ticks
I (3895828) http_download: [http_server/1] HTTP download/check: Method=HEAD, URL: 'http://192.168.1.145:8000/.releases/v1.15.0/fatfs_gwui.bin'

The problem is that your gateway was not received events:

I (3895784) http_download: [http_server/1] HTTP_EVENT_ON_FINISH
I (3895790) http_download: [http_server/1] HTTP_EVENT_DISCONNECTED

and the HTTP connection was not closed. Maybe there was a temporary network problem? Try to perform an HTTP HEAD request with curl to check your local HTTP server:

curl -v -X HEAD http://127.0.0.1:8000/.releases/v1.15.0/ruuvi_gateway_esp.bin
ojousima commented 1 month ago

Request:

curl -v -X HEAD http://127.0.0.1:8000/.releases/v1.15.0/ruuvi_gateway_esp.bin
Warning: Setting custom HTTP method to HEAD with -X/--request may not work the 
Warning: way you want. Consider using -I/--head instead.
*   Trying 127.0.0.1:8000...
* Connected to 127.0.0.1 (127.0.0.1) port 8000 (#0)
> HEAD /.releases/v1.15.0/ruuvi_gateway_esp.bin HTTP/1.1
> Host: 127.0.0.1:8000
> User-Agent: curl/8.1.2
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< Server: SimpleHTTP/0.6 Python/3.11.2
< Date: Fri, 03 May 2024 07:30:47 GMT
< Content-type: application/octet-stream
< 
* Closing connection 0

Server script output:

127.0.0.1 - - [03/May/2024 10:30:47] "HEAD /.releases/v1.15.0/ruuvi_gateway_esp.bin HTTP/1.1" 200 -
TheSomeMan commented 1 month ago

Request:

  • HTTP 1.0, assume close after body < HTTP/1.0 200 OK < Server: SimpleHTTP/0.6 Python/3.11.2 < Date: Fri, 03 May 2024 07:30:47 GMT < Content-type: application/octet-stream <
  • Closing connection 0

This looks good. Could you repeat the test with the gateway?

ojousima commented 1 month ago

Update fails, I see 192.168.1.203 - - [03/May/2024 11:00:49] "HEAD /.releases/v1.15.0/ruuvi_gateway_esp.bin HTTP/1.1" 200 - on server side. Do you need Gateway terminal logs again? WebUI report is Error when starting the firmware update process. Status: 502, Message: Failed to download ruuvi_gateway_esp.bin

TheSomeMan commented 1 month ago

Update fails, I see 192.168.1.203 - - [03/May/2024 11:00:49] "HEAD /.releases/v1.15.0/ruuvi_gateway_esp.bin HTTP/1.1" 200 - on server side. Do you need Gateway terminal logs again? WebUI report is Error when starting the firmware update process. Status: 502, Message: Failed to download ruuvi_gateway_esp.bin

That's strange. The server sees the HEAD request and responds to it, but the gateway does not see the connection close event. Can you try 'curl' from another computer in the LAN? And capture the network traffic to port 8000 with Wireshark? Maybe some network firewall is affecting this network connection?

ojousima commented 1 month ago

Here is Wireshark capture. Network has 3 devices: Mac as a server at 192.168.1.98, Windows PC as a client at 192.168.1.158 and Ruuvi Gateway as a client at 192.168.1.203. Ruuvvi GW is running Jenkins/Latest v1.15.0-43-gf426c53｜v1.0.0

image

Json of selected packets is attached, let me know if I can filter the information in some better way. JSON is pretty verbose.

fwupdate.json

TheSomeMan commented 1 month ago

The bug was fixed here: https://github.com/ruuvi/ruuvi.gateway_esp.c/pull/1039

ojousima commented 1 month ago

I'll check this when I'm in my home network later today