Duet3D / DuetSoftwareFramework

Software framework for the next-generation Duet3D platform based on .NET
GNU General Public License v3.0
61 stars 28 forks source link

Unable to complete a print #54

Closed techildllc closed 5 years ago

techildllc commented 5 years ago

I have been trying to print a number of files and none of them have been able to complete successfully. They will all "stop" midway through, never in the same spot. Print head will stop moving randomly and stay there indefinitely. Everything will start cooling down. Web controller will show print completed 100%. No errors shown in control server or webserver. Running M122 shows there are pending and buffered Gcodes.

Last few lines logged in controlserver:

Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Sent G1 E0.8 F1200, remaining space 36 (2012 total), needed 36
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Completed G1 X128.499 Y134.078 E0.02876
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Sent G1 X148.859 Y177.929 E0.07512 F771.7, remaining space 28 (1996 total), needed 52
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Completed G1 X128.916 Y133.529 E0.02295
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Sent G1 X148.755 Y177.921 E0.07161 F2220.7, remaining space 20 (1996 total), needed 52
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Completed G1 X129.456 Y132.85 E0.02884
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Sent G1 X148.581 Y177.907 E0.05307 F3349.7, remaining space 12 (1996 total), needed 52
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Completed G1 X142.053 Y145.447 E0.5925
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Sent G1 X148.337 Y177.888 E0.01658 F3880.7, remaining space 4 (1996 total), needed 52
Aug 10 15:55:15 raspberrypi DuetControlServer[329]: [info] Completed G1 X142.432 Y145.826 E0.01783

Last lines logged in webserver

Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Request starting HTTP/1.1 GET http://192.168.1.244/machine/directory/0:%2Ffilaments
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer)'
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Route matched with {action = "GetFileList", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] GetFileList(System.String) on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Executing action method DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer) - Validation state: Valid
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Executed action method DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer), returned result Microsoft.AspNetCore.Mvc.ContentResult in 8.855ms.
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Executing ContentResult with HTTP Response ContentType of application/json
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Executed action DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer) in 10.0615ms
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer)'
Aug 10 15:30:12 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Aug 10 15:30:12 raspberrypi DuetWebServer[436]:       Request finished in 18.3914ms 200 application/json
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Request starting HTTP/1.1 POST http://192.168.1.244/machine/code text/plain 26
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[4]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       CORS policy execution successful.
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Route matched with {action = "DoCode", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] DoCode() on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Executing action method DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) - Validation state: Valid
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: DuetWebServer.Controllers.MachineController[0]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       [DoCode] Executing code 'M32 "0:/gcodes/cap1.gcode"'
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Executed action method DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer), returned result Microsoft.AspNetCore.Mvc.ContentResult in 275.8518ms.
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 276.9521ms
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Aug 10 15:30:17 raspberrypi DuetWebServer[436]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Aug 10 15:30:17 raspberrypi DuetWebServer[436]:       Request finished in 278.2366ms 200 text/plain; charset=utf-8

Duet Control Server v1.0.3.1 Duet Web Control 2.0.0-RC8-b3 M122 === Diagnostics === RepRapFirmware for Duet 3 v0.5 version 3.0b7-ch running on Duet 3 prototype v0.5 Board ID: 08DGM-9T66A-G63SJ-6JKD2-3SD6P-TU0BA Used output buffers: 1 of 32 (6 max) === RTOS === Static ram: 65620 Dynamic ram: 133448 of which 16 recycled Exception stack ram used: 552 Never used ram: 193580 Tasks: NETWORK(ready,2036) HEAT(blocked,1132) CanClock(blocked,1472) CanSender(suspended,1420) TMC(blocked,456) MAIN(running,4392) IDLE(ready,196) Owned mutexes: === Platform === Last reset 01:07:42 ago, cause: software Last software reset at 2019-08-10 16:12, reason: Unknown, spinning module Platform, available RAM 194008 bytes (slot 0) Software reset code 0x0010 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x04429000 BFAR 0x00000000 SP 0xffffffff Task 0x4e49414d Error status: 0 MCU temperature: min 27.5, current 28.7, max 29.6 Supply voltage: min 23.6, current 23.9, max 24.0, under voltage events: 0, over voltage events: 0, power good: yes Driver 0: standstill, reads 18231, writes 31 timeouts 0, SG min/max 0/1023 Driver 1: standstill, reads 18232, writes 31 timeouts 0, SG min/max 0/1023 Driver 2: standstill, reads 18239, writes 26 timeouts 0, SG min/max 0/212 Driver 3: standstill, reads 18243, writes 23 timeouts 0, SG min/max 0/430 Driver 4: standstill, reads 18248, writes 19 timeouts 0, SG min/max 0/112 Driver 5: standstill, reads 18257, writes 11 timeouts 0, SG min/max 0/0 Date/time: 2019-08-10 17:20:01 Slowest loop: 271.80ms; fastest: 0.19ms === Move === Hiccups: 504, FreeDm: 375, MinFreeDm: 328, MaxWait: 920046ms Bed compensation in use: none, comp offset 0.000 === MainDDARing === Scheduled moves: 60, completed moves: 60, 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, chamberHeaters = -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: 15.04ms; fastest: 0.01ms Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) Telnet(0) Telnet(0) HTTP sessions: 0 of 8

