"The last HTTP request has timed out" after upgrade to 1.20

[dc42]

Anyone getting http timeout errors using DuetWiFiServer 1.20+1, please try reverting to version 1.20. it's compatible with 1.20.1RC firmware.

[pao_wikhan]

i reverted to 1.20
will keep you posted if i still have the issue.

Firmware Version: 1.20.1RC2 (2018-01-01)
WiFi Server Version: 1.20
Web Interface Version: 1.20

[Captain_sq]

I use 1.20 on FW, DWC and DWS

[Captain_sq]

Changing the number of AJAX retries from 1 to 5 seems to have effect. I've been on for 3 hours now and nothing dropped yet…

[Captain_sq]

@Captain_sq:

Changing the number of AJAX retries from 1 to 5 seems to have effect. I've been on for 3 hours now and nothing dropped yet…

Hmm… not out of the woods yet, it still drops connection. It seems that it's more likely to drop when the printer is active printing.

[dc42]

You can help debug this as described in my earlier post:

You can connect a PC via USB, then send M111 S1 P14 to enable wifi debug messages to be sent to USB.

Also please read https://duet3d.com/wiki/WiFi_disconnections_and_AJAX_timeout_errors if you haven't already.

[Captain_sq]

@dc42:

You can help debug this as described in my earlier post:

You can connect a PC via USB, then send M111 S1 P14 to enable wifi debug messages to be sent to USB.

Also please read https://duet3d.com/wiki/WiFi_disconnections_and_AJAX_timeout_errors if you haven't already.

Here is a log dump from sunday afternoon. Wifi debugging going. Several HTTP timeouts were noted on the browser during this time. I can, however, not make anything out of the printouts directly related to these events.

