Homing Inconsistent Duet 3

Garfield

@T3P3Tony So finally it happened again, again this was during homing procedures.

DuetControlServer does NOT hang or fail in a way that the linux OS understands

This is the message in the console, it is erroneous - whatever mechanism is used to determine the RRF 'availability' is failing and not the homing process - the mechanism causing the 'Transport endpoint is not connected' error is the problem here.

22/03/2020, 12:31:28 	G28 Y
Error: Operation failed (Reason: Transport endpoint is not connected)
22/03/2020, 12:31:28 	Error: G0/G1: insufficient axes homed

This is the report from sysctl - clearly shows duetcontrolserver is still running - but it has stopped communicating with the Pi

pi@duet3:~ $ sudo systemctl -l status duetcontrolserver
● duetcontrolserver.service - Duet Control Server
   Loaded: loaded (/lib/systemd/system/duetcontrolserver.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2020-03-22 00:29:41 GMT; 12h ago
 Main PID: 340 (DuetControlServ)
    Tasks: 15 (limit: 4915)
   Memory: 50.9M
   CGroup: /system.slice/duetcontrolserver.service
           └─340 /opt/dsf/bin/DuetControlServer

Mar 22 12:24:54 duet3 DuetControlServer[340]: [info] Executing nested macro file config-override.g on channel Trigger
Mar 22 12:24:54 duet3 DuetControlServer[340]: [info] Trigger: Finished macro file config-override.g
Mar 22 12:24:54 duet3 DuetControlServer[340]: [info] Trigger: Finished system macro file config.g
Mar 22 12:31:02 duet3 DuetControlServer[340]: [info] Executing nested macro file homex.g on channel HTTP
Mar 22 12:31:16 duet3 DuetControlServer[340]: [info] HTTP: Finished macro file homex.g
Mar 22 12:31:16 duet3 DuetControlServer[340]: [info] Executing nested macro file homey.g on channel HTTP
Mar 22 12:31:28 duet3 DuetControlServer[340]: [info] Received file abort request on channel HTTP for all files
Mar 22 12:31:28 duet3 DuetControlServer[340]: [info] Aborted macro file
Mar 22 12:31:28 duet3 DuetControlServer[340]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Mar 22 12:31:28 duet3 DuetControlServer[340]: [error] G0/G1: insufficient axes homed
pi@duet3:~ $

The journal contains the same messages.

pi@duet3:~ $ sudo journalctl -fu duetcontrolserver     
-- Logs begin at Thu 2019-02-14 10:11:59 GMT. --
Mar 22 12:24:54 duet3 DuetControlServer[340]: [info] Executing nested macro file config-override.g on channel Trigger
Mar 22 12:24:54 duet3 DuetControlServer[340]: [info] Trigger: Finished macro file config-override.g
Mar 22 12:24:54 duet3 DuetControlServer[340]: [info] Trigger: Finished system macro file config.g
Mar 22 12:31:02 duet3 DuetControlServer[340]: [info] Executing nested macro file homex.g on channel HTTP
Mar 22 12:31:16 duet3 DuetControlServer[340]: [info] HTTP: Finished macro file homex.g
Mar 22 12:31:16 duet3 DuetControlServer[340]: [info] Executing nested macro file homey.g on channel HTTP
Mar 22 12:31:28 duet3 DuetControlServer[340]: [info] Received file abort request on channel HTTP for all files
Mar 22 12:31:28 duet3 DuetControlServer[340]: [info] Aborted macro file
Mar 22 12:31:28 duet3 DuetControlServer[340]: [warn] HTTP: Out-of-order reply: 'G0/G1: insufficient axes homed'
Mar 22 12:31:28 duet3 DuetControlServer[340]: [error] G0/G1: insufficient axes homed

The message 'executing nested macro' is misleading - these macros are not nested unless the Pi or something in the background is doing this - my homex, homey and homez are all independent, when this failure occured I was homing axes individually. The error insufficiant axes homed is also erroneous. I was actually homing at the time of the error and not executing any command that required the axes to be homed.

Anything in the queue remains in the queue and the interface appears to be hung - it is NOT hung - it is waiting for a macro to complete that never will. When this transport error occurs the system needs to clear any outstanding queued commands and attempt to re-establish communication.

The time is also incorrect - the systemctl reports that the system has been running for 12 hours - it has not, it was started at approx 10am

-- Logs begin at Thu 2019-02-14 10:11:59 GMT. --
Mar 22 12:45:01 duet3 CRON[17414]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Mar 22 12:45:01 duet3 CRON[17410]: pam_unix(cron:session): session closed for user root
Mar 22 12:47:53 duet3 sudo[17864]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/usr/bin/journalctl -fu duetcontrolserver
Mar 22 12:47:53 duet3 sudo[17864]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Mar 22 12:48:00 duet3 sudo[17864]: pam_unix(sudo:session): session closed for user root
Mar 22 12:49:47 duet3 sudo[18117]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/usr/bin/journalctl -fu
Mar 22 12:49:47 duet3 sudo[18117]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Mar 22 12:49:47 duet3 sudo[18117]: pam_unix(sudo:session): session closed for user root
Mar 22 12:49:51 duet3 sudo[18142]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/usr/bin/journalctl -f
Mar 22 12:49:51 duet3 sudo[18142]: pam_unix(sudo:session): session opened for user root by pi(uid=0)

Is the time a clue ? and why is it so messed up .... I'm not a linux fan and this isn't helping that opinion

Danal

RE: Time

@Garfield said in Homing Inconsistent Duet 3:

he systemctl reports that the system has been running for 12 hours - it has not, it was started at approx 10am
-- Logs begin at Thu 2019-02-14 10:11:59 GMT. --

Check your system time zone. They come out of the box set to GMT.

ssh to the Pi and enter sudo raspi-config Use the menus to check the time zone, etc. In fact, if you just go to those menus (localization, time zone) and don't change anything, and back out, you will find something like the below in the console session after you back completely out of raspi-config. This also lets you verify how it is currently setup.

Current default time zone: 'America/Chicago'
Local time is now:      Sun Mar 22 14:36:29 CDT 2020.
Universal Time is now:  Sun Mar 22 19:36:29 UTC 2020.

@Garfield said in Homing Inconsistent Duet 3:

the systemctl reports that the system has been running for 12 hours

Not sure what you see that makes you think that? The log entry timestamps like "Mar 22 12:49:51" are a time of day, not a duration since boot. Again, timezone may affect this.

Garfield

This entry in the systemctl status states that it has been running since 00:29:41

Active: active (running) since Sun 2020-03-22 00:29:41 GMT; 12h ago

Regardless of the timezone that is incorrect

Danal

RE: Nested

@Garfield said in Homing Inconsistent Duet 3:

The message 'executing nested macro' is misleading - these macros are not nested unless the Pi or something in the background is doing this - my homex, homey and homez are all independent, when this failure occured I was homing axes individually.

In this case, "Nested" means the DSF was already executing a G28, and that called a macro. Please note this is chrishamm's code, and it's really the way his mind works that determines this word in a log message; there is not a technically correct or incorrect answer here.

Anyway, if it helps, the complete output from homing a single axis is below.

The error insufficiant axes homed is also erroneous. I was actually homing at the time of the error and not executing any command that required the axes to be homed.

Agreed, this seems like a bug.

Mar 22 14:39:27 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Mar 22 14:39:27 duet3 DuetWebServer[468]:       Request starting HTTP/1.1 POST http://192.168.7.101/machine/code text/plain;charset=UTF-8 5
Mar 22 14:39:27 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[4]
Mar 22 14:39:27 duet3 DuetWebServer[468]:       CORS policy execution successful.
Mar 22 14:39:27 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Mar 22 14:39:27 duet3 DuetWebServer[468]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Mar 22 14:39:27 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
Mar 22 14:39:27 duet3 DuetWebServer[468]:       Route matched with {action = "DoCode", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.As
pNetCore.Mvc.IActionResult] DoCode() on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
Mar 22 14:39:27 duet3 DuetWebServer[468]: info: DuetWebServer.Controllers.MachineController[0]
Mar 22 14:39:27 duet3 DuetWebServer[468]:       [DoCode] Executing code 'G28 X'
Mar 22 14:39:28 duet3 DuetControlServer[359]: [info] Executing nested macro file homex.g on channel HTTP
Mar 22 14:39:33 duet3 DuetControlServer[359]: [info] HTTP: Finished macro file homex.g
Mar 22 14:39:33 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Mar 22 14:39:33 duet3 DuetWebServer[468]:       Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
Mar 22 14:39:33 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
Mar 22 14:39:33 duet3 DuetWebServer[468]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 5771.5376ms
Mar 22 14:39:33 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Mar 22 14:39:33 duet3 DuetWebServer[468]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Mar 22 14:39:33 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Mar 22 14:39:33 duet3 DuetWebServer[468]:       Request finished in 5772.2764ms 200 text/plain; charset=utf-8

Danal

@Garfield said in Homing Inconsistent Duet 3:

This entry in the systemctl status states that it has been running since 00:29:41

Active: active (running) since Sun 2020-03-22 00:29:41 GMT; 12h ago

Regardless of the timezone that is incorrect

Excellent, thanks, let me look at that...

Garfield

The timezone / locale are correct - Europe/London

Danal

OK, it does say it started:

Sun 2020-03-22 00:29:41 GMT

and the latest timestamps are about 12 hours after that.

How long has the Pi been powered on at the moment you captured the logs? You said it "it was started at approx 10am". What time was it when you posted?

Your forum post time stamp says 7:53 AM, negative two hours, clearly one of the clocks somewhere is in a different time zone setting than some others...

Garfield

The 'hang' was around 12:30 - I'll check the forum profile - I don't do 07:53 on Sundays ...

Danal

@Garfield said in Homing Inconsistent Duet 3:

The timezone / locale are correct - Europe/London

Hey, fantastic, I lived in the New Barnet area (tiny bit South of the North East end of the black line) for a few months once while working a contract. REALLY enjoyed that area. Long ago; this was all the way back when the GLC existed. I was there when Parliament ordered them to dissolve and it became apparent that there would still be a some money on their last official day... so they threw a big party, "GLC day".

Long ago...

Of course, I'm talking about the London area, and you could be anywhere in that time zone.

Danal

@Garfield said in Homing Inconsistent Duet 3:

The 'hang' was around 12:30 - I'll check the forum profile - I don't do 07:53 on Sundays ...

Yeah, I kinda figured...

Danal

@Garfield said in Homing Inconsistent Duet 3:

sudo systemctl -l status duetcontrolserver

Just did mine, and it seems OK. I'll pay more attention to this for a few days:

sudo systemctl -l status duetcontrolserver
● duetcontrolserver.service - Duet Control Server
   Loaded: loaded (/lib/systemd/system/duetcontrolserver.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2020-03-22 13:33:24 CDT; 1h 24min ago
 Main PID: 359 (DuetControlServ)
    Tasks: 15 (limit: 4915)
   Memory: 50.3M
   CGroup: /system.slice/duetcontrolserver.service
           └─359 /opt/dsf/bin/DuetControlServer

Garfield

No worries. If there is anything that I can do to help nail this just drop me a line.

I've spent plenty of time in London for sure - in my IT career I've worked on Canary Wharf (various) / Whitehall / Nat West Tower / Lloyds of London / Deutsche Bank to name some of the larger ones, so I did almost live there - I stayed up in Edgware - couldn't deal with the none stop noise (I'm a country bum at heart) ... now living in the sticks within the Derbyshire High Peak.

The challenge is reproducing this 'hang' - it isn't predicatable and I've yet to find a sequence that will reproduce at will.

Where did you get the .Net dumps from - not seeing that in my Journal ? -

Garfield

Found this in the Journal. This is absolutely NOT the first time this Pi has been powered up, nor is it supposed to be using any time server but mine - which is set in the DNS / DHCP (run my own server).

Mar 22 00:30:01 duet3 DuetWebServer[445]:       [DoCode] Executing code 'G28'
Mar 22 00:30:02 duet3 DuetControlServer[340]: [info] Executing nested macro file homeall.g on channel HTTP
Mar 22 00:30:03 duet3 dhcpcd[409]: wlan0: failed to request information
Mar 22 00:30:11 duet3 systemd[1]: systemd-fsckd.service: Succeeded.
Mar 22 00:30:12 duet3 DuetControlServer[340]: [info] HTTP: Optional macro files deployprobe0.g and deployprobe.g not found
Mar 22 10:55:06 duet3 systemd-timesyncd[297]: Synchronized to time server for the first time 46.227.200.72:123 (2.debian.pool.ntp.org).
Mar 22 10:55:06 duet3 systemd[1]: Starting Daily apt upgrade and clean activities...
Mar 22 10:55:08 duet3 DuetControlServer[340]: [info] System time has been changed
Mar 22 10:55:08 duet3 systemd[1]: apt-daily-upgrade.service: Succeeded.
Mar 22 10:55:08 duet3 systemd[1]: Started Daily apt upgrade and clean activities.
Mar 22 10:55:55 duet3 CRON[879]: pam_unix(cron:session): session opened for user root by (uid=0)
Mar 22 10:55:55 duet3 CRON[883]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)