dc42 commented 5 years ago

Last reset 01:07:42 ago, cause: software Last software reset at 2019-08-10 16:12, reason: Unknown, spinning module Platform, available RAM 194008 bytes (slot 0) Software reset code 0x0010 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x04429000 BFAR 0x00000000 SP 0xffffffff Task 0x4e49414d

Does that last reset time correspond to when the print stopped, or before the print started?

techildllc commented 5 years ago

That time corresponds to the last print failure. When it all froze up, I reset the system just to be sure it can restart cleanly.

dc42 commented 5 years ago

Strange, that software reset code (0x0010) should only be set if you use M999 PERASE to reset and erase the processor.

chrishamm commented 5 years ago

Just to be sure: Can you run M115 and check if the date equals 2019-08-07b2? If yes, can you please provide a ZIP of your /sys directory and the file you've been trying to print?

techildllc commented 5 years ago

Strange, that software reset code (0x0010) should only be set if you use M999 PERASE to reset and erase the processor.

For the last firmware update, I still used an erase jumper on the board and an usb cable with BOSSA on my PC. After turning it off and turning it all back on again. Here is the M122

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 v0.5 version 3.0b7-ch running on Duet 3 prototype v0.5
Board ID: 08DGM-9T66A-G63SJ-6JKD2-3SD6P-TU0BA
Used output buffers: 1 of 32 (6 max)
=== RTOS ===
Static ram: 65620
Dynamic ram: 133324 of which 16 recycled
Exception stack ram used: 288
Never used ram: 193968
Tasks: NETWORK(ready,2036) HEAT(blocked,1248) CanClock(blocked,1472) CanSender(suspended,1420) TMC(blocked,616) MAIN(running,4392) IDLE(ready,196)
Owned mutexes:
=== Platform ===
Last reset 00:01:26 ago, cause: power up
Last software reset at 2019-08-10 16:12, reason: Unknown, spinning module Platform, available RAM 194008 bytes (slot 0)
Software reset code 0x0010 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x04429000 BFAR 0x00000000 SP 0xffffffff Task 0x4e49414d
Error status: 0
MCU temperature: min 17.2, current 25.8, max 26.4
Supply voltage: min 23.8, current 23.9, max 24.0, under voltage events: 0, over voltage events: 0, power good: yes
Driver 0: standstill, reads 60291, writes 18 timeouts 0, SG min/max 0/0
Driver 1: standstill, reads 60292, writes 18 timeouts 0, SG min/max 0/0
Driver 2: standstill, reads 60294, writes 17 timeouts 0, SG min/max 0/0
Driver 3: standstill, reads 60298, writes 14 timeouts 0, SG min/max 0/0
Driver 4: standstill, reads 60300, writes 14 timeouts 0, SG min/max 0/0
Driver 5: standstill, reads 60304, writes 11 timeouts 0, SG min/max 0/0
Date/time: 2019-08-12 20:15:35
Slowest loop: 8.32ms; fastest: 0.19ms
=== Move ===
Hiccups: 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, chamberHeaters = -1 -1
=== GCodes ===
Segments left: 0
Stack records: 1 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.52ms; fastest: 0.01ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) Telnet(0) Telnet(0)
HTTP sessions: 0 of 8
- Ethernet -
State: 0
Socket states: 0 0 0 0 0 0 0 0
=== Linux interface ===
State: 1, failed transfers: 0
Last transfer: 93ms ago
RX/TX seq numbers: 2058/2058
SPI underruns 0, overruns 0
Number of disconnects: 0
Buffer RX/TX: 0/0-0
=== Duet Control Server ===
Duet Control Server v1.0.3.1
Code buffer space: 2048
Configured SPI speed: 1000000 Hz
Full transfers per second: 0.01

