Another 'Hang' of DWC

Garfield

Sounds identical, I see this error a lot in syslog ...

Feb 20 21:59:39 duet3 vncserver-x11[467,root]: AgentInitCheck: agent comms failure
Feb 20 21:59:44 duet3 vncserver-x11[467,root]: AgentInitCheck: no response from agent

Why would I be seeing VNC server failures - ????????

Where would I find the duet control log ... and why can't linux distro's be consistent !!!!

Details of Duet

DSF Version: 1.2.4.0
Firmware: RepRapFirmware for Duet 3 MB6HC v0.6 or 1.0 3.01-RC2 (2020-02-18b1)

droftarts

@Garfield Unfortunately I don't have a working Pi4+Duet 3 working setup yet, so can't help with the details. This seems to be a DSF issue, so one for @chrishamm to look at.

Ian

A Former User

@Garfield said in Another 'Hang' of DWC:

Why would I be seeing VNC server failures - ????????

its part of the stock image unless you download the lite version with no x winows (or disable with raspi-config or remove with apt)

Danal

DSF logs are available via:

sudo journalctl -f

Or, if you want JUST a particular log:

sudo journalctl -fu duetwebserver
sudo journalctl -fu duetcontrolserver

Garfield

@Danal said in Another 'Hang' of DWC:

sudo journalctl -fu duetwebserver

No particular crash report web server

Feb 21 10:52:18 duet3 DuetWebServer[453]: info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Feb 21 10:52:18 duet3 DuetWebServer[453]:       Request starting HTTP/1.1 POST http://10.100.2.225/machine/code text/plain;charset=UTF-8 5
Feb 21 10:52:18 duet3 DuetWebServer[453]: info: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[4]
Feb 21 10:52:18 duet3 DuetWebServer[453]:       CORS policy execution successful.
Feb 21 10:52:18 duet3 DuetWebServer[453]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Feb 21 10:52:18 duet3 DuetWebServer[453]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Feb 21 10:52:18 duet3 DuetWebServer[453]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
Feb 21 10:52:18 duet3 DuetWebServer[453]:       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).
Feb 21 10:52:18 duet3 DuetWebServer[453]: info: DuetWebServer.Controllers.MachineController[0]
Feb 21 10:52:18 duet3 DuetWebServer[453]:       [DoCode] Executing code 'G28 X'

Nor Duet control server

Feb 21 00:17:10 duet3 DuetControlServer[373]: [warn] heater 1 appears to be over-powered. If left on at full power, its temperature is predicted to reach 365C.
Feb 21 00:17:11 duet3 DuetControlServer[373]: [info] Executing nested macro file config-override.g on channel Daemon
Feb 21 00:17:11 duet3 DuetControlServer[373]: [info] Daemon: Finished macro file config-override.g
Feb 21 00:17:11 duet3 DuetControlServer[373]: [info] Daemon: Finished system macro file config.g
Feb 21 10:24:07 duet3 DuetControlServer[373]: [info] System time has been changed
Feb 21 10:52:19 duet3 DuetControlServer[373]: [info] Executing nested macro file homex.g on channel HTTP
Feb 21 10:52:49 duet3 DuetControlServer[373]: [info] Received file abort request on channel HTTP for all files
Feb 21 10:52:49 duet3 DuetControlServer[373]: [info] Aborted macro file
Feb 21 10:52:49 duet3 DuetControlServer[373]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Feb 21 10:52:49 duet3 DuetControlServer[373]: [error] G0/G1: insufficient axes homed

I wonder if the out of order reply is the trigger ....

Danal

It is certainly a symptom, but we already knew that from the DWC console.

The "out of order" just means it came over the socket on its own, not as a sequenced response to something. We knew that also.

Garfield

How can I assist further ? - makes sense to do so while I can reproduce the problem at will.

Restarting the service definitely fixes the problem.

Incidentally I did not send any 'abort' requests so I don't know why the 'Received file abort' is there.

Danal

I just noticed the "System Time Has Been Changed".

For me, changing the time on the Pi will kill a print. Cause a hang or a fault.

Do we know what is causing that?

Garfield

@Danal said in Another 'Hang' of DWC:

sudo journalctl -f

I just ran again since those logs I had recently turned on, these logs are from the system that's been enabled a while (like ever since).

