To recap:
I'm running a function on the Pi (via pydsfapi) that periodically excutes a M573 P0 and a M573 P1. If that function is running, then the print job fails at some point (or rather, it has every time the dozen or so times I've tried). If that function is not running the print completes (or rather, it has every time the three times I've tried). I therefore don't believe that running standalone tells me anything - the problem does not seem to actually be connectivity of wires.
I was also putting data on the Pi's SPI bus 1, but I'm now confident that's not the problem - I set up a test case where I hammered SPI bus 1 hard (about ten times more data through it than my actual running case) and the print job completed when M573 were not running. When I run with the M573 but without any data going out SPI bus 1 it fails.
Should I be able to fire a M573 at the Duet regularly (two every three seconds) while the duet is running a print job? Or am I doing something unreasonable?
I ran DCS with -l debug and at the failure point I get this:
[debug] File: Sent G1 X-103.971 Y-101.262 E0.01481, remaining space 80, needed 48
[debug] Completed G1 X-80.988 Y-83.250 E0.05486 =>
[debug] Waiting for execution of G1 X-103.537 Y-101.695 E0.01658
[debug] Processing G1 X-103.537 Y-101.695 E0.01658
[debug] Waiting for finish of G1 X-103.537 Y-101.695 E0.01658
[debug] File: Sent G1 X-103.537 Y-101.695 E0.01658, remaining space 32, needed 48
[debug] IPC#12: Received command SimpleCode
[debug] Waiting for execution of M573 P0
[debug] Processing M573 P0
[debug] Waiting for finish of M573 P0
[debug] Completed G1 X-80.590 Y-83.562 E0.01318 =>
[debug] SBC: Sent M573 P0, remaining space 1504, needed 32
[debug] Waiting for execution of G1 X-104.085 Y-101.695 E0.01481
[debug] Processing G1 X-104.085 Y-101.695 E0.01481
[debug] Waiting for finish of G1 X-104.085 Y-101.695 E0.01481
[debug] Completed G1 X-90.554 Y-83.562 E0.25963 =>
[debug] Waiting for execution of G1 X-103.652 Y-102.129 E0.01658
[debug] File: Sent G1 X-104.085 Y-101.695 E0.01481, remaining space 128, needed 48
[debug] Completed G1 X-96.125 Y-89.133 E0.20528 =>
[debug] Processing G1 X-103.652 Y-102.129 E0.01658
[debug] Waiting for execution of G1 X-103.104 Y-102.129 E0.01481
[debug] Waiting for finish of G1 X-103.652 Y-102.129 E0.01658
[debug] Processing G1 X-103.104 Y-102.129 E0.01481
[debug] Waiting for finish of G1 X-103.104 Y-102.129 E0.01481
[debug] File: Sent G1 X-103.652 Y-102.129 E0.01658, remaining space 80, needed 48
[debug] File: Sent G1 X-103.104 Y-102.129 E0.01481, remaining space 32, needed 48
[debug] Completed M573 P0 => Average heater 0 PWM: 0.154
[debug] IPC#12: Received command SimpleCode
[debug] Waiting for execution of M573 P1
[debug] Processing M573 P1
[debug] Waiting for finish of M573 P1
[debug] SBC: Sent M573 P1, remaining space 1504, needed 32
[debug] Completed M573 P1 => Average heater 1 PWM: 0.506
[debug] Completed G1 X-77.616 Y-89.133 E0.48226 =>
[debug] Waiting for execution of G1 X-102.670 Y-102.562 E0.01658
[debug] Processing G1 X-102.670 Y-102.562 E0.01658
[debug] Waiting for finish of G1 X-102.670 Y-102.562 E0.01658
[debug] File: Sent G1 X-102.670 Y-102.562 E0.01658, remaining space 32, needed 48
[debug] Completed G1 X-83.187 Y-94.704 E0.20528 =>
[debug] Waiting for execution of G1 X-103.218 Y-102.562 E0.01481
[debug] Processing G1 X-103.218 Y-102.562 E0.01481
[debug] Waiting for finish of G1 X-103.218 Y-102.562 E0.01481
[debug] File: Sent G1 X-103.218 Y-102.562 E0.01481, remaining space 32, needed 48
[debug] Completed G1 X-101.696 Y-94.704 E0.48226 =>
[debug] Waiting for execution of G1 X-102.785 Y-102.996 E0.01658
[debug] Processing G1 X-102.785 Y-102.996 E0.01658
[debug] Waiting for finish of G1 X-102.785 Y-102.996 E0.01658
[debug] File: Sent G1 X-102.785 Y-102.996 E0.01658, remaining space 36, needed 44
[debug] Lost connection to Duet
System.OperationCanceledException: Timeout while waiting for transfer ready pin
at DuetControlServer.SPI.DataTransfer.WaitForTransfer() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1063
at DuetControlServer.SPI.DataTransfer.ExchangeResponse(UInt32 response) in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1184
at DuetControlServer.SPI.DataTransfer.ExchangeHeader() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1142
at DuetControlServer.SPI.DataTransfer.PerformFullTransfer(Boolean connecting) in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 162
[warn] Lost connection to Duet (Timeout while waiting for transfer ready pin)
[warn] Bad header checksum (expected 0xffff, got 0x64a1)
[debug] Lost connection to Duet
System.OperationCanceledException: Timeout while waiting for transfer ready pin
at DuetControlServer.SPI.DataTransfer.WaitForTransfer() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1063
at DuetControlServer.SPI.DataTransfer.ExchangeResponse(UInt32 response) in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1184
at DuetControlServer.SPI.DataTransfer.ExchangeHeader() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1100
at DuetControlServer.SPI.DataTransfer.PerformFullTransfer(Boolean connecting) in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 162
[debug] Lost connection to Duet
System.OperationCanceledException: Timeout while waiting for transfer ready pin
at DuetControlServer.SPI.DataTransfer.WaitForTransfer() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1063
at DuetControlServer.SPI.DataTransfer.ExchangeHeader() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1078
at DuetControlServer.SPI.DataTransfer.PerformFullTransfer(Boolean connecting) in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 162
The line at line 1 of that snippet is line 13,870 of the gcode file, so it has done a fair amount of printing at this point.
Lines 7 and 28 of the above are where it gets the M573 commands from my parallel routine which must be causing this problem, but don't seem to me to be immediately precipitating it - the Duet completes another few G1 commands before it actually packs up (or am I mis-reading that?)
I note that the last block of Timeout while waiting for transfer ready pin traceback above have different line numbers to the first two blocks. The 1063 / 1078 / 162 numbers repeat for a couple of hundred lines, then I get:
[debug] Lost connection to Duet
System.OperationCanceledException: Board is not available (no header)
at DuetControlServer.SPI.DataTransfer.ExchangeHeader() in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 1093
at DuetControlServer.SPI.DataTransfer.PerformFullTransfer(Boolean connecting) in /home/christian/Duet3D/DuetSoftwareFramework/src/DuetControlServer/SPI/DataTransfer.cs:line 162
These line numbers (1093 / 162) repeat for about 150 lines, then I get:
[info] Connection to Duet established
[debug] Cancelled G1 X-92.582 Y-102.416 E0.01825
[debug] Cancelled G1 X-105.817 Y-98.825 E0.15186
[warn] Controller has been reset
[debug] Cancelled G1 X-104.838 Y-100.394 E0.01481
[debug] Cancelled G1 X-102.670 Y-102.562 E0.01658
[debug] Cancelled G1 X-93.037 Y-101.961 E0.01265
[debug] Cancelled G1 X-104.519 Y-101.262 E0.01658
[debug] Cancelled G1 X-92.137 Y-102.416 E0.01265
[debug] Cancelled G1 X-92.128 Y-102.871 E0.02019
[debug] Cancelled G1 F3000.000
[debug] Cancelled G1 X-92.591 Y-101.961 E0.01825
[debug] Cancelled G1 X-105.705 Y-99.527 E0.02200
[debug] Cancelled G1 X-91.416 Y-102.871 F7200.000
[debug] Cancelled G1 X-88.492 Y-100.274 E0.41365
[info] Starting macro file config.g on channel Trigger
[debug] Cancelled G1 X-104.367 Y-100.274 E0.05342
[debug] Cancelled G1 X-103.537 Y-101.695 E0.01658
[debug] Waiting for execution of M550 P"duet3" (macro code)
[debug] Waiting for execution of M905 P"2020-11-11" S"20:24:21" (macro code)
[debug] Processing M550 P"duet3"
[debug] Waiting for execution of ; Configuration file for Duet 3 (firmware version 3) (macro code)
[debug] Waiting for finish of M550 P"duet3"
[debug] Waiting for execution of ; initially generated by RepRapFirmware Configuration Tool v3.1.4 on Thu Sep 17 2020 20:49:45 (macro code)
and from here my config.g loads up happily and everything returns to normal.
My parallel routine is (now) simple. Having pared it down to work out what is causing teh problem, this casues a failure such as described above, every time:
#!/usr/bin/python3
# monitor heater duty
# this is interval of getting heater pwm
hpwmInt=3
import time
from pydsfapi import pydsfapi
from pydsfapi.initmessages.clientinitmessages import SubscriptionMode
# establish the connection
command_connection = pydsfapi.CommandConnection(debug=True)
command_connection.connect()
# heaters to monitor
numh=2
try:
# Get updates
while True:
time.sleep(hpwmInt - time.time()%hpwmInt)
print()
print(time.asctime())
for h in range(numh):
# M573 response for each heater - split off last word (which is value required)
hpwm_str=command_connection.perform_simple_code('M573 P'+str(h))
hpwm=float(hpwm_str.split()[-1])
print(str(h) + ': ' + str(hpwm))
finally:
command_connection.close()
Thanks.