Just to be sure: Can you run M115 and check if the date equals 2019-08-07b2? If yes, can you please provide a ZIP of your /sys directory and the file you've been trying to print?

Sure, heres is the M115 output, compressed /sys folder is being email to you:

M115
FIRMWARE_NAME: RepRapFirmware for Duet 3 v0.5 FIRMWARE_VERSION: 3.0b7-ch ELECTRONICS: Duet 3 prototype v0.5 FIRMWARE_DATE: 2019-08-07b2
wilriker commented 5 years ago

Just to state that this is not a general problem: I can print successfully with the latest firmware/DSF version (just finished a 90 minute print). Though the symptoms are at least somewhat similar to what I had a couple of versions ago.

techildllc commented 5 years ago

Just to state that this is not a general problem: I can print successfully with the latest firmware/DSF version (just finished a 90 minute print). Though the symptoms are at least somewhat similar to what I had a couple of versions ago.

What about a longer print? This happens at random times. I can probably eek out a 60 min print, though probably not reliably. Any idea on a potential fix or place to look or probe?

wilriker commented 5 years ago

Usually my prints are rather small and thus short so I can hardly give numbers on longer prints. But in none of the last 6 prints (all 90 minutes or less) I had something similar.

But unfortunately I have no idea on how to diagnose any further. I know that especially the cooling down that happened to me a couple of versions ago I could not find any source that would shut off the heaters but still they turned off at some random point in time (the printer would though continue to print and at least XYZ movements continued after hotend fell below min extrusion temp). But as I said before this has been fixed in the current versions.

wilriker commented 5 years ago
duetcontrolserver=1.0.3.1-1
duetruntime=1.0.3.1-1
duetsd=1.0.1-4
duettools=1.0.3.1-1
duetwebcontrol=2.0.0.RC8.b3-1
duetwebserver=1.1.0.0-1
duet3firmware=3.0alpha@2019-08-25b1

OK, now I got hit by the same phenomenon, i.e. at a seemingly random point in the print (about 45 minutes in) the print head stopped, DWC jumped to finished and heaters were turned off. I updated to the latest commit of v3-dev branch right before starting the print.

