3.5.0b1+ Wifi error - SPI timeout

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

[StreetFurnitureAustralia]

@OwenD I can't replicate it but when it happens again then I can try and get it.

[StreetFurnitureAustralia]

@OwenD I'm not in the office but a colleague sent me thisreceived_6062637163802703.mp4

As you can see its being spammed

[OwenD]

@StreetFurnitureAustralia
That's the same behaviour
Can you try to get the reports as shown above and then roll the wifi back to 1.2.7
I haven't had a repeat since rolling back but it's infrequent for me, so I can't be sure it's the firmware

[StreetFurnitureAustralia]

@OwenD I will try just never don't this before, is there a way to log this via the duet webinterface and not need to connect a laptop directly?

[OwenD]

@StreetFurnitureAustralia
No, if the wifi module can't connect then the only way to get the info is via a terminal like YAT using the usb connection
If you roll back to 1.27 and have no further issues it's at least showing the same results as I'm getting
Maybe it's an Aussie only issue?
Wifi channel or something related?

[StreetFurnitureAustralia]

@OwenD could make sense, This is at my work and we use Unifi wifi gear. How about yourself?

[Aitor]

Good morning @dc42 ,

I would like to share my case in this post, I don't know if it will help.

After a while (X), usually the next day, my printer loses connection and I have to reset it to get a new IP address. In addition, it often changes IP addresses, and I have even been given IP addresses that have already been assigned to other Duets.

The commands I used to use to establish a connection no longer work:

M552 S-1
G4 S1
M552 S0
G4 S1
M552 S1

To solve this problem, I have had to use the following commands:

M552 S-1
G4 S1
M400
M552 S0
G4 S1
M400
M552 S1

If I don't perform these steps, sometimes I can't connect the printer. I suppose that these commands cannot be launched during a print to switch from M552 S1 to M552 S2 (although I haven't tried it).

Finally, I would like to share the results of M122 and the object model and M540 command, as I think this may be where one of the problems lies:

In M122, the MAC address is visible.
In the object model and the M540 command, the MAC address is "00:00:00:00:00:00".

6/4/2023, 12:19:43	M540
MAC: 00:00:00:00:00:00
6/4/2023, 12:04:07	M122
=== Diagnostics ===
RepRapFirmware for Duet 2 WiFi/Ethernet version 3.5beta2+ (2023-02-10 11:58:19) running on Duet WiFi 1.02 or later

=== Network ===
Slowest loop: 6.76ms; fastest: 0.00ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 1 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 e8:68:e7:79:5f:a3
WiFi Vcc 3.39, reset reason Turned on by main processor
WiFi flash size 2097152, free heap 43068
WiFi IP address 192.168.1.18
WiFi signal strength -54dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

[StreetFurnitureAustralia]

@OwenD I couldn't get the info due to time restraints at work but I have rolled it back.

[StreetFurnitureAustralia]

@OwenD @dc42 reverting back to 1.27 has made the SPI issue disappear for me.