[[language]]
(12:28:27.689) M122
(12:28:27.852) === Diagnostics ===
(12:28:27.852) Used output buffers: 1 of 32 (14 max)
(12:28:27.852) === Platform ===
(12:28:27.852) RepRapFirmware for Duet WiFi version 1.20 running on Duet WiFi 1.0
(12:28:27.852) Board ID: 08DGM-95BNL-MGPSN-6J9DL-3SJ6K-92Y7Y
(12:28:27.852) Static ram used: 15448
(12:28:27.852) Dynamic ram used: 99232
(12:28:27.852) Recycled dynamic ram:WiFi: 
(12:28:27.877)  4104
(12:28:27.877) Stack ram used: 3576 current, 8544 maximum
(12:28:27.877) Never used ram: 3744
(12:28:27.877) Last reset 02:27:28 ago, cause: power up
(12:28:27.877) Last software reset at 2018-01-13 22:54, reason: User, spinning module GCodes, available RAM 11952 bytes (slot 3)
(12:28:27.877) Software reset code 0x0003 HFSRWiFi: xmit: 0
(12:28:27.877)  0x00000000, CFSR 0x00000000, ICSR 0x0441f0WiFi: recv: 0
(12:28:27.877) 00, BFAR 0xe000ed38, SP 0xffffffff
(12:28:27.877) Error status: 0
(12:28:27.877) Free file entries: 9
(12:28:27.877) SD card 0 detected, interface speed: 20.0MBytes/sec
(12:28:27.877) SD card longest block write time: 265.2ms
(12:28:27.877) MCU temperature: min 29.2, current 31.7, max 32WiFi: fw: 0
(12:28:27.877) .1
(12:28:27.877) Supply voltage: min 11.8, current 12.0, max 12.3, under voltage events: 0, oveWiFi: drop: 0
(12:28:27.877) r voltage events: 0
(12:28:27.877) Driver 0: ok, SG min/max 0/358
(12:28:27.877) Driver 1: ok, SG min/max 0/1023
(12:28:27.877) Driver 2: standstill, SG min/max 0/217
(12:28:27.877) Driver 3: open-load-A open-load-B, SG min/max 0/1023
(12:28:27.877) WiFi: chkerr: 0
(12:28:27.877) Driver 4: standstill, SG min/max 0/211
(12:28:27.877) Date/time: 2018-01-14 12:28:26
(12:28:27.877) Cache data hit count 4294967295
(12:28:27.877) Slowest main loop (seconds): 0.268294; fastest: 0.000109
(12:28:27.877) === Move ===
(12:28:27.877) MaxReps: 4, StepErrors: 0, FreeDm: 151, MinFreeDm 133, MaxWait: 929981ms, Underruns:WiFi: lenerr: 0
(12:28:27.877)  0, 0
(12:28:27.877) Scheduled moves: 10204, completed moves: 1WiFi: memerr: 0
(12:28:27.877) 0178
(12:28:27.877) Bed compensation in use: mesh
(12:28:27.877) Bed probe heights: -0.707 -0.709 0.000 0.000 0.000
(12:28:27.877) === Heat ===
(12:28:27.877) Bed heaters = 0 -1 -1 -1, chamberHeaters = -1 -1
(12:28:27.877) Heater 0 is on, I-accum = 0.0
(12:28:27.877) Heater 1 is on, I-accum = 0.9
(12:28:27.877) WiFi: rterr: 0
(12:28:27.877) === GCodes ===
(12:28:27.877) Segments left: 1
(12:28:27.877) Stack records: 2 allocated, 0 in use
(12:28:27.877) Movement locWiFi: proterr: 0
(12:28:27.877) k held by null
(12:28:27.877) http is idle in state(s) 0
(12:28:27.877) telnet is idle in state(s) 0
(12:28:27.877) file is doing "G1 X229.168 Y157.350 E3.7634" in state(s) 0
(12:28:27.877) serial is ready with "M122" in state(s) 0
(12:28:27.877) auxWiFi: opterr: 0
(12:28:27.877)  is idle in state(s) 0
(12:28:27.877) daemon is idle in state(s) 0
(12:28:27.877) queue is idle in state(s) 0
(12:28:27.877) autopause is idle in state(s) 0
(12:28:27.877) WiFi: err: 0
(12:28:27.877) Code queue is empty.
(12:28:27.877) Network state is running
(12:28:27.877) WiFi module is connected to access point 
(12:28:27.877) Failed messages: pending 0, notready 0, noresp 0
(12:28:27.877) WiFi fiWiFi: cachehit: 0
(12:28:27.877) rmware version 1.20
(12:28:27.877) WiFi MAC address 2c:3a:e8:0b:15:63
(12:28:27.877) WiFi Vcc 3.38, reset reason Turned on by main processor
(12:28:27.877) WiFi flash size 4194304, free heap 15728
(12:28:27.877) WiFi IP address 192.168.200.72
(12:28:27.877) WiFi signal strength -38dBm, reconnections 0, sleep mode modem
(12:28:27.877) HTTP sessiWiFi: 
(12:28:27.877) ons: 1 of 8
(12:28:27.877) Socket states:  0 0 0 0 0 0 0 0
(12:28:27.877) Responder staWiFi: xmit: 128
(12:28:27.877) tes: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
(12:28:27.877) ok
(12:28:27.877) WiFi: recv: 15278
(12:28:27.877) WiFi: fw: 0
(12:28:27.877) WiFi: drop: 5725
(12:28:27.877) WiFi: chkerr: 0
(12:28:27.877) WiFi: lenerr: 0
(12:28:27.877) WiFi: memerr: 0
(12:28:27.877) WiFi: rterr: 0
(12:28:27.877) WiFi: proterr: 5725
(12:28:27.877) WiFi: opterr: 0
(12:28:27.877) WiFi: err: 0
(12:28:27.877) WiFi: cachehit: 61522
(12:28:27.877) WiFi: 
(12:28:27.877) WiFi: xmit: 61749
(12:28:27.877) WiFi: recv: 44699
(12:28:27.877) WiFi: fw: 0
(12:28:27.877) WiFi: drop: 3177
(12:28:27.877) WiFi: chkerr: 0
(12:28:27.877) WiFi: lenerr: 0
(12:28:27.877) WiFi: memerr: 0
(12:28:27.877) WiFi: rterr: 0
(12:28:27.877) WiFi: proterr: 0
(12:28:27.877) WiFi: opterr: 0
(12:28:27.877) WiFi: err: 0
(12:28:27.877) WiFi: cachehit: 0
(12:28:27.877) WiFi: 
(12:28:27.877) WiFi: xmit: 161
(12:28:27.877) WiFi: recv: 147
(12:28:27.877) WiFi: drop: 0
(12:28:27.877) WiFi: chkerr: 0
(12:28:27.877) WiFi: lenerr: 0
(12:28:27.877) WiFi: memerr: 0
(12:28:27.877) WiFi: proterr: 0
(12:28:27.877) WiFi: rx_v1: 0
(12:28:27.877) WiFi: rx_group: 0
(12:28:27.877) WiFi: rx_general: 147
(12:28:27.877) WiFi: rx_report: 0
(12:28:27.877) WiFi: tx_join: 6
(12:28:27.877) WiFi: tx_leave: 4
(14:23:46.549) 
(14:23:46.551) 
(14:23:47.789) 
(14:23:47.840) Done printing fileFinished printing file Monteringsdetaljer/2020 Profil/X5S PLA L020 N040-050 PrA 2020 profile 180 mm v1.gcode, print time was 2h 12m
(15:10:46.527) M122
(15:10:46.689) === Diagnostics ===
(15:10:46.689) Used output buffers: 1 of 32 (14 max)
(15:10:46.689) === Platform ===
(15:10:46.689) RepRapFirmware for Duet WiFi version 1.20 running on Duet WiFi 1.0
(15:10:46.689) Board ID: 08DGM-95BNL-MGPSN-6J9DL-3SJ6K-92Y7Y
(15:10:46.689) Static ram used: 15448
(15:10:46.689) Dynamic ram used: 99232
(15:10:46.689) Recycled dynamic ram:WiFi: tx_report: 
(15:10:46.721)  4104
(15:10:46.721) Stack ram used: 3576 current, 8544 maximum
(15:10:46.721) Never used ram: 3744
(15:10:46.721) Last reset 05:09:47 ago, cause: power up
(15:10:46.721) Last software reset at 2018-01-13 22:54, reason: User, spinning module GCodes, available RAM 11952 bytes (slot 3)
(15:10:46.721) Software reset code 0x0003 HFSRWiFi: xmit: 0
(15:10:46.721)  0x00000000, CFSR 0x00000000, ICWiFi: recv: 0
(15:10:46.721) SR 0x0441f000, BFAR 0xe000ed38, SP 0xffffffff
(15:10:46.721) Error status: 0
(15:10:46.721) Free file entries: 10
(15:10:46.721) SD card 0 detected, interface speed: 20.0MBytes/sec
(15:10:46.721) SD card longest block write time: 0.0ms
(15:10:46.721) MCU temperature: min 30.1, current 30.4, max 32.WiFi: fw: 0
(15:10:46.721) 7
(15:10:46.721) Supply voltage: min 11.8, current 12.1, max 12.3, under voltage evenWiFi: drop: 0
(15:10:46.721) ts: 0, over voltage events: 0
(15:10:46.721) Driver 0: standstill, SG min/max 0/1023
(15:10:46.721) Driver 1: standstill, SG min/max 0/1023
(15:10:46.721) Driver 2: standstill, SG min/max 95/197
(15:10:46.721) Driver 3: standstill, SG min/max 0/1WiFi: chkerr: 0
(15:10:46.721) 023
(15:10:46.721) Driver 4: standstill, SG min/max 70/195
(15:10:46.721) Date/time: 2018-01-14 15:10:44
(15:10:46.721) Cache data hit count 42949672WiFi: lenerr: 0
(15:10:46.721) 95
(15:10:46.721) Slowest main loop (seconds): 0.159779; fastest: 0.000109
(15:10:46.721) === Move ===
(15:10:46.721) MaxReps: 4, StepErrors: 0, FreeDm: 240, MinFreeDm 128, MaxWait: 0ms, Underruns:WiFi: memerr: 0
(15:10:46.721)  0, 1
(15:10:46.721) Scheduled moves: 0, completed moves: 0
(15:10:46.721) Bed compensation in use: mesh
(15:10:46.721) Bed probe heights: -0.707 -0.709 0.000 0.000 0.000
(15:10:46.721) === Heat =WiFi: rterr: 0
(15:10:46.721) ==
(15:10:46.721) Bed heaters = 0 -1 -1 -1, chamberHeaters = -1 -1
(15:10:46.721) Heater 0 is on, I-accum = 0.0
(15:10:46.721) Heater 1 is on, I-accum = 0.8
(15:10:46.721) === GCodWiFi: proterr: 0
(15:10:46.721) es ===
(15:10:46.721) Segments left: 0
(15:10:46.721) Stack records: 2 allocated, 0 in use
(15:10:46.721) Movement lock held by null
(15:10:46.721) http is idle in state(s) 0
(15:10:46.721) telnet is idle in state(s) 0
(15:10:46.721) file is idle in state(s)WiFi: opterr: 0
(15:10:46.721)  0
(15:10:46.721) serial is ready with "M122" in state(s) 0
(15:10:46.721) aux is idle in state(s) 0
(15:10:46.721) daemon is idle inWiFi: err: 0
(15:10:46.721)  state(s) 0
(15:10:46.721) queue is idle in state(s) 0
(15:10:46.721) autopause is idle in state(s) 0
(15:10:46.721) Code queue is empty.
(15:10:46.721) Network state is running
(15:10:46.721) WiFi module is connected to access point 
(15:10:46.721) Failed messages: pending 0, notready 0, norWiFi: cachehit: 0
(15:10:46.721) esp 0
(15:10:46.721) WiFi firmware version 1.20
(15:10:46.721) WiFi MAC address 2c:WiFi: 
(15:10:46.721) 3a:e8:0b:15:63
(15:10:46.721) WiFi Vcc 3.39, reset reason Turned on by main processor
(15:10:46.721) WiFi flash size 4194304, free heap 15728
(15:10:46.721) WiFi IP address 192.168.200.72
(15:10:46.721) WiFi signal strength -47dBm, reconnections 0, sleep mode modem
(15:10:46.721) HTTP sessions: 1 of 8
(15:10:46.721) Socket states:WiFi: xmit: 247
(15:10:46.721)   0 0 0 0 0 0 WiFi: recv: 34164
(15:10:46.721) 0 0
(15:10:46.721) Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
(15:10:46.721) ok
(15:10:46.721) WiFi: fw: 0
(15:10:46.721) WiFi: drop: 11259
(15:10:46.721) WiFi: chkerr: 0
(15:10:46.721) WiFi: lenerr: 0
(15:10:46.721) WiFi: memerr: 0
(15:10:46.721) WiFi: rterr: 0
(15:10:46.721) WiFi: proterr: 11259
(15:10:46.721) WiFi: opterr: 0
(15:10:46.721) WiFi: err: 0
(15:10:46.721) WiFi: cachehit: 63985
(15:10:46.721) WiFi: 
(15:10:46.721) WiFi: xmit: 64376
(15:10:46.721) WiFi: recv: 42488
(15:10:46.721) WiFi: fw: 0
(15:10:46.721) WiFi: drop: 5660
(15:10:46.721) WiFi: chkerr: 0
(15:10:46.721) WiFi: lenerr: 0
(15:10:46.721) WiFi: memerr: 0
(15:10:46.721) WiFi: rterr: 0
(15:10:46.721) WiFi: proterr: 0
(15:10:46.721) WiFi: opterr: 0
(15:10:46.721) WiFi: err: 0
(15:10:46.721) WiFi: cachehit: 0
(15:10:46.721) WiFi: 
(15:10:46.721) WiFi: xmit: 323
(15:10:46.721) WiFi: recv: 309
(15:10:46.721) WiFi: drop: 0
(15:10:46.721) WiFi: chkerr: 0
(15:10:46.721) WiFi: lenerr: 0
(15:10:46.721) WiFi: memerr: 0
(15:10:46.721) WiFi: proterr: 0
(15:10:46.721) WiFi: rx_v1: 0
(15:10:46.721) WiFi: rx_group: 0
(15:10:46.721) WiFi: rx_general: 309
(15:10:46.721) WiFi: rx_report: 0
(15:10:46.721) WiFi: tx_join: 6
(15:10:46.721) WiFi: tx_leave: 4