My .Net stuff seems to match yours pretty much.

Mar 22 11:35:34 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Mar 22 11:35:34 duet3 DuetWebServer[445]:       Request starting HTTP/1.1 POST http://10.100.2.225/machine/code text/plain;charset=UTF-8 5
Mar 22 11:35:34 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Cors.Infrastructure.CorsService[4]
Mar 22 11:35:34 duet3 DuetWebServer[445]:       CORS policy execution successful.
Mar 22 11:35:34 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Mar 22 11:35:34 duet3 DuetWebServer[445]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Mar 22 11:35:34 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
Mar 22 11:35:34 duet3 DuetWebServer[445]:       Route matched with {action = "DoCode", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] DoCode()
Mar 22 11:35:34 duet3 DuetWebServer[445]: info: DuetWebServer.Controllers.MachineController[0]
Mar 22 11:35:34 duet3 DuetWebServer[445]:       [DoCode] Executing code 'G28 X'
Mar 22 11:35:34 duet3 DuetControlServer[340]: [info] Executing nested macro file homex.g on channel HTTP
Mar 22 11:35:46 duet3 DuetControlServer[340]: [info] HTTP: Finished macro file homex.g
Mar 22 11:35:46 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Mar 22 11:35:46 duet3 DuetWebServer[445]:       Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
Mar 22 11:35:46 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
Mar 22 11:35:46 duet3 DuetWebServer[445]:       Executed action DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer) in 11945.7232ms
Mar 22 11:35:46 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Mar 22 11:35:46 duet3 DuetWebServer[445]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.DoCode (DuetWebServer)'
Mar 22 11:35:46 duet3 DuetWebServer[445]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]