Here are the last lines of DCS

Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X76.742 Y121.69, remaining space 252 (816 total), needed 44
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X75.791 Y122.641 E0.08387, remaining space 200 (764 total), needed 52
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X75.477 Y122.955, remaining space 156 (720 total), needed 44
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X75.391 Y123.041 E0.00758, remaining space 104 (668 total), needed 52
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X75.081 Y123.351, remaining space 60 (624 total), needed 44
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X74.877 Y123.554 E0.01795, remaining space 8 (572 total), needed 52
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X91.909 Y135.514 E1.1549
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X74.569 Y123.863, remaining space 16 (760 total), needed 44
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Completed G1 X91.821 Y135.602
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X64.587 Y133.844 E0.88031, remaining space 0 (752 total), needed 52
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X90.74 Y136.039
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X65.024 Y134.114, remaining space 0 (856 total), needed 44
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X79.516 Y124.814 E0.98994
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X75.093 Y124.046 E0.88798, remaining space 0 (848 total), needed 52
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X79.101 Y124.4
Aug 27 12:03:22 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X75.409 Y123.73, remaining space 0 (952 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X78.839 Y124.138 E0.02311
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X78.396 Y123.694
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X78.273 Y123.572 E0.0108
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X77.803 Y123.102
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X75.605 Y123.534 E0.01729, remaining space 140 (1136 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X75.928 Y123.211, remaining space 96 (1092 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X76.018 Y123.121 E0.00794, remaining space 44 (1040 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X76.342 Y122.797, remaining space 0 (996 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X76.25 Y121.549 E0.13697
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X76.742 Y121.69
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X75.791 Y122.641 E0.08387
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X75.477 Y122.955
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X75.391 Y123.041 E0.00758
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X75.081 Y123.351
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X77.316 Y121.823 E0.0859, remaining space 236 (1424 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X77.653 Y121.486, remaining space 192 (1380 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X78.005 Y121.134 E0.03104, remaining space 140 (1328 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X77.409 Y121.023, remaining space 96 (1284 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X77.072 Y121.36 E0.02972, remaining space 44 (1232 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X75.601 Y120.9, remaining space 0 (1188 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X74.877 Y123.554 E0.01795
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X74.569 Y123.863
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X64.587 Y133.844 E0.88031
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X65.024 Y134.114
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G1 F5040 X75.093 Y124.046 E0.88798
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Completed G0 F12000 X75.409 Y123.73
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X74.809 Y120.108 E0.06985, remaining space 236 (1424 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 X74.721 Y120.02, remaining space 200 (1388 total), needed 36
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X69.896 Y115.195, remaining space 156 (1344 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X69.098 Y114.397 E0.07038, remaining space 104 (1292 total), needed 52
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G0 F12000 X69.64 Y114.649, remaining space 60 (1248 total), needed 44
Aug 27 12:03:23 duet3-v05 DuetControlServer[269]: [info] Sent G1 F5040 X69.336 Y114.954 E0.02686, remaining space 8 (1196 total), needed 52

Last lines in DWS

Aug 27 11:20:37 duet3-v05 DuetWebServer[283]: info: DuetWebServer.Controllers.MachineController[0]
Aug 27 11:20:37 duet3-v05 DuetWebServer[283]:       [DoCode] Executing code 'M32 "0:/gcodes/Meisenknodelpresse.gcode"'
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]:       Executed action method DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer), returned result Microsoft.AspNetCore.Mvc.ContentResult in 576.3832ms.
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]:       Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 577.6198ms
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Aug 27 11:20:38 duet3-v05 DuetWebServer[283]:       Request finished in 578.7072ms 200 text/plain; charset=utf-8
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Request starting HTTP/1.1 POST http://localhost/machine/code text/plain 4
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[4]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       CORS policy execution successful.
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Route matched with {action = "DoCode", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] DoCode() on controller DuetWebServer.Contr>
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Executing action method DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) - Validation state: Valid
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: DuetWebServer.Controllers.MachineController[0]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       [DoCode] Executing code 'M115'
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Executed action method DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer), returned result Microsoft.AspNetCore.Mvc.ContentResult in 51.2768ms.
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 51.9544ms
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Aug 27 11:23:45 duet3-v05 DuetWebServer[283]:       Request finished in 52.8437ms 200 text/plain; charset=utf-8
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]:       Request starting HTTP/1.1 POST http://localhost/machine/code text/plain 30
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[4]
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]:       CORS policy execution successful.
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]:       Route matched with {action = "DoCode", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] DoCode() on controller DuetWebServer.Contr>
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]: info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Aug 27 12:04:12 duet3-v05 DuetWebServer[283]:       Executing action method DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) - Validation state: Valid

And M122

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 v0.5 version 3.0alpha running on Duet 3 prototype v0.5
Board ID: 08DGM-9T66A-G63SJ-6J9DG-3SD6P-9V07A
Used output buffers: 1 of 32 (6 max)
=== RTOS ===
Static ram: 68044
Dynamic ram: 134104 of which 20 recycled
Exception stack ram used: 592
Never used ram: 190456
Tasks: NETWORK(ready,2044) HEAT(blocked,1212) CanReceiv(suspended,3812) CanSender(suspended,1488) CanClock(blocked,1424) TMC(blocked,448) MAIN(running,4508) IDLE(ready,200)
Owned mutexes:
=== Platform ===
Last reset 00:45:58 ago, cause: software
Last software reset at 2019-08-27 11:01, reason: Unknown, spinning module Platform, available RAM 190548 bytes (slot 3)
Software reset code 0x0010 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x04429000 BFAR 0x00000000 SP 0xffffffff Task 0x4e49414d
Error status: 0
MCU temperature: min 32.0, current 39.5, max 40.1
Supply voltage: min 0.1, current 24.1, max 24.3, under voltage events: 0, over voltage events: 0, power good: yes
Driver 0: standstill, reads 34176, writes 20 timeouts 0, SG min/max 0/1023
Driver 1: standstill, reads 34178, writes 20 timeouts 0, SG min/max 0/1023
Driver 2: standstill, reads 34179, writes 20 timeouts 0, SG min/max 0/1023
Driver 3: standstill, reads 34178, writes 22 timeouts 0, SG min/max 0/1023
Driver 4: standstill, reads 34185, writes 16 timeouts 0, SG min/max 0/1023
Driver 5: standstill, reads 34191, writes 11 timeouts 0, SG min/max 0/0
Date/time: 2019-08-27 12:06:16
Slowest loop: 58.54ms; fastest: 0.18ms
=== Move ===
Hiccups: 0, FreeDm: 375, MinFreeDm: 327, MaxWait: 378551ms
Bed compensation in use: none, comp offset 0.000
=== MainDDARing ===
Scheduled moves: 1, completed moves: 1, 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, chamberHeaters = -1 -1
=== GCodes ===
Segments left: 0
Stack records: 3 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: 1.29ms; fastest: 0.01ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) Telnet(0) Telnet(0)
HTTP sessions: 0 of 8
- Ethernet -
State: 0
Socket states: 0 0 0 0 0 0 0 0
=== Filament sensors ===
Extruder 0: pos 9.00, ok, measured min 57% avg 84% max 97% over 4448.5mm, errs: frame 13 parity 0 ovrun 0 pol 311 ovdue 0
=== Linux interface ===
State: 0, failed transfers: 0
Last transfer: 94ms ago
RX/TX seq numbers: 3999/25755
SPI underruns 0, overruns 0
Number of disconnects: 1
Buffer RX/TX: 0/0-0
=== Duet Control Server ===
Duet Control Server v1.0.3.1
File:
Pending code: G0 F12000 X69.03 Y115.259
Pending code: G1 F5040 X68.155 Y116.134 E0.07717
Pending code: G0 F12000 X67.858 Y116.432
Pending code: G1 F5040 X67.776 Y116.514 E0.00723
Pending code: G0 F12000 X67.48 Y116.809
Pending code: G1 F5040 X67.296 Y116.993 E0.01623
Pending code: G0 F12000 X67.001 Y117.289
Pending code: G1 F5040 X57.276 Y127.014 E0.85769
Pending code: G0 F12000 X57.587 Y127.41
Pending code: G1 F5040 X67.254 Y117.743 E0.85257
Pending code: G0 F12000 X67.547 Y117.45
Pending code: G1 F5040 X67.735 Y117.261 E0.01662
Pending code: G0 F12000 X68.03 Y116.967
Pending code: G1 F5040 X68.11 Y116.886 E0.0071
Pending code: G0 F12000 X68.405 Y116.592
Pending code: G1 F5040 X69.268 Y115.729 E0.07611
Buffered code: G1 F5040 X75.605 Y123.534 E0.01729
Buffered code: G0 F12000 X75.928 Y123.211
Buffered code: G1 F5040 X76.018 Y123.121 E0.00794
Buffered code: G0 F12000 X76.342 Y122.797
Buffered code: G1 F5040 X77.316 Y121.823 E0.0859
Buffered code: G0 F12000 X77.653 Y121.486
Buffered code: G1 F5040 X78.005 Y121.134 E0.03104
Buffered code: G0 F12000 X77.409 Y121.023
Buffered code: G1 F5040 X77.072 Y121.36 E0.02972
Buffered code: G0 F12000 X75.601 Y120.9
Buffered code: G1 F5040 X74.809 Y120.108 E0.06985
Buffered code: G1 X74.721 Y120.02
Buffered code: G0 F12000 X69.896 Y115.195
Buffered code: G1 F5040 X69.098 Y114.397 E0.07038
Buffered code: G0 F12000 X69.64 Y114.649
Buffered code: G1 F5040 X69.336 Y114.954 E0.02686
=> 760 bytes
Code buffer space: 2048
Configured SPI speed: 1000000 Hz
Full transfers per second: 340.72
Processing print job /opt/dsf/sd/gcodes/Meisenknodelpresse.gcode
chrishamm commented 5 years ago

I found a potential issue that could lead to out-of-sync execution of G-codes. It has been fixed in DCS 1.0.3.3 but I have not been able to test it in depth yet.

This version is available from the unstable package feed, see https://duet3d.dozuki.com/Wiki/Duet_3_prototype_guide_for_OEMs#Section_Installation Could you install it and check if it helps?

wilriker commented 5 years ago

At least I have not been seeing this issue anymore since 1.0.3.3. Of course with a random problem it is always hard to tell if it really is gone.

chrishamm commented 5 years ago

I am closing this because I cannot reproduce it - especially not with the latest version 1.0.4.1 If this problem still persists, please open a new issue.