[xnaron]

I am seeing it drop also with my new Duet Ethernet and agree it is more likely to drop when the printer is active printing.

Firmware Version: 1.20 (2017-12-23)
Web Interface Version: 1.20

[dc42]

@xnaron:

I am seeing it drop also with my new Duet Ethernet and agree it is more likely to drop when the printer is active printing.

Firmware Version: 1.20 (2017-12-23)
Web Interface Version: 1.20

If you have increased the microstepping, use M122 during or after printing to check that the MaxReps count isn't getting too high. If it gets too high then the network tasks can get can get starved of CPU cycles.

[xnaron]

"Communication Error"

"A communication error was reported, so the current session has been terminated. Please check you board and try to connect again."

"Error reason: Unknown request"

Duet Ethernet. M122 below. Microstepping is 16x with interpolation across all 4 drivers.

[[language]]
4:21:45 PMM122
=== Diagnostics ===
Used output buffers: 3 of 32 (13 max)
=== Platform ===
RepRapFirmware for Duet Ethernet version 1.20 running on Duet Ethernet 1.0
Board ID: 08DGM-95BNL-MGPSN-6JKF8-3SJ6L-11YRY
Static ram used: 11992
Dynamic ram used: 98680
Recycled dynamic ram: 4016
Stack ram used: 1216 current, 8472 maximum
Never used ram: 7912
Last reset 00:10:29 ago, cause: power up
Last software reset at 2018-01-17 14:21, reason: User, spinning module GCodes, available RAM 15976 bytes (slot 3)
Software reset code 0x0003 HFSR 0x00000000, CFSR 0x00000000, ICSR 0x0441f000, BFAR 0xe000ed38, SP 0xffffffff
Error status: 0
Free file entries: 9
SD card 0 detected, interface speed: 20.0MBytes/sec
SD card longest block write time: 348.3ms
MCU temperature: min 29.2, current 36.4, max 36.6
Supply voltage: min 23.8, current 24.1, max 24.4, under voltage events: 0, over voltage events: 0
Driver 0: ok, SG min/max 0/218
Driver 1: ok, SG min/max 0/212
Driver 2: standstill, SG min/max 34/216
Driver 3: ok, SG min/max 0/1023
Driver 4: standstill, SG min/max not available
Date/time: 2018-01-17 16:21:44
Cache data hit count 1099848700
Slowest main loop (seconds): 0.348692; fastest: 0.000045
=== Move ===
MaxReps: 3, StepErrors: 0, FreeDm: 207, MinFreeDm 150, MaxWait: 2928233205ms, Underruns: 23, 0
Scheduled moves: 9428, completed moves: 9417
Bed compensation in use: none
Bed probe heights: 0.000 0.000 0.000 0.000 0.000
=== Heat ===
Bed heaters = 0 -1 -1 -1, chamberHeaters = -1 -1
Heater 0 is on, I-accum = 0.1
Heater 1 is on, I-accum = 0.4
=== GCodes ===
Segments left: 1
Stack records: 1 allocated, 0 in use
Movement lock held by null
http is idle in state(s) 0
telnet is idle in state(s) 0
file is doing "G1 X161.519 Y144.421 E0.6619" in state(s) 0
serial is idle in state(s) 0
aux is idle in state(s) 0
daemon is idle in state(s) 0
queue is idle in state(s) 0
autopause is idle in state(s) 0
Code queue is empty.
=== Network ===
State: 5
HTTP sessions: 1 of 8
Responder states: HTTP(1) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
4:21:40 PMConnection established!
4:21:04 PMDisconnected.
4:13:45 PMM32 3DBenchy_195C.gcode
File 3DBenchy_195C.gcode selected for printing

[dc42]

I'll need to look up what that "Unknown request" message means.

[xnaron]

I'm trying 1.20 RC2 will see if it has the same issue.

[dc42]

The change between DuetWiFiServer 1.20 and 1.20+1 is probably more significant that the changes to DuetWiFiFirmware.

[kraegar]

Since updating to 1.20 release I'd started getting these. I did not get them running the earlier 1.20 betas (going by my downloads I used beta 1, 6 &10) I went to DuetWiFiServer 1.20+1 and 1.20.1RC and it actually seemed more frequent.

I'm now back to 1.20 for firmware, web, and wifi versions, and they're still happening every few minutes. It's the same error others are reporting in DWC: "The last HTTP request has timed out. Please make sure the connection between your device and the board is not interrupted."

Tomorrow I'll connect via usb and use M111 S1 P14 to grab some logs.