Still having issues with Cancel in DSF 1.2.2.0

gtjoseph commented 4 years ago

Pause is no longer executing moves from the buffer but Cancel still is.

You might want to leave this one open until I can confirm it's actually fixed. :)

chrishamm commented 4 years ago

Can you give me an example for this? I can pause/cancel a print and no extra codes from the buffer are executed. Also, the code in DSF makes sure pending codes are cancelled.

There is one thing I've just spotted and it's a missing error message in DSF in case a user tries to cancel a print without pausing it first (unless M0/1 is called from the file itself) so I'll fix that in the next version.

gtjoseph commented 4 years ago

I think that noticing it depends on the code that's left in the buffer, if you're printing a radius with tons of segments, you probably won't notice the extra move because it's so tiny. If you're printing something that has long moves it's much more obvious. Try printing a large square and see what happens. In the mean time, I'll up the log level on the DCS and see if I can capture the extra codes.

chrishamm commented 4 years ago

I'm sorry but I have not been able to provoke this behavior once. Perhaps it was somehow related to the out-of-order execution you reported in another ticket but I took the time to review everything related to cancelling in DSF and RRF and yet I could not find one potential place that could explain this. Of course I made a new G-code file with long moves as well and tried to reproduce it by pausing/resuming/cancelling that file various times but it always worked as expected on my setup.

Please check if DSF 1.2.3 solves this problem and if it does not, please provide accurate instructions on how this can be reproduced.

gtjoseph commented 4 years ago

I meant to create a test gcode file over the weekend but didn't get to it. I'll do it on 1.2.2.0 first then try 1.2.3.

gtjoseph commented 4 years ago

Still having the issue with 1.2.3.0. Here's some output from the DCS. Not sure if that warning is significant or not.

[debug] Cancelled G1 X35.642 Y61.384
[info] Executing nested macro file pause.g on channel HTTP
[debug] ==> Starting code: M25
[debug] Waiting for execution of ; pause.g (type 1)
[debug] Processing ; pause.g
[debug] Completed ; pause.g
[debug] Waiting for execution of ; called when a print from SD card is paused (type 1)
[debug] Processing ; called when a print from SD card is paused
[debug] Completed ; called when a print from SD card is paused
[debug] Waiting for execution of G91; relative positioning (type 1)
[debug] Processing G91; relative positioning
[debug] Waiting for execution of G1 Z5 F600; lift Z by 5mm (type 1)
[debug] Processing G1 Z5 F600; lift Z by 5mm
[debug] HTTP: Sent G91; relative positioning, remaining space 1516, needed 20
[debug] HTTP: Sent G1 Z5 F600; lift Z by 5mm, remaining space 1480, needed 36
[debug] HTTP: Finished macro file pause.g
[debug] Completed G1 Z5 F600; lift Z by 5mm
[debug] Completed G91; relative positioning
[info] HTTP: Finished macro file pause.g
[debug] Completed M25 => Printing paused at X39.4 Y83.6 Z10.0
[debug] HTTP: ==> Starting code: M25 => Printing paused at X39.4 Y83.6 Z10.0
[debug] IPC#26: Connection closed
[debug] IPC#27: Got new UNIX connection, checking mode...
[debug] IPC#27: Command processor added
[debug] IPC#27: Received command SimpleCode
[debug] Waiting for execution of M0 H1
[debug] Processing M0 H1
[info] Cancelled print file
[debug] HTTP: Sent M0 H1, remaining space 1508, needed 28
[info] Cancelled printing file 0:/gcodes/sr.gcode, print time was 0h 0m
[warn] File: Out-of-order reply: ''
[info] Executing nested macro file stop.g on channel HTTP
[debug] ==> Starting code: M0 H1
[debug] Waiting for execution of ; stop.g (type 1)
[debug] Processing ; stop.g
[debug] Completed ; stop.g
[debug] Waiting for execution of ; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled) (type 1)
[debug] Processing ; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled)
[debug] Completed ; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled)
[debug] Waiting for execution of G91; relative positioning (type 1)
[debug] Processing G91; relative positioning
[debug] Waiting for execution of G1 Z5 F600; lift Z by 5mm (type 1)
[debug] HTTP: Sent G91; relative positioning, remaining space 1516, needed 20
[debug] Processing G1 Z5 F600; lift Z by 5mm
[debug] HTTP: Sent G1 Z5 F600; lift Z by 5mm, remaining space 1480, needed 36
[debug] Completed G91; relative positioning
[debug] HTTP: Finished macro file stop.g
[debug] Completed G1 Z5 F600; lift Z by 5mm
[info] HTTP: Finished macro file stop.g
[debug] Completed M0 H1
[debug] HTTP: ==> Starting code: M0 H1

And here's the gcode file I was printing. It's a stripped version of a real print file but without any extrusion or heat, etc. so it's safe to run. It just prints some rounded corner rectangles. Start it printing and give it about 15-20 seconds and pause with just an M25, then wait a few seconds and cancel with an M0 H1. At the very least, you should see the XY position display change and if the pause is executed as the printer is about to print one of the sides, you'll see the carriage change actual position.

sr.gcode.txt

My stop.g and pause.g are simple...

G91            ; relative positioning
G1 Z5 F600     ; lift Z by 5mm

chrishamm commented 4 years ago

Thanks for the feedback but I'm afraid the log does not really explain why you are encountering this issue. There are no more File codes (in whatever order) sent to the printer when M25 is called. Also I cannot spot any out-of-order execution of the macro files.

Can you please flash the latest RRF3 firmware binary from dc42's repository and enable debugging for the GCodes module via M111 P3 S1 if this problem persists? There was definitely an issue with out-of-order replies in previous firmware versions but AFAICT it has been fixed in the latest one.

The only thing I find surprising is that there is no "Print has been paused at byte xxx" in the log. Was it perhaps somewhere else in your log? At the time this message is printed, RRF's internal code buffer is invalidated and pending codes are thrown away.

gtjoseph commented 4 years ago

Sorry... Here's what was leading up to the log I pasted above...

[debug] Waiting for execution of G1 X35.642 Y61.384
[debug] Processing G1 X35.642 Y61.384
[debug] File: Sent G1 X37.343 Y77.996, remaining space 852, needed 36
[debug] File: Sent G1 X36.859 Y77.195, remaining space 816, needed 36
[debug] File: Sent G1 X36.772 Y77.036, remaining space 780, needed 36
[debug] File: Sent G1 X36.534 Y76.547, remaining space 744, needed 36
[debug] File: Sent G1 X36.462 Y76.380, remaining space 708, needed 36
[debug] File: Sent G1 X36.141 Y75.534, remaining space 672, needed 36
[debug] File: Sent G1 X36.084 Y75.361, remaining space 636, needed 36
[debug] File: Sent G1 X35.938 Y74.837, remaining space 600, needed 36
[debug] File: Sent G1 X35.898 Y74.660, remaining space 564, needed 36
[debug] File: Sent G1 X35.729 Y73.741, remaining space 528, needed 36
[debug] File: Sent G1 X35.700 Y73.501, remaining space 492, needed 36
[debug] File: Sent G1 X35.645 Y72.596, remaining space 456, needed 36
[debug] File: Sent G1 X35.642 Y72.476, remaining space 420, needed 36
[debug] File: Sent G1 X35.642 Y61.384, remaining space 384, needed 36
[debug] IPC#26: Got new UNIX connection, checking mode...
[debug] IPC#26: Command processor added
[debug] IPC#26: Received command SimpleCode
[debug] Waiting for execution of M25
[debug] Processing M25
[debug] HTTP: Sent M25, remaining space 1516, needed 20
[info] Print paused at file position 3511. Reason: User
[debug] Print has been paused at byte 3511
[debug] Cancelled G1 X40.365 Y82.920
[debug] Cancelled G1 X41.401 Y82.360
[debug] Cancelled G1 X41.565 Y82.283
[debug] Cancelled G1 X42.067 Y82.075
[debug] Cancelled G1 X42.237 Y82.013
[debug] Cancelled G1 X42.537 Y81.919
[debug] Cancelled G1 X42.124 Y81.777
[debug] Cancelled G1 X41.955 Y81.710
[debug] Cancelled G1 X41.101 Y81.326
[debug] Cancelled G1 X40.887 Y81.213
[debug] Cancelled G1 X40.571 Y82.795
[debug] Cancelled G1 X40.061 Y80.714
[debug] Cancelled G1 X39.101 Y79.980
[debug] Cancelled G1 X38.920 Y79.820
[debug] Cancelled G1 X38.237 Y79.137
[debug] Cancelled G1 X38.076 Y78.956
[debug] Cancelled G1 X37.480 Y78.195
[debug] Cancelled G1 X37.343 Y77.996
[debug] Cancelled G1 X36.859 Y77.195
[debug] Cancelled G1 X36.772 Y77.036
[debug] Cancelled G1 X36.534 Y76.547
[debug] Cancelled G1 X39.862 Y80.576
[debug] Cancelled G1 X36.462 Y76.380
[debug] Cancelled G1 X36.141 Y75.534
[debug] Cancelled G1 X36.084 Y75.361
[debug] Cancelled G1 X35.938 Y74.837
[debug] Cancelled G1 X35.898 Y74.660
[debug] Cancelled G1 X35.729 Y73.741
[debug] Cancelled G1 X35.645 Y72.596
[debug] Cancelled G1 X35.700 Y73.501
[debug] Cancelled G1 X35.642 Y72.476
[debug] Cancelled G1 X35.642 Y61.384
[info] Executing nested macro file pause.g on channel HTTP