-- Logs begin at Fri 2020-02-21 14:17:01 GMT. --
Feb 21 23:17:29 duet3 DuetWebServer[442]:       G90
Feb 21 23:17:29 duet3 DuetWebServer[442]:       M121'
Feb 21 23:17:29 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Feb 21 23:17:29 duet3 DuetWebServer[442]:       Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
Feb 21 23:17:29 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
Feb 21 23:17:29 duet3 DuetWebServer[442]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 426.4927ms
Feb 21 23:17:29 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Feb 21 23:17:29 duet3 DuetWebServer[442]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Feb 21 23:17:29 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Feb 21 23:17:29 duet3 DuetWebServer[442]:       Request finished in 427.1703ms 200 text/plain; charset=utf-8

pi@duet3:~ $ sudo journalctl -fu duetcontrolserver
-- Logs begin at Fri 2020-02-21 14:17:01 GMT. --
Feb 21 23:16:15 duet3 DuetControlServer[371]: [warn] Resetting controller
Feb 21 23:16:16 duet3 DuetControlServer[371]: [info] Connection to Duet established
Feb 21 23:16:16 duet3 DuetControlServer[371]: [info] Executing system macro file config.g on channel Daemon
Feb 21 23:16:16 duet3 DuetControlServer[371]: [warn] heater 1 appears to be over-powered. If left on at full power, its temperature is predicted to reach 365C.
Feb 21 23:16:17 duet3 DuetControlServer[371]: [info] Executing nested macro file config-override.g on channel Daemon
Feb 21 23:16:17 duet3 DuetControlServer[371]: [info] Daemon: Finished macro file config-override.g
Feb 21 23:16:17 duet3 DuetControlServer[371]: [info] Daemon: Finished system macro file config.g
Feb 21 23:17:29 duet3 DuetControlServer[371]: [info] Received file abort request on channel HTTP for all files
Feb 21 23:17:29 duet3 DuetControlServer[371]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Feb 21 23:17:29 duet3 DuetControlServer[371]: [error] G0/G1: insufficient axes homed

pi@duet3:~ $ sudo journalctl -f
-- Logs begin at Fri 2020-02-21 14:17:01 GMT. --
Feb 21 23:19:04 duet3 sudo[28383]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Feb 21 23:19:09 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Feb 21 23:19:14 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Feb 21 23:19:19 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Feb 21 23:19:24 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Feb 21 23:19:26 duet3 sudo[28383]: pam_unix(sudo:session): session closed for user root
Feb 21 23:19:29 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Feb 21 23:19:34 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Feb 21 23:19:37 duet3 sudo[28480]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/usr/bin/journalctl -f
Feb 21 23:19:37 duet3 sudo[28480]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Feb 21 23:19:39 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Feb 21 23:19:44 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Feb 21 23:19:49 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent

The systemctl status says the service is running

duetcontrolserver.service                     loaded active running   Duet Control Server                                                                     
duetwebserver.service                          loaded active running   Duet Web Server

but interaction is not possible, I persisted in pushing buttons and got an

Error: Push(): Stack overflow

Feb 21 23:26:58 duet3 DuetControlServer[371]: [info] Received file abort request on channel HTTP for all files
Feb 21 23:26:58 duet3 DuetControlServer[371]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Feb 21 23:26:58 duet3 DuetControlServer[371]: [error] G0/G1: insufficient axes homed
Feb 21 23:26:59 duet3 DuetControlServer[371]: [info] Received file abort request on channel HTTP for all files
Feb 21 23:26:59 duet3 DuetControlServer[371]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Feb 21 23:26:59 duet3 DuetControlServer[371]: [error] G0/G1: insufficient axes homed
Feb 21 23:26:59 duet3 DuetControlServer[371]: [error] Push(): stack overflow
Feb 21 23:27:00 duet3 DuetControlServer[371]: [info] Received file abort request on channel HTTP for all files
Feb 21 23:27:00 duet3 DuetControlServer[371]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Feb 21 23:27:00 duet3 DuetControlServer[371]: [error] G0/G1: insufficient axes homed

Garfield

The Duetcontrolserver hang / fail is still happening, it is unpredictable but occurs most during homing. The web gui still functions for some things but is useless for any kind of control once this occurs.

Does anyone have a way to put this service into some sort of debug mode because there is nothing useful logged - it is almost as though the Pi doesn't know the service isn't working, this may be a communication failure between the web service and the control service and not actually a service failure.

