Timeout while waiting for transfer ready pin

achrn

Does anyone know what does this indicate (beyond the obvious that it lost connection to the Duet), and/or how do I troubleshoot and/or fix it:

07/11/2020, 19:25:24 	Error: G0/G1: insufficient axes homed
07/11/2020, 19:25:24 	Warning: Controller has been reset
07/11/2020, 19:25:24 	Connection to Duet established
07/11/2020, 19:25:06 	Warning: Lost connection to Duet (Timeout while waiting for transfer ready pin)
07/11/2020, 19:17:14 	Height map saved to file heightmap.csv
07/11/2020, 19:17:14 	45 points probed, min error -0.079, max error 0.008, mean -0.033, deviation 0.016
07/11/2020, 19:13:03 	M32 "0:/gcodes/top_encl_front_Delta 0.15_Delta PETG_Delta.gcode"
File 0:/gcodes/top_encl_front_Delta 0.15_Delta PETG_Delta.gcode selected for printing
07/11/2020, 19:13:02 	Upload of top_encl_front_Delta 0.15_Delta PETG_Delta.gcode successful after 1s

It's a MB6HC with Pi 4 (4GB) SBC, running firmware 3.1.1.

It lost connection just as it got to the end of the first layer, though I have also had the same on a smaller print at about layer 30.

At some point soon after it stopped printing the 24V power supply (which is switched by the pson pin) also went off for about half a second and came back on again. (The duet is powered by injecting 5V at the 5V/pson/GND connection, all jumpers are off the block near the middle of the board, the pson switches on the mains to a 24V PSU by a real relay with actual coil and flappy contact - I heard it clack-click).

I was running a python program that uses pydsfapi - it monitors the machine model and also every three seconds does a 'M573 P0' and immediately it gets the response to that does a 'M573 P1' to get heater power. Could that upset it?

The same routine is also writing to another SPI bus on the Pi - bus 1 device 0. I guess that could also be to blame.

Thanks.

A Former User

the timeout error means DuetControlServer was not able to see the TRF_RDY pin from the Duet and timed out, you could try to verify the state of the pin manually or refer to this thread for some ideas on how to test the pi side of the setup.

https://forum.duet3d.com/topic/15551/duet3-pi-dcs-is-unavailable-after-wiring-24v/120?_=1604779364666

achrn

@bearer Thanks, but my print job managed the first 2700 or so lines of gcode before coming up with this timeout, so I think it's not a hardware fault on the wires (or lack of functioning SPI device on the Pi). Would that many commands get transferred before the pin was in use?

A Former User

Its either a bug in the software or a hardware issue, it could be the Duet as well.

From the logs it seems it was reset and failed to connect after. I'd try the board without the Pi and test the Pi seperately to narrow in on where the fault is.

A Former User

Test the same file with the Duet in standalone mode to see if the file completes.

achrn

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.

wytechpw

@achrn had same error. I have 2 24v power units, one for board and one for bed. Just swapped outputs around and system now works ok