Still have the issue with @dc42 's 3.0 pre-built binary.

Attempting to print with M111 P3 S1 enabled results in the Duet3 hanging and needint a reset.

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC v0.6 or 1.0 version 3.0 running on Duet 3 MB6HC
Board ID: 08DGM-9T66A-G63SJ-6J9F4-3SD6S-1U03B
Used output buffers: 1 of 32 (8 max)
=== RTOS ===
Static ram: 152720
Dynamic ram: 150204 of which 0 recycled
Exception stack ram used: 292
Never used ram: 90000
Tasks: NETWORK(ready,1984) HEAT(blocked,820) CanReceiv(suspended,3808) CanSender(suspended,1476) CanClock(blocked,1424) TMC(blocked,212) MAIN(running,4156) IDLE(ready,160)
Owned mutexes:
=== Platform ===
Last reset 00:00:13 ago, cause: reset button
Last software reset time unknown, reason: User, spinning module LinuxInterface, available RAM 91776 bytes (slot 1)
Software reset code 0x0010 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0444a000 BFAR 0x00000000 SP 0xffffffff Task 0x4e49414d
Error status: 0
Free file entries: 10
SD card 0 not detected, interface speed: 37.5MBytes/sec
SD card longest block write time: 0.0ms, max retries 0
MCU temperature: min 35.1, current 36.3, max 36.4
Supply voltage: min 15.8, current 25.2, max 25.6, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.2, current 12.2, max 12.2, under voltage events: 0
Driver 0: standstill, reads 65445, writes 14 timeouts 0, SG min/max 0/0
Driver 1: standstill, reads 65446, writes 14 timeouts 0, SG min/max 0/0
Driver 2: standstill, reads 65446, writes 14 timeouts 0, SG min/max 0/0
Driver 3: standstill, reads 65447, writes 14 timeouts 0, SG min/max 0/0
Driver 4: standstill, reads 65447, writes 14 timeouts 0, SG min/max 0/0
Driver 5: standstill, reads 65448, writes 14 timeouts 0, SG min/max 0/0
Date/time: 2020-01-07 18:34:42
Slowest loop: 2.48ms; fastest: 0.09ms
=== Move ===
Hiccups: 0(0), FreeDm: 375, MinFreeDm: 375, MaxWait: 0ms
Bed compensation in use: none, comp offset 0.000
=== MainDDARing ===
Scheduled moves: 0, completed moves: 0, StepErrors: 0, LaErrors: 0, Underruns: 0, 0
=== AuxDDARing ===
Scheduled moves: 0, completed moves: 0, StepErrors: 0, LaErrors: 0, Underruns: 0, 0
=== Heat ===
Bed heaters = 0 -1 -1 -1 -1 -1 -1 -1 -1, chamberHeaters = -1 -1 -1 -1
=== GCodes ===
Segments left: 0
Stack records: 2 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 idle in state(s) 0
serial is idle in state(s) 0
aux is idle in state(s) 0
daemon* is ready with "M122" in state(s) 0
queue is idle in state(s) 0
lcd is idle in state(s) 0
spi is idle in state(s) 0
autopause is idle in state(s) 0
Code queue is empty.
=== Network ===
Slowest loop: 0.46ms; fastest: 0.01ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0) Telnet(0)
HTTP sessions: 0 of 8
- Ethernet -
State: 0
Error counts: 0 0 0 0 0
Socket states: 0 0 0 0 0 0 0 0
=== CAN ===
Messages sent 53, longest wait 0ms for type 0
=== Linux interface ===
State: 0, failed transfers: 0
Last transfer: 16ms ago
RX/TX seq numbers: 9637/446
SPI underruns 0, overruns 0
Number of disconnects: 0
Buffer RX/TX: 0/0-0
=== Duet Control Server ===
Duet Control Server v1.2.3.0
Code buffer space: 4096
Configured SPI speed: 2000000 Hz
Full transfers per second: 16.84

chrishamm commented 4 years ago

Yes, that's all looking good. DCS stops sending instructions to the firmware when it is supposed to and RRF throws away the pending codes at the right time. At present I have no explanation why you are seeing additional movement when the print is cancelled.

You need to hook up the Pi or a PC to the USB port of the Duet 3 and record the USB log once debugging via M111 has been enabled. If you are using DuetPi, you only need to start minicom.

Can you add M122 to pause.g and send me the output, too?

gtjoseph commented 4 years ago

M122 in pause.g displays nothing however, I've got more info for you...

I did an M111 P3 S1 from the USB console and started the print, then did a pause

file: G1 X41.401001 Y82.360001
file: G1 X41.564999 Y82.282997
file: G1 X42.067001 Y82.074997
file: G1 X42.237000 Y82.013000
file: G1 X42.536999 Y81.918999 *******
file: G1 X42.124001 Y81.777000
file: G1 X41.955002 Y81.709999
file: G1 X41.101002 Y81.325996
file: G1 X40.887001 Y81.212997
file: G1 X40.061001 Y80.713997
file: G1 X39.862000 Y80.575996
file: G1 X39.101002 Y79.980003
file: G1 X38.919998 Y79.820000
file: G1 X38.237000 Y79.137001
file: G1 X38.076000 Y78.956001
file: G1 X37.480000 Y78.195000
file: G1 X37.342999 Y77.996002
file: G1 X36.859001 Y77.195000
file: G1 X36.771999 Y77.036003
file: G1 X36.534000 Y76.546997
file: G1 X36.462002 Y76.379997
file: G1 X36.140999 Y75.533997
file: G1 X36.084000 Y75.361000
file: G1 X35.938000 Y74.836998
file: G1 X35.897999 Y74.660004
file: G1 X35.729000 Y73.740997
file: G1 X35.700001 Y73.500999
file: G1 X35.645000 Y72.596001
file: G1 X35.641998 Y72.475998
file: G1 X35.641998 Y61.383999
file: G1 X35.641998 Y61.324001
file: G1 X35.657001 Y60.841999
file: G1 X35.671001 Y60.660999
file: G1 X35.784000 Y59.729000
file: G1 X35.827999 Y59.487000
file: G1 X36.066002 Y58.530998
file: G1 X36.138000 Y58.303001
file: G1 X36.473999 Y57.417999
file: G1 X36.573002 Y57.199001
file: G1 X37.021000 Y56.345001
file: G1 X37.146000 Y56.138000
file: G1 X37.695000 Y55.342999
file: G1 X37.844002 Y55.153000
file: G1 X38.485001 Y54.429001
file: G1 X38.655998 Y54.257999
file: G1 X39.379002 Y53.618000
file: G1 X39.854000 Y53.855999 F7200
http: M25
Paused print, file offset=3663
http: G91
http: G1 Z5 F600
http: G90
http: M122

At this time, the displayed coordinates were X42.537 Y81.919 which do NOT match the last move reported before the M25, nor the physical location of the toolhead. In fact, X42.537 Y81.919 is about 44 moves back.

I then sent a cancel. The toolhead and the display both moved to X39.854 Y53.855 to match the last reported move above. Then...

Done printing file
Cancelled printing file 0:/gcodes/sr.gcode, print time was 0h 0m
http: M0 H1
http: G91
http: G1 Z5 F600
http: G90
http: M122

chrishamm commented 4 years ago

AFAIR RRF does not report the current head position but the position of the last read move. When a print is paused, the move engine looks for the first move where the print can be paused and then reports/rewinds back to the file position after this move. That's what you see when you get the "Print paused at byte xxx" message.

In the logs above I still cannot see any direct fault of DSF - no new move from File is processed after M25 or before M0 H1. So I suspect this is rather related to RepRapFirmware. However I won't be able to run further tests before next week. Does this problem still show up when you clear stop.g?

chrishamm commented 4 years ago

Thinking further about it, my best guess is that the move buffer isn't properly reset at the time M0/stop.g is called. I'll try to figure out if that is the case.

gtjoseph commented 4 years ago

Yes, with an empty stop.g, the rest of the moves between the reported position and the last "file:" debug statement are executed on cancel.