The latest logs from the latest 'crash' - absolutely useless ..... I will be removing VNC since it serves no useful purpose to have a remote access to a browser window - that I already have access to.

pi@duet3:~ $ sudo journalctl -fu duetcontrolserver
-- Logs begin at Sun 2020-03-08 00:17:01 GMT. --
Mar 09 12:03:00 duet3 DuetControlServer[13318]:    DuetAPI.Commands.CodeParserException: Duplicate P parameter
Mar 09 12:03:00 duet3 DuetControlServer[13318]:    at DuetAPI.Commands.Code.Parse(TextReader reader, Code result, Boolean& enforcingAbsolutePosition) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Commands/Code/Parser.cs:line 339
Mar 09 12:03:00 duet3 DuetControlServer[13318]:    at DuetControlServer.FileExecution.BaseFile.ReadCode() in /home/christian/duet/DuetSoftwareFramework/src/DuetControlServer/FileExecution/BaseFile.cs:line 154
Mar 09 12:03:00 duet3 DuetControlServer[13318]:    at DuetControlServer.FileExecution.MacroFile.ReadCode() in /home/christian/duet/DuetSoftwareFramework/src/DuetControlServer/FileExecution/MacroFile.cs:line 187
Mar 09 12:03:00 duet3 DuetControlServer[13318]:    at DuetControlServer.SPI.ChannelInformation.ProcessRequests() in /home/christian/duet/DuetSoftwareFramework/src/DuetControlServer/SPI/ChannelInformation.cs:line 221
Mar 09 12:03:00 duet3 DuetControlServer[13318]: [warn] heater 0 appears to be over-powered. If left on at full power, its temperature is predicted to reach 875C.
Mar 09 12:03:00 duet3 DuetControlServer[13318]: [info] Executing nested macro file config-override.g on channel Daemon
Mar 09 12:03:00 duet3 DuetControlServer[13318]: [error] G31: Cannot set a temperature coefficient without a valid heater number
Mar 09 12:03:00 duet3 DuetControlServer[13318]: [info] Daemon: Finished macro file config-override.g
Mar 09 12:03:00 duet3 DuetControlServer[13318]: [info] Daemon: Finished system macro file config.g

 ^H

^C
pi@duet3:~ $ sudo journalctl -fu duetwebserver
-- Logs begin at Sun 2020-03-08 00:17:01 GMT. --
Mar 09 12:03:26 duet3 DuetWebServer[442]:    at DuetAPIClient.BaseConnection.PerformCommand[T](BaseCommand command, CancellationToken cancellationToken) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPIClient/BaseConnection.cs:line 178
Mar 09 12:03:26 duet3 DuetWebServer[442]:    at DuetWebServer.Controllers.MachineController.DoCode() in /home/christian/duet/DuetSoftwareFramework/src/DuetWebServer/Controllers/MachineController.cs:line 100
Mar 09 12:03:26 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
Mar 09 12:03:26 duet3 DuetWebServer[442]:       Executing ObjectResult, writing value of type 'System.String'.
Mar 09 12:03:26 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
Mar 09 12:03:26 duet3 DuetWebServer[442]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 689487.1924ms
Mar 09 12:03:26 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Mar 09 12:03:26 duet3 DuetWebServer[442]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Mar 09 12:03:26 duet3 DuetWebServer[442]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Mar 09 12:03:26 duet3 DuetWebServer[442]:       Request finished in 689491.1494ms 500 text/plain; charset=utf-8
^C
pi@duet3:~ $ sudo journalctl -f
-- Logs begin at Sun 2020-03-08 00:17:01 GMT. --
Mar 09 12:06:03 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Mar 09 12:06:08 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Mar 09 12:06:08 duet3 sudo[15679]: pam_unix(sudo:session): session closed for user root
Mar 09 12:06:13 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Mar 09 12:06:18 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Mar 09 12:06:23 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Mar 09 12:06:28 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Mar 09 12:06:33 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Mar 09 12:06:36 duet3 sudo[15778]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/usr/bin/journalctl -f
Mar 09 12:06:36 duet3 sudo[15778]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Mar 09 12:06:38 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Mar 09 12:06:43 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure
Mar 09 12:06:48 duet3 vncserver-x11[463]: AgentInitCheck: no response from agent
Mar 09 12:06:53 duet3 vncserver-x11[463]: AgentInitCheck: agent comms failure