Unsolved 3.5.0b1+ Wifi error - SPI timeout

[dc42]

@OwenD that depends on when you pulled the source files from github.

[OwenD]

@dc42 said in 3.5.0b1+ Wifi error - SPI timeout:

@OwenD that depends on when you pulled the source files from github.

It would have been the same day, but I'll revert and run another print just to be sure.

[OwenD]

@OwenD
I've run several prints with no re-occurrence of this issue, so I'll mark this as solved.
If it crops up again, I'll re-visit.

[OwenD]

Came home from work today to find this had re-occurred.
The printer has been idle for several days apart from some macro debugging last night.
When it occurs the PanelDue is flooded with error messages at a very high rate.
Connected by USB and got an M122 report.

ror: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
M122
=== Diagnostics ===
RepRapFirmware for Duet 2 WiFi/Ethernet version 3.5beta1+ (2022-12-31 17:10:26) running on Duet WiFi 1.02 or later
Board ID: 08DGM-917NK-F2MS4-7J1DA-3S86T-TZTWD
Used output buffers: 1 of 26 (26 max)
=== RTOS ===
Static ram: 22148
Dynamic ram: 79236 of which 216 recycled
Never used RAM 4712, free system stack 192 words
Tasks: NETWORK(notifyWait,37.1%,233) ACCEL(notifyWait,0.0%,348) HEAT(notifyWait,0.6%,330) Move(notifyWait,0.1%,362) MAIN(running,60.8%,331) IDLE(ready,1.6%,30), total 100.0%
Owned mutexes: WiFi(NETWORK) USB(MAIN)
=== Platform ===
Last reset 23:57:15 ago, cause: software
Last software reset at 2023-01-19 19:22, reason: User, GCodes spinning, available RAM 8228, slot 2
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00400000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x00
Aux0 errors 0,0,0
Step timer max interval 0
MCU temperature: min 27.3, current 29.4, max 34.3
Supply voltage: min 0.4, current 0.5, max 0.5, under voltage events: 0, over voltage events: 0, power good: no
Heap OK, handles allocated/used 297/195, heap memory allocated/used/recyclable 4096/3648/484, gc cycles 89
Events: 0 queued, 0 completed
Driver 0: ok, SG min n/a
Driver 1: ok, SG min n/a
Driver 2: ok, SG min n/a
Driver 3: ok, SG min n/a
Driver 4: ok, SG min n/a
Driver 5: 
Driver 6: 
Driver 7: 
Driver 8: 
Driver 9: 
Driver 10: 
Driver 11: 
Date/time: 2023-01-20 19:19:46
Cache data hit count 4294967295
Slowest loop: 97.05ms; fastest: 0.07ms
I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0
=== Storage ===
Free file entries: 10
SD card 0 detected, interface speed: 20.0MBytes/sec
SD card longest read time 4.8ms, write time 131.9ms, max retries 0
=== Move ===
DMs created 83, segments created 0, maxWait 0ms, bed compensation in use: none, comp offset 0.000
no step interrupt scheduled
=== DDARing 0 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
=== GCodes ===
Movement locks held by null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is ready with "M122" in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
Daemon is idle in state(s) 0
Autopause is idle in state(s) 0
Q0 segments left 0
Code queue 0 is empty
=== Filament sensors ===
Extruder 0 sensor: ok
=== Network ===
Slowest loop: 523.09ms; fastest: 0.00ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 0 of 8
= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 5, noresp 775826
Error: failed to retrieve WiFi status message: SPI timeout
Failed to get WiFi status
Socket states: 0 0 0 0 0 0 0 0
ok
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout
Error: failed to retrieve WiFi status message: SPI timeout

[jay_s_uk]

@OwenD before you reset could you try activating wifi debugging over USB?
M111 P14 S1

[OwenD]

@jay_s_uk
Will do.
Not sure how long it will take before it will occur again.

[T3P3Tony]

@OwenD also it would be helpful to get a summary of how (in)frequently this occurs and confirmation of the firmware and wifi firmware versions running.

[dc42]

@OwenD version 2.1beta2 of DuetWiFiSocketServer has been replaced by 2.1beta3 available at https://github.com/Duet3D/WiFiSocketServerRTOS/releases/tag/2.1beta3.

[OwenD]

@dc42 @T3P3Tony

I'm afraid I haven't been able to reproduce this and I can't determine one factor that has "fixed" it.
I do have a few observations.
I used to get the occasional message on PanelDue that said that the WiFi had been successfully reconnected.
This is a modal message, so it could have happened at any time and I wouldn't see it until I went to the shed.
My wifi signal in the shed has always been around -51db, not horrible, but not great either.
After this issue arose, I went and got a wifi range extender.
This boosted the signal to around -41 to -44db
Note: That I hadn't had a re-occurrence BEFORE I put the extender on.
I don't know what signal I showed with 2.1beta2 as it didn't report it.