dc42 commented 4 years ago

@gtjoseph, please can you clarify exactly what moves get executed on cancel. In an earlier message you said "I then sent a cancel. The toolhead and the display both moved to X39.854 Y53.855 to match the last reported move above." That makes it sound that only a single move was executed, not the whole sequence of skipped moves.

gtjoseph commented 4 years ago

@dc42 It wasn't apparent before but I verified that it's the "rest" of the moves in sequence. So for instance, with my rounded corner rectangles above, when I pressed pause, the toolhead stopped just before rounding a corner which was the file: G1 X42.536999 Y81.918999 ******* line. Those coordinates were what was displayed. When I pressed cancel, the toolhead moved around the corner and stopped at the coordinates stated in the last line in the debug file: G1 X39.854000 Y53.855999 F7200.

wilriker commented 4 years ago

I can chime in here again because I can also see this behavior still in 1.2.3.0.

I was printing a hollow single-walled cube all day repeatedly (testing PA and DAA settings). It has the layer change front center. I paused it when it reached the back right corner, it executed pause.g just fine. Then when cancelling I first expected it to see it returning to where it left off. Instead it returned to the layer seam and then continued with stop.g.

Looking at DCS log

Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [info] Print paused at file position 12452. Reason: User
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Print has been paused at byte 12452
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G0 F12000 X110 Y60.225 Z8.9
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X159.775 Y159.775 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X60.225 Y159.775 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X60.225 Y60.225 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X110 Y60.225 E1.86246
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G0 F12000 X110 Y60.225 Z9.1
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X159.775 Y159.775 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X60.225 Y159.775 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X60.225 Y60.225 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X110 Y60.225 E1.86246
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G0 F12000 X110 Y60.225 Z9.3
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled M572 D0 S0.1
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X159.775 Y159.775 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X60.225 Y159.775 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X60.225 Y60.225 E3.72493
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G1 X110 Y60.225 E1.86246
Jan 12 17:34:56 duet3-6HC DuetControlServer[9180]: [debug] Cancelled G0 F12000 X110 Y60.225 Z9.5

it's the first cancelled command that it then executed although being cancelled because X110 Y60.225 Z8.9 is where it returned to.

I have not checked what DWC showed at that point in time.

chrishamm commented 4 years ago

Can you provide both the DCS and M111 P3 S1 logs? I doubt the G0 code is actually fed to RRF because a cancelled code cannot be sent to RRF since it can be only cancelled before it is processed. The logs should confirm this and hopefully reveal the actual cause.

wilriker commented 4 years ago

Here you go: M111 P3 S1 output:

$ miniterm.py --echo /dev/ttyACM0 115200                                                                                                                 Sun 12 Jan 2020 17:58:00 CET
--- Miniterm on /dev/ttyACM0  115200,8,N,1 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---

Error: Bad command: Connection to Linux
ok
M111 P3 S1
Debugging enabled for modules: GCodes(3)
Debugging disabled for modules: Platform(0) Network(1) Webserver(2) Move(4) Heat(5) DDA(6) Roland(7) Scanner(8) PrintMonitor(9) Storage(10) PortControl(11) DuetExpansion(12) Filamen
tSensors(13) WiFi(14) Display(15) LinuxInterface(16)
http: M80
file: M80
file: T0
file: G21
file: G90
file: M83
file: M106 P0 S0
file: M703
file: M572 D0 S0.050000
file: M591 D0 R85:107 S1
file: M140 S60
file: M116 H0
http: G10 P0 S205
file: G10 P0 S205
file: M116 P0
http: M220 S125
file: M140 S55
file: G28
file: M80
file: G4 P750
file: G91
file: G1 H2 Z2 F3000
file: M400
file: M913 X40 Y45
file: G1 H1 X-300 Y-300 F3600
file: G1 X5 Y5 F3000
file: G1 H1 X-300 Y-300 F360
file: M98 P"homez.g"
file: M80
file: G4 P750
file: G91
file: M400
file: M913 Z50
file: G1 H1 Z-300 F900
file: G1 Z1 F3000
file: G1 H1 Z-300 F180
file: M584 P4
file: G1 H2 W0.340000
file: M584 P3
file: M400
file: G0 Z0.500000
file: M913 Z100
file: G90
file: G92 Z0
file: M400
file: M913 X100 Y100
file: G90
file: G0 Z0 F600
file: G0 Z2
file: M106 P2 S0.550000
file: T0
queue: M106 P2 S0.550000
file: M82
file: G11
file: M83
file: G10
file: M107
file: G0 F6000 X57.764999 Y57.693001 Z0.300000
file: G11
file: G1 F1200 X58.155998 Y57.368999 E0.028500
file: G1 X58.592999 Y57.111000 E0.028480
file: G1 X59.064999 Y56.924999 E0.028470
file: G1 X59.561001 Y56.814999 E0.028520
file: G1 X59.918999 Y56.785000 E0.020160
file: G1 X60.240002 Y56.776001 E0.018020
file: G1 X60.330002 Y56.775002 E0.005050
file: G1 X159.339005 Y56.775002 E5.557030
file: G1 X160.037003 Y56.785000 E0.039180
file: G1 X160.542999 Y56.833000 E0.028530
queue: M107
file: G1 X161.033997 Y56.958000 E0.028440
file: G1 X161.500000 Y57.160000 E0.028510
file: G1 X161.929001 Y57.431999 E0.028510
file: G1 X162.309006 Y57.768002 E0.028470
file: G1 X162.632004 Y58.159000 E0.028470
file: G1 X162.889999 Y58.597000 E0.028530
file: G1 X163.076004 Y59.069000 E0.028470
file: G1 X163.184998 Y59.563999 E0.028450
file: G1 X163.214996 Y59.918999 E0.020000
file: G1 X163.223999 Y60.238998 E0.017970
file: G1 X163.225006 Y60.330002 E0.005110
file: G1 X163.225006 Y159.304001 E5.555060
file: G1 X163.216003 Y160.031006 E0.040810
file: G1 X163.169998 Y160.535995 E0.028460
file: G1 X163.044998 Y161.028000 E0.028490
file: G1 X162.843994 Y161.494995 E0.028540
file: G1 X162.572998 Y161.923996 E0.028480
file: G1 X162.238007 Y162.304993 E0.028470
file: G1 X161.847000 Y162.628006 E0.028470
file: G1 X161.410004 Y162.886993 E0.028510
file: G1 X160.938004 Y163.074005 E0.028500
file: G1 X160.442993 Y163.184006 E0.028460
file: G1 X160.080994 Y163.214996 E0.020390
file: G1 X159.759995 Y163.223999 E0.018020
file: G1 X159.669998 Y163.225006 E0.005050
file: G1 X60.665001 Y163.225006 E5.556800
file: G1 X59.966999 Y163.216003 E0.039180
file: G1 X59.462002 Y163.169006 E0.028470
file: G1 X58.970001 Y163.044006 E0.028490
file: G1 X58.504002 Y162.843002 E0.028480
file: G1 X58.075001 Y162.572006 E0.028480
file: G1 X57.694000 Y162.235992 E0.028510
file: G1 X57.370998 Y161.845993 E0.028420
file: G1 X57.112000 Y161.408997 E0.028510
file: G1 X56.925999 Y160.936996 E0.028470
file: G1 X56.816002 Y160.440994 E0.028520
file: G1 X56.785000 Y160.078003 E0.020450
file: G1 X56.776001 Y159.744995 E0.018700
file: G1 X56.775002 Y159.658005 E0.004880
file: G1 X56.775002 Y60.630001 E5.558090
file: G1 X56.784000 Y59.965000 E0.037330
file: G1 X56.831001 Y59.459999 E0.028470
file: G1 X56.957001 Y58.967999 E0.028510
file: G1 X57.158001 Y58.501999 E0.028480
file: G1 X57.429001 Y58.073002 E0.028480
file: G1 X57.764999 Y57.693001 E0.028470
file: G10
file: G0 F6000 X60.356998 Y59.334999
file: G0 X60.356998 Y60.356998
file: G0 X110 Y60.360001
file: G0 X110 Y60.224998
file: M572 D0 S0.010000
file: G11
file: G1 F1200 X159.774994 Y60.224998 E2.793700
file: G1 X159.774994 Y159.774994 E5.587390
file: G1 X60.224998 Y159.774994 E5.587390
file: G1 X60.224998 Y60.224998 E5.587390
file: G1 X110 Y60.224998 E2.793700
file: M106 S76.500000
file: G0 F9000 X110 Y60.224998 Z0.500000
file: G1 F1800 X159.774994 Y60.224998 E1.862460
file: G1 X159.774994 Y159.774994 E3.724930
file: G1 X60.224998 Y159.774994 E3.724930
file: G1 X60.224998 Y60.224998 E3.724930
queue: M106 S76.500000
file: G1 X110 Y60.224998 E1.862460
file: M106 S76.800003
file: G0 F12000 X110 Y60.224998 Z0.700000
file: G1 F2400 X159.774994 Y60.224998 E1.862460
file: G1 X159.774994 Y159.774994 E3.724930
file: G1 X60.224998 Y159.774994 E3.724930
file: G1 X60.224998 Y60.224998 E3.724930
queue: M106 S76.800003
file: G1 X110 Y60.224998 E1.862460
file: G0 F12000 X110 Y60.224998 Z0.900000
file: G1 F2400 X159.774994 Y60.224998 E1.862460
file: G1 X159.774994 Y159.774994 E3.724930
file: G1 X60.224998 Y159.774994 E3.724930
file: G1 X60.224998 Y60.224998 E3.724930
file: G1 X110 Y60.224998 E1.862460
file: G0 F12000 X110 Y60.224998 Z1.100000
file: G1 F2400 X159.774994 Y60.224998 E1.862460
file: G1 X159.774994 Y159.774994 E3.724930
file: G1 X60.224998 Y159.774994 E3.724930
file: G1 X60.224998 Y60.224998 E3.724930
file: G1 X110 Y60.224998 E1.862460
file: G0 F12000 X110 Y60.224998 Z1.300000
http: M25
Paused print, file offset=3151
http: M83
http: G10
http: G91
http: G1 Z5 F360
http: G90
http: G1 X0 Y0 F6000
Done printing file
Cancelled printing file 0:/gcodes/Test/PAtestCube.gcode, print time was 0h 4m
http: M0 H1
http: M106 S0
http: G91
http: G1 Z4 X-20 Y20 F9000
http: G0 X-300 F3600
http: G90
http: G0 Y160 F5000
http: M591 D0
http: M591 D0 S0
http: M84
http: M106 P2 S0
http: M81
Warning: 12V under-voltage event (9.5V)