Danal

@Garfield said in Homing Inconsistent Duet 3:

systemd-timesyncd[297]: Synchronized to time server for the first time

I find this message in my logs as well, shortly after my most recent power up. I believe timesyncd is saying "for the first time since this instance started"

 sudo journalctl | grep -B15 -A 10 "for the first"
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Request starting HTTP/1.1 GET http://duet3/machine/directory/0:%2Fmacros application/json
Mar 22 13:33:43 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer)'
Mar 22 13:33:43 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Route matched with {action = "GetFileList", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microso
ft.AspNetCore.Mvc.IActionResult] GetFileList(System.String) on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
Mar 22 13:33:43 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ContentResultExecutor[1]
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Executing ContentResult with HTTP Response ContentType of application/json
Mar 22 13:33:43 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Executed action DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer) in 63.9038ms
Mar 22 13:33:43 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Executed endpoint 'DuetWebServer.Controllers.MachineController.GetFileList (DuetWebServer)'
Mar 22 13:33:43 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
Mar 22 13:33:43 duet3 DuetWebServer[468]:       Request finished in 71.024ms 200 application/json
Mar 22 13:33:49 duet3 dhcpcd[433]: wlan0: DHCPv6 REPLY: No Addresses Available
Mar 22 13:33:53 duet3 systemd[1]: systemd-fsckd.service: Succeeded.
Mar 22 13:39:50 duet3 systemd-timesyncd[302]: Synchronized to time server for the first time 141.30.228.4:123 (2.debian.pool.ntp.org).
Mar 22 13:39:54 duet3 DuetControlServer[359]: [info] System time has been changed
Mar 22 13:40:01 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
Mar 22 13:40:01 duet3 DuetWebServer[468]:       Request starting HTTP/1.1 GET http://192.168.7.101/machine/file/0:%2Fsys%2Fconfig.g
Mar 22 13:40:01 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
Mar 22 13:40:01 duet3 DuetWebServer[468]:       Executing endpoint 'DuetWebServer.Controllers.MachineController.DownloadFile (DuetWebServer)'
Mar 22 13:40:01 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
Mar 22 13:40:01 duet3 DuetWebServer[468]:       Route matched with {action = "DownloadFile", controller = "Machine"}. Executing controller action with signature System.Threading.Tasks.Task`1[Micros
oft.AspNetCore.Mvc.IActionResult] DownloadFile(System.String) on controller DuetWebServer.Controllers.MachineController (DuetWebServer).
Mar 22 13:40:01 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.FileStreamResultExecutor[2]
Mar 22 13:40:01 duet3 DuetWebServer[468]:       Executing Microsoft.AspNetCore.Mvc.FileStreamResult, sending file with download name '' ...
Mar 22 13:40:01 duet3 DuetWebServer[468]: info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]

Danal

@Danal said in Homing Inconsistent Duet 3:

Mar 22 13:39:50 duet3 systemd-timesyncd[302]: Synchronized to time server for the first time 141.30.228.4:123 (2.debian.pool.ntp.org)

@Garfield said in Homing Inconsistent Duet 3:

Mar 22 10:55:06 duet3 systemd-timesyncd[297]: Synchronized to time server for the first time 46.227.200.72:123 (2.debian.pool.ntp.org).

Also, it certainly looks like your machine is using internet time servers. If you want it to use yours, check

/etc/systemd/timesyncd.conf

P.S. mine is at default, which is a file full of comments. The defaults are compiled in... uncomment and edit as appropriate to point to your servers.

dc42

@Luke-sLaboratory said in Homing Inconsistent Duet 3:

The problem is that N.O can't randomly close the connection

Yes it can! NO endstops are susceptible to capacitive coupling from other wires, e.g. motor, heater and fan wires. If you use NO endstops, you should use shielded endstop cables.

NC endstops are not susceptible to capacitive coupling. They can be susceptible to inductive coupling, which could possibly be a problem if you run endstop wires and stepper motor wires in the same cable bundle and neither is twisted pair wires; but this is much less likely than the problems you will get if you use the same cable bundles with NO endstop switches.

Luke'sLaboratory

@dc42 @Danal

I concede.

I'll never again have NO switches.

Thanks for the education.

Luke

Danal

Other forum reader's should know that Luke and I are both very active on the Jubilee discord.