I just installed 2.1beta3
My first M122 showed a signal of -36db with the extender!

= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 2.1beta3
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.38, reset reason Power up
WiFi flash size 2097152, free heap 39380
WiFi IP address 192.168.1.163
WiFi signal strength -36dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

I then went back in versions and did reports on each, both with and without the extender.

No extender

= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 2.1beta3
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.38, reset reason Turned on by main processor
WiFi flash size 2097152, free heap 39440
WiFi IP address 192.168.1.163
WiFi signal strength -41dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

No extender

= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 1.27
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.38, reset reason Power up
WiFi flash size 4194304, free heap 23776
WiFi IP address 192.168.1.163
WiFi signal strength -51dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

No extender

= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 2.1beta3
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.38, reset reason Turned on by main processor
WiFi flash size 2097152, free heap 40992
WiFi IP address 192.168.1.163
WiFi signal strength -44dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

With extender

= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 2.1beta3
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.38, reset reason Turned on by main processor
WiFi flash size 2097152, free heap 38844
WiFi IP address 192.168.1.163
WiFi signal strength -37dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

I'm not sure how the firmware version can increase the signal so dramatically?

I'm inclined to mark this as solved again simply because I can't repeat it reliably, so if nobody else is complaining it's not worth chasing.

[dc42]

@OwenD thanks for reporting this. Versions 1.x and 2.x of the WiFi firmware use different versions of the Expressif SDK. I guess either one of those SDK versions is mis-reporting RSSI, or they have changed the interface and we didn't pick that up. I will check the version 2.x code.

[OwenD]

So for some reason this has reared it's head again a couple of times lately.
My system has a 5v power supply which powers the duet and switches a 24 volt power supply via the ATX pin as required.
Before resetting I ran M111 P14 S1, then M122
YAT seems to have dumped that report due to the volume of lines added, so I've only got the report immediately after restarting.

For some reason the MCU voltage shows a very low value until I run M80 and kick the 24v power supply into action. Not sure if that's related.
It does the same regardless of this wifi anomaly.