and DCS log

$ sudo journalctl -efu duetcontrolserver              125ms  Sun 12 Jan 2020 17:58:30 CET
-- Logs begin at Tue 2019-12-17 13:44:45 CET. --
Jan 12 17:58:49 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.215 Y59.919 E0.02
Jan 12 17:58:49 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X163.224 Y60.239 E0.01797
Jan 12 17:58:49 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.224 Y60.239 E0.01797
Jan 12 17:58:49 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X163.225 Y60.33 E0.00511
Jan 12 17:58:49 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.225 Y60.33 E0.00511
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [info] Executing system macro file start.g on channel File
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] ==> Starting code:
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code T0
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code M82;absolute extrusion mode
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G11; un-retract (Cura retracts at the end)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code M83;relative extrusion mode
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G10
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; start.g (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing ; start.g
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed ; start.g
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; called by RRF when a print is started (not though when resumed) (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing ; called by RRF when a print is started (not though when resumed)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed ; called by RRF when a print is started (not though when resumed)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M80; Turn the VIN PSU on (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M80; Turn the VIN PSU on
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of T0; Select the first tool (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing T0; Select the first tool
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G21; metric values (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing G21; metric values
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G90; absolute positioning (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing G90; absolute positioning
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M83; relative extrusion mode (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M83; relative extrusion mode
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M106 P0 S0; start with the fan off (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M106 P0 S0; start with the fan off
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M703; Load filament's config.g (includes heating) (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M703; Load filament's config.g (includes heating)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M80; Turn the VIN PSU on, remaining space 1516, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent T0; Select the first tool, remaining space 1496, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent G21; metric values, remaining space 1476, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent G90; absolute positioning, remaining space 1456, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M83; relative extrusion mode, remaining space 1436, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M106 P0 S0; start with the fan off, remaining space 1400, needed 36
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed M80; Turn the VIN PSU on
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed T0; Select the first tool
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed G21; metric values
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed G90; absolute positioning
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed M83; relative extrusion mode
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed M106 P0 S0; start with the fan off
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G28; home all axes (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing G28; home all axes
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;G29 S1       ; enable bed leveling compensation (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing ;G29 S1       ; enable bed leveling compensation
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed ;G29 S1       ; enable bed leveling compensation
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;M98 P/sys/wipe_nozzle.g ; Wipe the nozzle (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing ;M98 P/sys/wipe_nozzle.g ; Wipe the nozzle
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Completed ;M98 P/sys/wipe_nozzle.g ; Wipe the nozzle
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 Z2; lift the nozzle a bit (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing G0 Z2; lift the nozzle a bit
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M106 P2 S0.55; Start hardware cooling (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M106 P2 S0.55; Start hardware cooling
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M703; Load filament's config.g (includes heating), remaining space 1516, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent G28; home all axes, remaining space 1496, needed 20
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 Z2; lift the nozzle a bit, remaining space 1468, needed 28
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M106 P2 S0.55; Start hardware cooling, remaining space 1432, needed 36
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [info] Executing nested macro file config.g on channel File
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] ==> Starting code: M703; Load filament's config.g (includes heating)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G28; home all axes
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G0 Z2; lift the nozzle a bit
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code M106 P2 S0.55; Start hardware cooling
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M572 D0 S0.05; Pressure Advance (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M572 D0 S0.05; Pressure Advance
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M591 D0 R85:107 S1; Duet3D laser sensor for extruder drive 0 is connected to endstop input 3 (E0),
 tolerance 85 to 107%, 3mm comparison length (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M572 D0 S0.05; Pressure Advance, remaining space 1500, needed 36
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M591 D0 R85:107 S1; Duet3D laser sensor for extruder drive 0 is connected to endstop input 3 (E0), tolerance 85
to 107%, 3mm comparison length
, tolerance 85 to 107%, 3mm comparison length (Pre)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M140 S60; set bed temp (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M140 S60; set bed temp
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M116 H0; wait for bed temp (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M116 H0; wait for bed temp
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G10 P0 S205; set extruder temp (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing G10 P0 S205; set extruder temp
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M116 P0; wait for extruder temp (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M116 P0; wait for extruder temp
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M140 S55; set bed temp (type 1)
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] Processing M140 S55; set bed temp
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M591 D0 R85:107 S1; Duet3D laser sensor for extruder drive 0 is connected to endstop input 3 (E0), tolerance 85
to 107%, 3mm comparison length, remaining space 1448, needed 52
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M140 S60; set bed temp, remaining space 1420, needed 28
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M116 H0; wait for bed temp, remaining space 1392, needed 28
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent G10 P0 S205; set extruder temp, remaining space 1356, needed 36
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M116 P0; wait for extruder temp, remaining space 1328, needed 28
Jan 12 17:58:50 duet3-6HC DuetControlServer[716]: [debug] File: Sent M140 S55; set bed temp, remaining space 1300, needed 28
Jan 12 17:59:18 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G10 P0 S205
Jan 12 17:59:18 duet3-6HC DuetControlServer[716]: [debug] Processing G10 P0 S205
Jan 12 17:59:18 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G10 P0 S205, remaining space 1500, needed 36
Jan 12 17:59:18 duet3-6HC DuetControlServer[716]: [debug] Completed G10 P0 S205
Jan 12 18:01:05 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M220 S125
Jan 12 18:01:05 duet3-6HC DuetControlServer[716]: [debug] Processing M220 S125
Jan 12 18:01:05 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M220 S125, remaining space 1508, needed 28
Jan 12 18:01:06 duet3-6HC DuetControlServer[716]: [debug] Completed M220 S125
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Finished macro file config.g
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G28; home all axes, remaining space 1516, needed 20
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 Z2; lift the nozzle a bit, remaining space 1488, needed 28
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M106 P2 S0.55; Start hardware cooling, remaining space 1452, needed 36
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed M703; Load filament's config.g (includes heating)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [info] File: Finished macro file config.g
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: ==> Starting code: M703; Load filament's config.g (includes heating)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [info] Executing nested macro file homeall.g on channel File
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] ==> Starting code: G28; home all axes
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G0 Z2; lift the nozzle a bit
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code M106 P2 S0.55; Start hardware cooling
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; homeall.g (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing ; homeall.g
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed ; homeall.g
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; called to home all axes (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing ; called to home all axes
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed ; called to home all axes
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing ;
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed ;
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST) (type
 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M80; Turn the VIN PSU on (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing M80; Turn the VIN PSU on
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G4 P750; Wait for the PSU to initialize (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G4 P750; Wait for the PSU to initialize
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G91; relative positioning (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G91; relative positioning
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 H2 Z2 F3000; lift Z relative to current position (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G1 H2 Z2 F3000; lift Z relative to current position
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M400; Wait for all movements to finish (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing M400; Wait for all movements to finish
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M913 X40 Y45; Reduce motor current (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing M913 X40 Y45; Reduce motor current
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; X and Y (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing ; X and Y
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed ; X and Y
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 H1 X-300 Y-300 F3600; move quickly to X and Y axis endstops and stop there (first pass) (type 1
)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G1 H1 X-300 Y-300 F3600; move quickly to X and Y axis endstops and stop there (first pass)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X5 Y5 F3000; go back a few mm (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X5 Y5 F3000; go back a few mm
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 H1 X-300 Y-300 F360; move slowly to X and Y axis endstops once more (second pass) (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G1 H1 X-300 Y-300 F360; move slowly to X and Y axis endstops once more (second pass)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M80; Turn the VIN PSU on, remaining space 1516, needed 20
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G4 P750; Wait for the PSU to initialize, remaining space 1488, needed 28
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G91; relative positioning, remaining space 1468, needed 20
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; Z (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 H2 Z2 F3000; lift Z relative to current position, remaining space 1424, needed 44
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing ; Z
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M400; Wait for all movements to finish, remaining space 1404, needed 20
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M913 X40 Y45; Reduce motor current, remaining space 1368, needed 36
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 H1 X-300 Y-300 F3600; move quickly to X and Y axis endstops and stop there (first pass), remaining space 1316
, needed 52
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X5 Y5 F3000; go back a few mm, remaining space 1272, needed 44
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 H1 X-300 Y-300 F360; move slowly to X and Y axis endstops once more (second pass), remaining space 1220, need
ed 52
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Completed ; Z
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M98 P"homez.g" (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing M98 P"homez.g"
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M400; Wait for all movements to finish (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing M400; Wait for all movements to finish
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M913 X100 Y100; Restore motor current (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing M913 X100 Y100; Restore motor current
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G90; absolute positioning (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G90; absolute positioning
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 Z0 F600; Go to Z=0 in case the switch was lower (type 1)
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] Processing G0 Z0 F600; Go to Z=0 in case the switch was lower
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M98 P"homez.g", remaining space 1184, needed 36
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M400; Wait for all movements to finish, remaining space 1164, needed 20
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent M913 X100 Y100; Restore motor current, remaining space 1128, needed 36
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G90; absolute positioning, remaining space 1108, needed 20
Jan 12 18:01:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 Z0 F600; Go to Z=0 in case the switch was lower, remaining space 1072, needed 36
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [info] Executing nested macro file homez.g on channel File
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] ==> Starting code: M98 P"homez.g"
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code M400; Wait for all movements to finish
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code M913 X100 Y100; Restore motor current
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G90; absolute positioning
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Suspending code G0 Z0 F600; Go to Z=0 in case the switch was lower
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; homez.g (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing ; homez.g
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Completed ; homez.g
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; called to home the Z axis (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing ; called to home the Z axis
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Completed ; called to home the Z axis
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing ;
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Completed ;
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST) (type
 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Completed ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M80; Turn the VIN PSU on (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M80; Turn the VIN PSU on
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G4 P750; Wait for the PSU to initialize (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G4 P750; Wait for the PSU to initialize
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G91; relative positioning (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G91; relative positioning
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M400; Wait for all movements to finish (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M400; Wait for all movements to finish
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M913 Z50; Reduce motor current (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M913 Z50; Reduce motor current
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 H1 Z-300 F900; move quickly to Z axis endstop and stop there (first pass) (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G1 H1 Z-300 F900; move quickly to Z axis endstop and stop there (first pass)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 Z1 F3000; go back a few mm (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G1 Z1 F3000; go back a few mm
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 H1 Z-300 F180; move slowly to Z axis endstop once more (second pass) (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G1 H1 Z-300 F180; move slowly to Z axis endstop once more (second pass)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M584 P4; Enable W axis (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M584 P4; Enable W axis
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 H2 W0.34; Correction factor between the two endstop positions (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G1 H2 W0.34; Correction factor between the two endstop positions
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M80; Turn the VIN PSU on, remaining space 1516, needed 20
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M584 P3; Disable W axis (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G4 P750; Wait for the PSU to initialize, remaining space 1488, needed 28
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M584 P3; Disable W axis
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G91; relative positioning, remaining space 1468, needed 20
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M400; Wait for all movements to finish, remaining space 1448, needed 20
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M913 Z50; Reduce motor current, remaining space 1420, needed 28
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 H1 Z-300 F900; move quickly to Z axis endstop and stop there (first pass), remaining space 1376, needed 44
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 Z1 F3000; go back a few mm, remaining space 1340, needed 36
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M400; Wait for all movements to finish (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 H1 Z-300 F180; move slowly to Z axis endstop once more (second pass), remaining space 1296, needed 44
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M400; Wait for all movements to finish
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M584 P4; Enable W axis, remaining space 1268, needed 28
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 H2 W0.34; Correction factor between the two endstop positions, remaining space 1232, needed 36
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M584 P3; Disable W axis, remaining space 1204, needed 28
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 Z0.5; Endstops are below zero so lift to zero (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M400; Wait for all movements to finish, remaining space 1184, needed 20
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G0 Z0.5; Endstops are below zero so lift to zero
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M913 Z100; Restore motor current (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing M913 Z100; Restore motor current
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G90; absolute positioning (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G90; absolute positioning
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G92 Z0; Set Z=0 (type 1)
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] Processing G92 Z0; Set Z=0
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 Z0.5; Endstops are below zero so lift to zero, remaining space 1156, needed 28
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent M913 Z100; Restore motor current, remaining space 1128, needed 28
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G90; absolute positioning, remaining space 1108, needed 20
Jan 12 18:01:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G92 Z0; Set Z=0, remaining space 1080, needed 28
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Finished macro file homez.g
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent M400; Wait for all movements to finish, remaining space 1516, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent M913 X100 Y100; Restore motor current, remaining space 1480, needed 36
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G90; absolute positioning, remaining space 1460, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 Z0 F600; Go to Z=0 in case the switch was lower, remaining space 1424, needed 36
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [info] File: Finished macro file homez.g
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: ==> Starting code: M98 P"homez.g"
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Finished macro file homeall.g
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 Z2; lift the nozzle a bit, remaining space 1508, needed 28
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent M106 P2 S0.55; Start hardware cooling, remaining space 1472, needed 36
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [info] File: Finished macro file homeall.g
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G28; home all axes
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: ==> Starting code: G28; home all axes
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G0 Z2; lift the nozzle a bit
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M106 P2 S0.55; Start hardware cooling
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M591 D0 R85:107 S1; Duet3D laser sensor for extruder drive 0 is connected to endstop input 3 (E0), tolerance 85 t
o 107%, 3mm comparison length
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Finished macro file start.g
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M572 D0 S0.05; Pressure Advance
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M140 S60; set bed temp
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M116 H0; wait for bed temp
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G10 P0 S205; set extruder temp
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M116 P0; wait for extruder temp
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M140 S55; set bed temp
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M80; Turn the VIN PSU on
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G4 P750; Wait for the PSU to initialize
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G91; relative positioning
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 H2 Z2 F3000; lift Z relative to current position
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M400; Wait for all movements to finish
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M913 X40 Y45; Reduce motor current
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 H1 X-300 Y-300 F3600; move quickly to X and Y axis endstops and stop there (first pass)
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X5 Y5 F3000; go back a few mm
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 H1 X-300 Y-300 F360; move slowly to X and Y axis endstops once more (second pass)
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M98 P"homez.g"
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M400; Wait for all movements to finish
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M913 X100 Y100; Restore motor current
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G90; absolute positioning
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G0 Z0 F600; Go to Z=0 in case the switch was lower
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M80; Turn the VIN PSU on
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G4 P750; Wait for the PSU to initialize
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G91; relative positioning
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M400; Wait for all movements to finish
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M913 Z50; Reduce motor current
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 H1 Z-300 F900; move quickly to Z axis endstop and stop there (first pass)
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 Z1 F3000; go back a few mm
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 H1 Z-300 F180; move slowly to Z axis endstop once more (second pass)
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 H2 W0.34; Correction factor between the two endstop positions
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M584 P4; Enable W axis
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M584 P3; Disable W axis
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G0 Z0.5; Endstops are below zero so lift to zero
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M400; Wait for all movements to finish
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M913 Z100; Restore motor current
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G92 Z0; Set Z=0
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G90; absolute positioning
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent T0, remaining space 1516, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent M82;absolute extrusion mode, remaining space 1496, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G11; un-retract (Cura retracts at the end), remaining space 1476, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent M83;relative extrusion mode, remaining space 1456, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G10, remaining space 1436, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: -> Resumed suspended code
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [info] File: Finished system macro file start.g
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent M107, remaining space 1416, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F6000 X57.765 Y57.693 Z0.3, remaining space 1364, needed 52
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G11, remaining space 1344, needed 20
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F1200 X58.156 Y57.369 E0.0285, remaining space 1292, needed 52
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X58.593 Y57.111 E0.02848, remaining space 1248, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X59.065 Y56.925 E0.02847, remaining space 1204, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X59.561 Y56.815 E0.02852, remaining space 1160, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X59.919 Y56.785 E0.02016, remaining space 1116, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.24 Y56.776 E0.01802, remaining space 1072, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.33 Y56.775 E0.00505, remaining space 1028, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.339 Y56.775 E5.55703, remaining space 984, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X160.037 Y56.785 E0.03918, remaining space 940, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X160.543 Y56.833 E0.02853, remaining space 896, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X161.034 Y56.958 E0.02844, remaining space 852, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X161.5 Y57.16 E0.02851, remaining space 808, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X161.929 Y57.432 E0.02851, remaining space 764, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X162.309 Y57.768 E0.02847, remaining space 720, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X162.632 Y58.159 E0.02847, remaining space 676, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X162.89 Y58.597 E0.02853, remaining space 632, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.076 Y59.069 E0.02847, remaining space 588, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.185 Y59.564 E0.02845, remaining space 544, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.215 Y59.919 E0.02, remaining space 500, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.224 Y60.239 E0.01797, remaining space 456, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.225 Y60.33 E0.00511, remaining space 412, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed T0
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [warn] CodeQueue: Out-of-order reply: ''
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X163.225 Y159.304 E5.55506
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.225 Y159.304 E5.55506
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M82;absolute extrusion mode
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.225 Y159.304 E5.55506, remaining space 612, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G11; un-retract (Cura retracts at the end)
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M83;relative extrusion mode
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X163.216 Y160.031 E0.04081
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.216 Y160.031 E0.04081
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G10
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed M107
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G0 F6000 X57.765 Y57.693 Z0.3
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G11
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 F1200 X58.156 Y57.369 E0.0285
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X163.17 Y160.536 E0.02846
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.17 Y160.536 E0.02846
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X163.045 Y161.028 E0.02849
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X163.045 Y161.028 E0.02849
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X162.844 Y161.495 E0.02854
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X162.844 Y161.495 E0.02854
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X162.573 Y161.924 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X162.573 Y161.924 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X162.238 Y162.305 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X162.238 Y162.305 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X161.847 Y162.628 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X161.847 Y162.628 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X161.41 Y162.887 E0.02851
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X161.41 Y162.887 E0.02851
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X160.938 Y163.074 E0.0285
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X160.938 Y163.074 E0.0285
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X160.443 Y163.184 E0.02846
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X160.443 Y163.184 E0.02846
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X160.081 Y163.215 E0.02039
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X160.081 Y163.215 E0.02039
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X58.593 Y57.111 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.216 Y160.031 E0.04081, remaining space 920, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X59.065 Y56.925 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.17 Y160.536 E0.02846, remaining space 876, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X59.561 Y56.815 E0.02852
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.76 Y163.224 E0.01802
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X163.045 Y161.028 E0.02849, remaining space 832, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.76 Y163.224 E0.01802
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X59.919 Y56.785 E0.02016
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X162.844 Y161.495 E0.02854, remaining space 788, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X162.573 Y161.924 E0.02848, remaining space 744, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.24 Y56.776 E0.01802
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.33 Y56.775 E0.00505
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.339 Y56.775 E5.55703
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X162.238 Y162.305 E0.02847, remaining space 700, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X160.037 Y56.785 E0.03918
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X161.847 Y162.628 E0.02847, remaining space 656, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X161.41 Y162.887 E0.02851, remaining space 612, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X160.938 Y163.074 E0.0285, remaining space 568, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X160.443 Y163.184 E0.02846, remaining space 524, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X160.081 Y163.215 E0.02039, remaining space 480, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.76 Y163.224 E0.01802, remaining space 436, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.67 Y163.225 E0.00505
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.67 Y163.225 E0.00505
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.665 Y163.225 E5.5568
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.665 Y163.225 E5.5568
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X59.967 Y163.216 E0.03918
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X59.967 Y163.216 E0.03918
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X59.462 Y163.169 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X59.462 Y163.169 E0.02847
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X58.97 Y163.044 E0.02849
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X58.97 Y163.044 E0.02849
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X58.504 Y162.843 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X58.504 Y162.843 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X58.075 Y162.572 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X58.075 Y162.572 E0.02848
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [warn] CodeQueue: Out-of-order reply: ''
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.67 Y163.225 E0.00505, remaining space 392, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.665 Y163.225 E5.5568, remaining space 348, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X59.967 Y163.216 E0.03918, remaining space 304, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X59.462 Y163.169 E0.02847, remaining space 260, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X58.97 Y163.044 E0.02849, remaining space 216, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X58.504 Y162.843 E0.02848, remaining space 172, needed 44
Jan 12 18:01:27 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X58.075 Y162.572 E0.02848, remaining space 128, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X160.543 Y56.833 E0.02853
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X161.034 Y56.958 E0.02844
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X161.5 Y57.16 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X161.929 Y57.432 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X162.309 Y57.768 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X162.632 Y58.159 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X162.89 Y58.597 E0.02853
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.076 Y59.069 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.185 Y59.564 E0.02845
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.215 Y59.919 E0.02
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.224 Y60.239 E0.01797
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.225 Y60.33 E0.00511
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.225 Y159.304 E5.55506
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.216 Y160.031 E0.04081
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X57.694 Y162.236 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X57.694 Y162.236 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X57.371 Y161.846 E0.02842
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X57.371 Y161.846 E0.02842
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X57.112 Y161.409 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X57.112 Y161.409 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.926 Y160.937 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.926 Y160.937 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.816 Y160.441 E0.02852
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.816 Y160.441 E0.02852
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.785 Y160.078 E0.02045
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.785 Y160.078 E0.02045
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.776 Y159.745 E0.0187
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.776 Y159.745 E0.0187
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.775 Y159.658 E0.00488
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.775 Y159.658 E0.00488
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.775 Y60.63 E5.55809
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.775 Y60.63 E5.55809
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.784 Y59.965 E0.03733
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.784 Y59.965 E0.03733
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.831 Y59.46 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.831 Y59.46 E0.02847
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X56.957 Y58.968 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X56.957 Y58.968 E0.02851
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X57.158 Y58.502 E0.02848
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X57.158 Y58.502 E0.02848
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X57.429 Y58.073 E0.02848
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X57.429 Y58.073 E0.02848
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X57.694 Y162.236 E0.02851, remaining space 700, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X57.371 Y161.846 E0.02842, remaining space 656, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X57.112 Y161.409 E0.02851, remaining space 612, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.926 Y160.937 E0.02847, remaining space 568, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.816 Y160.441 E0.02852, remaining space 524, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.785 Y160.078 E0.02045, remaining space 480, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.776 Y159.745 E0.0187, remaining space 436, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.775 Y159.658 E0.00488, remaining space 392, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.775 Y60.63 E5.55809, remaining space 348, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.784 Y59.965 E0.03733, remaining space 304, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.831 Y59.46 E0.02847, remaining space 260, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X56.957 Y58.968 E0.02851, remaining space 216, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X57.158 Y58.502 E0.02848, remaining space 172, needed 44
Jan 12 18:01:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X57.429 Y58.073 E0.02848, remaining space 128, needed 44
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.17 Y160.536 E0.02846
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X57.765 Y57.693 E0.02847
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X57.765 Y57.693 E0.02847
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X163.045 Y161.028 E0.02849
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X162.844 Y161.495 E0.02854
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G10
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X162.573 Y161.924 E0.02848
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing G10
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X162.238 Y162.305 E0.02847
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F6000 X60.357 Y59.335
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F6000 X60.357 Y59.335
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 X60.357 Y60.357
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing G0 X60.357 Y60.357
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X161.847 Y162.628 E0.02847
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X161.41 Y162.887 E0.02851
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X160.938 Y163.074 E0.0285
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 X110 Y60.36
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X160.443 Y163.184 E0.02846
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X160.081 Y163.215 E0.02039
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.76 Y163.224 E0.01802
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.67 Y163.225 E0.00505
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.665 Y163.225 E5.5568
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X59.967 Y163.216 E0.03918
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X57.765 Y57.693 E0.02847, remaining space 700, needed 44
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing G0 X110 Y60.36
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] File: Sent G10, remaining space 680, needed 20
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F6000 X60.357 Y59.335, remaining space 636, needed 44
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 X60.357 Y60.357, remaining space 600, needed 36
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 X110 Y60.225
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing G0 X110 Y60.225
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M572 D0 S0.01
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing M572 D0 S0.01
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:01:32 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G11
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Processing G11
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F1200 X159.775 Y60.225 E2.7937
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F1200 X159.775 Y60.225 E2.7937
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E5.58739
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E5.58739
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E5.58739
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E5.58739
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E5.58739
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E5.58739
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 X110 Y60.36, remaining space 564, needed 36
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 X110 Y60.225, remaining space 528, needed 36
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent M572 D0 S0.01, remaining space 492, needed 36
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G11, remaining space 472, needed 20
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F1200 X159.775 Y60.225 E2.7937, remaining space 420, needed 52
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E5.58739, remaining space 376, needed 44
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E5.58739, remaining space 332, needed 44
Jan 12 18:01:33 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E5.58739, remaining space 288, needed 44
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X59.462 Y163.169 E0.02847
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X58.97 Y163.044 E0.02849
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E2.7937
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E2.7937
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X58.504 Y162.843 E0.02848
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X58.075 Y162.572 E0.02848
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X57.694 Y162.236 E0.02851
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X57.371 Y161.846 E0.02842
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X57.112 Y161.409 E0.02851
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.926 Y160.937 E0.02847
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:44.670361
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:44.670361
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.776 Y159.745 E0.0187
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.775 Y159.658 E0.00488
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.816 Y160.441 E0.02852
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.785 Y160.078 E0.02045
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.775 Y60.63 E5.55809
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:44.670361
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:1
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:1
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:1
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M106 S76.5
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing M106 S76.5
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F9000 X110 Y60.225 Z0.5
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F9000 X110 Y60.225 Z0.5
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F1800 X159.775 Y60.225 E1.86246
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F1800 X159.775 Y60.225 E1.86246
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.784 Y59.965 E0.03733
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E2.7937, remaining space 860, needed 44
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent M106 S76.5, remaining space 832, needed 28
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F9000 X110 Y60.225 Z0.5, remaining space 780, needed 52
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F1800 X159.775 Y60.225 E1.86246, remaining space 728, needed 52
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 684, needed 44
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 640, needed 44
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:58.127011
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:58.127011
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:58.127011
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:2
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:2
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:2
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 596, needed 44
Jan 12 18:01:37 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 552, needed 44
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.831 Y59.46 E0.02847
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X56.957 Y58.968 E0.02851
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M106 S76.8
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing M106 S76.8
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X57.158 Y58.502 E0.02848
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X57.429 Y58.073 E0.02848
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X57.765 Y57.693 E0.02847
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G10
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G0 F6000 X60.357 Y59.335
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G0 X60.357 Y60.357
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G0 X110 Y60.36
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed G0 X110 Y60.225
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z0.7
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z0.7
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:68.312334
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:68.312334
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:68.312334
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:3
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:3
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:3
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent M106 S76.8, remaining space 916, needed 28
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z0.7, remaining space 864, needed 52
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F2400 X159.775 Y60.225 E1.86246, remaining space 812, needed 52
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 768, needed 44
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 724, needed 44
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 680, needed 44
Jan 12 18:01:41 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 636, needed 44
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed M572 D0 S0.01
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed G11
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed G1 F1200 X159.775 Y60.225 E2.7937
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.775 Y159.775 E5.58739
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z0.9
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z0.9
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y159.775 E5.58739
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z0.9, remaining space 824, needed 52
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y60.225 E5.58739
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F2400 X159.775 Y60.225 E1.86246, remaining space 772, needed 52
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 728, needed 44
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 684, needed 44
Jan 12 18:01:46 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 640, needed 44
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X110 Y60.225 E2.7937
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:78.497656
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:78.497656
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:78.497656
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:4
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:4
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:4
Jan 12 18:01:48 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 640, needed 44
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Completed M106 S76.5
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Completed G0 F9000 X110 Y60.225 Z0.5
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z1.1
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z1.1
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z1.1, remaining space 668, needed 52
Jan 12 18:01:52 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F2400 X159.775 Y60.225 E1.86246, remaining space 616, needed 52
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] Completed G1 F1800 X159.775 Y60.225 E1.86246
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 668, needed 44
Jan 12 18:01:56 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 624, needed 44
Jan 12 18:02:00 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:00 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:00 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:00 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 624, needed 44
Jan 12 18:02:02 duet3-6HC DuetControlServer[716]: [warn] CodeQueue: Out-of-order reply: ''
Jan 12 18:02:02 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:02 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:02:02 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:02:02 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 624, needed 44
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X110 Y60.225 E1.86246
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:88.682979
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:88.682979
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:88.682979
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:5
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:5
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:5
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:02:03 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Completed M106 S76.8
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z1.3
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Completed G0 F12000 X110 Y60.225 Z0.7
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z1.3
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M572 D0 S0.02
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Processing M572 D0 S0.02
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z1.3, remaining space 696, needed 52
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] File: Sent M572 D0 S0.02, remaining space 660, needed 36
Jan 12 18:02:06 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F2400 X159.775 Y60.225 E1.86246, remaining space 608, needed 52
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] Completed G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 660, needed 44
Jan 12 18:02:08 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 616, needed 44
Jan 12 18:02:11 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:11 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:11 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:11 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 616, needed 44
Jan 12 18:02:12 duet3-6HC DuetControlServer[716]: [warn] CodeQueue: Out-of-order reply: ''
Jan 12 18:02:12 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:12 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:02:12 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:02:12 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 616, needed 44
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X110 Y60.225 E1.86246
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:98.868302
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:98.868302
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:98.868302
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:6
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:6
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:6
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z1.5
Jan 12 18:02:13 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z1.5
Jan 12 18:02:14 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z1.5, remaining space 608, needed 52
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] Completed G0 F12000 X110 Y60.225 Z0.9
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:16 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F2400 X159.775 Y60.225 E1.86246, remaining space 608, needed 52
Jan 12 18:02:17 duet3-6HC DuetControlServer[716]: [debug] Completed G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:17 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:17 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:17 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:17 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:17 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:18 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 660, needed 44
Jan 12 18:02:18 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 616, needed 44
Jan 12 18:02:20 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:20 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:20 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:20 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 616, needed 44
Jan 12 18:02:21 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:21 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:02:21 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:02:21 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 616, needed 44
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X110 Y60.225 E1.86246
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:109.053624
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:109.053624
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:109.053624
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:7
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:7
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:7
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z1.7
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z1.7
Jan 12 18:02:22 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z1.7, remaining space 608, needed 52
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] Completed G0 F12000 X110 Y60.225 Z1.1
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TYPE:WALL-OUTER
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] Processing ;TYPE:WALL-OUTER
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] Completed ;TYPE:WALL-OUTER
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] Processing G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:24 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 F2400 X159.775 Y60.225 E1.86246, remaining space 608, needed 52
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] Completed G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X159.775 Y159.775 E3.72493, remaining space 660, needed 44
Jan 12 18:02:26 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y159.775 E3.72493, remaining space 616, needed 44
Jan 12 18:02:28 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:28 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:28 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:28 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X60.225 Y60.225 E3.72493, remaining space 616, needed 44
Jan 12 18:02:29 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:29 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X110 Y60.225 E1.86246
Jan 12 18:02:29 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X110 Y60.225 E1.86246
Jan 12 18:02:29 duet3-6HC DuetControlServer[716]: [debug] File: Sent G1 X110 Y60.225 E1.86246, remaining space 616, needed 44
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X110 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;TIME_ELAPSED:119.238947
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Processing ;TIME_ELAPSED:119.238947
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Completed ;TIME_ELAPSED:119.238947
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;LAYER:8
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Processing ;LAYER:8
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Completed ;LAYER:8
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;MESH:cube.stl
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Processing ;MESH:cube.stl
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Completed ;MESH:cube.stl
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 F12000 X110 Y60.225 Z1.9
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Processing G0 F12000 X110 Y60.225 Z1.9
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] File: Sent G0 F12000 X110 Y60.225 Z1.9, remaining space 608, needed 52
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M25
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Processing M25
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M25, remaining space 1516, needed 20
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [info] Paused print, file offset=3151
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [info] Print paused at file position 3151. Reason: User
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Print has been paused at byte 3151
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G0 F12000 X110 Y60.225 Z1.3
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled M572 D0 S0.02
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X110 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G0 F12000 X110 Y60.225 Z1.5
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X110 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G0 F12000 X110 Y60.225 Z1.7
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 F2400 X159.775 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X159.775 Y159.775 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X60.225 Y159.775 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X60.225 Y60.225 E3.72493
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G1 X110 Y60.225 E1.86246
Jan 12 18:02:30 duet3-6HC DuetControlServer[716]: [debug] Cancelled G0 F12000 X110 Y60.225 Z1.9
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [info] Executing nested macro file pause.g on channel HTTP
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] ==> Starting code: M25
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; pause.g (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing ; pause.g
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed ; pause.g
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; called when a print from SD card is paused (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing ; called when a print from SD card is paused
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed ; called when a print from SD card is paused
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing ;
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed ;
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST) (type
 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M83; relative extruder moves (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing M83; relative extruder moves
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G10; retract filament (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing G10; retract filament
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G91; relative positioning (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing G91; relative positioning
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 Z5 F360; lift Z by 5mm (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing G1 Z5 F360; lift Z by 5mm
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G90; absolute positioning (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing G90; absolute positioning
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 X0 Y0 F6000; go to front-left (type 1)
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Processing G1 X0 Y0 F6000; go to front-left
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M83; relative extruder moves, remaining space 1516, needed 20
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G10; retract filament, remaining space 1496, needed 20
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G91; relative positioning, remaining space 1476, needed 20
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G1 Z5 F360; lift Z by 5mm, remaining space 1440, needed 36
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G90; absolute positioning, remaining space 1420, needed 20
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G1 X0 Y0 F6000; go to front-left, remaining space 1376, needed 44
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] HTTP: Finished macro file pause.g
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed M83; relative extruder moves
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed G91; relative positioning
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed G10; retract filament
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 Z5 F360; lift Z by 5mm
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed G90; absolute positioning
Jan 12 18:02:32 duet3-6HC DuetControlServer[716]: [debug] Completed G1 X0 Y0 F6000; go to front-left
Jan 12 18:02:35 duet3-6HC DuetControlServer[716]: [debug] Completed M25 => Printing paused at X159.8 Y159.8 Z1.1
Jan 12 18:02:35 duet3-6HC DuetControlServer[716]: [info] HTTP: Finished macro file pause.g
Jan 12 18:02:35 duet3-6HC DuetControlServer[716]: [debug] HTTP: ==> Starting code: M25 => Printing paused at X159.8 Y159.8 Z1.1
Jan 12 18:02:38 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M0 H1
Jan 12 18:02:38 duet3-6HC DuetControlServer[716]: [debug] Processing M0 H1
Jan 12 18:02:38 duet3-6HC DuetControlServer[716]: [info] Cancelled print file
Jan 12 18:02:38 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M0 H1, remaining space 1508, needed 28
Jan 12 18:02:38 duet3-6HC DuetControlServer[716]: [info] Cancelled printing file 0:/gcodes/Test/PAtestCube.gcode, print time was 0h 4m
Jan 12 18:02:38 duet3-6HC DuetControlServer[716]: [warn] File: Out-of-order reply: ''
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [info] Executing nested macro file stop.g on channel HTTP
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] ==> Starting code: M0 H1
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; stop.g (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing ; stop.g
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed ; stop.g
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled) (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing ; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed ; called when M0 (Stop) is run (e.g. when a print from SD card is cancelled)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing ;
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed ;
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST) (type
 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed ; generated by RepRapFirmware Configuration Tool on Sat Apr 28 2018 20:07:26 GMT+0200 (CEST)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;G10 P0 R-273.15 S-273.15 ; extruder heater off (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing ;G10 P0 R-273.15 S-273.15 ; extruder heater off
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed ;G10 P0 R-273.15 S-273.15 ; extruder heater off
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of ;M140 S-273.15            ; bed heater off (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing ;M140 S-273.15            ; bed heater off
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed ;M140 S-273.15            ; bed heater off
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M106 S0; turn off fan (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing M106 S0; turn off fan
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G91; relative positioning (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing G91; relative positioning
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G1 Z+4 X-20 Y+20 F9000; move nozzle away from object (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing G1 Z+4 X-20 Y+20 F9000; move nozzle away from object
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 X-300 F3600; move X to the left, so the head is completely out of the way (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing G0 X-300 F3600; move X to the left, so the head is completely out of the way
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G90; absolute positioning (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing G90; absolute positioning
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of G0 Y160 F5000; move bed to the front (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing G0 Y160 F5000; move bed to the front
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M591 D0; output stats on LFS (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing M591 D0; output stats on LFS
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M591 D0 S0; Disable Laser Filament Sensor (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing M591 D0 S0; Disable Laser Filament Sensor
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M106 S0; turn off fan, remaining space 1508, needed 28
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G91; relative positioning, remaining space 1488, needed 20
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G1 Z+4 X-20 Y+20 F9000; move nozzle away from object, remaining space 1436, needed 52
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M84; steppers off (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing M84; steppers off
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G0 X-300 F3600; move X to the left, so the head is completely out of the way, remaining space 1400, needed 36
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G90; absolute positioning, remaining space 1380, needed 20
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent G0 Y160 F5000; move bed to the front, remaining space 1344, needed 36
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M591 D0; output stats on LFS, remaining space 1316, needed 28
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M591 D0 S0; Disable Laser Filament Sensor, remaining space 1280, needed 36
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M106 P2 S0; Stop hardware cooling (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing M106 P2 S0; Stop hardware cooling
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Waiting for execution of M81; Turn off VIN PSU - fans run on 5V and are not affected (type 1)
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Processing M81; Turn off VIN PSU - fans run on 5V and are not affected
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M84; steppers off, remaining space 1260, needed 20
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M106 P2 S0; Stop hardware cooling, remaining space 1224, needed 36
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] HTTP: Sent M81; Turn off VIN PSU - fans run on 5V and are not affected, remaining space 1204, needed 20
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed M106 S0; turn off fan
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed G91; relative positioning
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed G1 Z+4 X-20 Y+20 F9000; move nozzle away from object
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed G0 X-300 F3600; move X to the left, so the head is completely out of the way
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed G90; absolute positioning
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed G0 Y160 F5000; move bed to the front
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed M591 D0; output stats on LFS => Duet3D laser filament monitor v1 on pin io5.in, enabled, allow 85% to 107%, check
 every 3.0mm, version 1, measured min 92% avg 95% max 98% over 90.3mm
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [info] Duet3D laser filament monitor v1 on pin io5.in, enabled, allow 85% to 107%, check every 3.0mm, version 1, measured min 92% a
vg 95% max 98% over 90.3mm
Jan 12 18:02:39 duet3-6HC DuetControlServer[716]: [debug] Completed M591 D0 S0; Disable Laser Filament Sensor
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [debug] Completed M84; steppers off
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [debug] HTTP: Finished macro file stop.g
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [debug] Completed M106 P2 S0; Stop hardware cooling
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [debug] Completed M81; Turn off VIN PSU - fans run on 5V and are not affected
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [info] HTTP: Finished macro file stop.g
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [debug] Completed M0 H1
Jan 12 18:02:42 duet3-6HC DuetControlServer[716]: [debug] HTTP: ==> Starting code: M0 H1
Jan 12 18:02:44 duet3-6HC DuetControlServer[716]: [warn] 12V under-voltage event (9.5V)

I paused the print when it reached X110 Y60.224998 and when cancelling it returned to X110 Y60.224998 Z1.300000.

From the logs you can see that DCS states it

Cancelled G0 F12000 X110 Y60.225 Z1.3

but in M111 log you can see it reached it's target - though it was only executed when cancelling the paused print.

chrishamm commented 4 years ago

Ah yes, the SPI connector invalidates the codes being processed by RRF when it receives a notification about the print being paused. Hence it's cancelled after M25. However the M111 log clearly shows that no new codes are being fed/interpreted by RRF once M25 is processed, so the error must be somewhere in RepRapFirmware.

I'll try to debug this in a few days unless @dc42 beats me to it.

dc42 commented 4 years ago

I've tried to reproduce this using the latest RRF3 build, and failed. I am using this file:

G1 F300

G1 X0.2 G1 Y0.2 G1 X0 G1 Y0

G1 X0.2 G1 Y0.2 G1 X0 G1 Y0 (repeat the above 4 lines many times)

I tested on Duet 3 in both standalone mode and with the RPi. No moves get executed after cancel. The file is designed so that the pause can be done almost immediately, because the feed rate is lower than the configured XY jerk. Also the moves are short so that the move buffer should be full, in case the problem only happens when the move buffer is full.

@gtjoseph, please can you test this file on your machine. If it doesn't fail with this file, please provide a file that it does fail on.

dc42 commented 4 years ago

With @wilriker's help, I was able to reproduce this, although I only ever saw a single command executed after cancelling the print. I believe this is fixed in RRF 3.1beta 2020-01-13b3.

wilriker commented 4 years ago

I can confirm this fixed with the latest 3.01beta. I would say if @gtjoseph can also confirm this one could be closed.

gtjoseph commented 4 years ago

Yep, just tried it with the current 3.01-dev and it's fixed. Thanks!

Duet3D / DuetSoftwareFramework

Still having issues with Cancel in DSF 1.2.2.0 #94