Error: failed to retrieve WiFi status message: SPI timeout
ResponseTimeout, pending=1
ESP reported status change
ResponseTimeout, pending=1
Error: failed to retrieve WiFi status message: SPI timeout
ResponseTimeout, pending=1
ESP reported status change
ResponseTimeout, pending=1
Error: failed to retrieve WiFi status message: SPI timeout
ResponseTimeout, pending=1
ESP reported status change
ResponseTimeout, pending=1
Error: failed to retrieve WiFi status message: SPI timeout
M111 P14 S1
Debugging enabled for modules: WiFi(14 - 0xffffffff)
Debugging disabled for modules: Platform(0) Network(1) Webserver(2) Gcodes(3) Move(4) Heat(5) Dda(6) unused1(7) unused2(8) PrintMonitor(9) Storage(10) PortControl(11) DuetExpansion(12) FilamentSensors(13) Display(15) SbcInterface(16) Can(17)
M122
=== Diagnostics ===
RepRapFirmware for Duet 2 WiFi/Ethernet version 3.5beta2+ (2023-02-12 12:52:31) running on Duet WiFi 1.02 or later
Board ID: 08DGM-917NK-F2MS4-7J1DA-3S86T-TZTWD
Used output buffers: 1 of 26 (11 max)
=== RTOS ===
Static ram: 22216
Dynamic ram: 79456 of which 12 recycled
Never used RAM 8284, free system stack 184 words
Tasks: NETWORK(ready,10.9%,377) ACCEL(notifyWait,0.0%,348) HEAT(notifyWait,0.0%,327) Move(notifyWait,0.0%,361) MAIN(running,87.9%,502) IDLE(ready,1.1%,30), total 100.0%
Owned mutexes: WiFi(NETWORK) USB(MAIN)
=== Platform ===
Last reset 00:01:21 ago, cause: power up
Last software reset at 2023-02-15 03:34, reason: StuckInSpinLoop, Platform spinning, available RAM 7040, slot 0
Software reset code 0x4080 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0040080f BFAR 0xe000ed38 SP 0x20003014 Task NETW Freestk 488 ok
Stack: 00414fdf 00459cc2 010f0000 e8000000 400985ff 41c475a6 3edb9368 3331bb4c 40000000 b5ddd8b0 388ab355 bb360b61 3e2aaaab 3f800000 3f800000 41d94ba3 4354c416 41200000 3f800000 80000010 00414fa5 b5ddd8b0 388ab355 20010fbc 3e2aaa01 3f800000 20011248
Error status: 0x00
Aux0 errors 0,0,0
Step timer max interval 0
MCU temperature: min 29.3, current 33.6, max 33.8
Supply voltage: min 0.3, current 0.5, max 0.5, under voltage events: 0, over voltage events: 0, power good: no
Heap OK, handles allocated/used 99/15, heap memory allocated/used/recyclable 2048/384/116, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: ok, SG min n/a
Driver 1: ok, SG min n/a
Driver 2: ok, SG min n/a
Driver 3: ok, SG min n/a
Driver 4: ok, SG min n/a
Driver 5: 
Driver 6: 
Driver 7: 
Driver 8: 
Driver 9: 
Driver 10: 
Driver 11: 
Date/time: 1970-01-01 00:00:00
Cache data hit count 3368987419
Slowest loop: 7.82ms; fastest: 0.14ms
I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0
=== Storage ===
Free file entries: 10
SD card 0 detected, interface speed: 20.0MBytes/sec
SD card longest read time 1.0ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 83, segments created 0, maxWait 0ms, bed compensation in use: none, comp offset 0.000
no step interrupt scheduled
=== DDARing 0 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
=== GCodes ===
Movement locks held by null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is ready with "M122" in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
Daemon is idle in state(s) 0
Autopause is idle in state(s) 0
Q0 segments left 0
Code queue 0 is empty
=== Filament sensors ===
Extruder 0 sensor: ok
=== Network ===
Slowest loop: 7.76ms; fastest: 0.00ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 0 of 8
= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 2.1beta3
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.39, reset reason Power up
WiFi flash size 2097152, free heap 45652
WiFi IP address 192.168.1.163
WiFi signal strength -29dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0
ok
WiFi: <ESC>[0mConns: 0:free, 1:free, 2:free, 3:free, 4:free, 5:free, 6:free, 7:free

[OwenD]

Some more info this morning.
Normally I discover this problem either when I walk out to the garage to get a beer and see the PanelDue flashing ans SPI error, or I can't connect to DWC.
This morning I opened my phone (to a previously open tab) and DWC was frozen.
When I tried refreshing, it just said connecting and that the drive wasn't mounted.

Suspecting an SD card issue, I checked the PanelDue wasn't displaying any errors.
Sending M20 resulted in a normal listing, so the SD card has to be mounted.
Maybe this is a red herring?
DWC from my laptop just doesn't connect. "Can't find host"

M20
Begin file list
random-moves-test.g
Outer_Trays_0.2mm_PLA.gcode
freak_Pin_0.14mm_PA-CF.gcode
Inner_Trays_0.2mm_PLA.gcode
SKEW_100mm_0.2mm_PLA.gcode
cube_0.2mm_PLA.gcode
Freak body large skirt_0.2mm_PA-CF.gcode
YACS_0.2mm_PLA.gcode
calibration_0.2mm_PLA.gcode
monitor-pad-right_0.2mm_PLA.gcode
calibration piece _0.2mm_PLA.gcode
Box1_0.2mm_PLA.gcode
EspChunky_0.2mm_PA-CF.gcode
pump-filter_0.2mm_PA-CF.gcode
End file list

If I send M111 P14 S1, I immediately get a barrage of busy responses in YAT .

M111 P14 S1
Debugging enabled for modules: WiFi(14 - 0xffffffff)
Debugging disabled for modules: Platform(0) Network(1) Webserver(2) Gcodes(3) Move(4) Heat(5) Dda(6) unused1(7) unused2(8) PrintMonitor(9) Storage(10) PortControl(11) DuetExpansion(12) FilamentSensors(13) Display(15) SbcInterface(16) Can(17)
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
ResponseBusy
M111 S0
ok

If I try to do a network scan I get this

M587.1
Error: M587.1: failed to start scan: another SPI transfer is pending

[Phaedrux]

Can you try flashing back to 1.27 and seeing if this still happens? If so, I think it may be the module.

[OwenD]

@Phaedrux
Can't rule out a hardware issue I guess.
Have reverted back to 1.27 and will monitor.
I did an M122 before and after the change.
This is the network section. Note the not ready number and lack of IP address.

=== Network ===
Slowest loop: 29273.09ms; fastest: 100.43ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 0 of 8
= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 42217, noresp 1
Failed to get WiFi status
Socket states: 6 0 0 0 0 0 0 0

After reverting and restart.

= WiFi =
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 2
WiFi firmware version 1.27
WiFi MAC address bc:dd:c2:89:a0:bb
WiFi Vcc 3.38, reset reason Power up
WiFi flash size 4194304, free heap 24848
WiFi IP address 192.168.1.163
WiFi signal strength -35dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

[StreetFurnitureAustralia]

Hi, I have also been getting instability issue with the wifi since going to 3.5.0b1.

The duet will drop off from the network midprint or even not connect at all unless i power it down and then back up.

[OwenD]

@StreetFurnitureAustralia
Are you getting the same SPI timeout messages noted in this thread?
Can you connect via USB and grab the same reports as above?
My error is quite random and very specific.
It has not reappeared since rolling the wifi back to 1.27 but it only happened occasionally so I'm not ready to say it's definitely firmware yet.