Homing Inconsistent Duet 3
-
@spllg said in Homing Inconsistent Duet 3:
@Luke-sLaboratory i have no idea. the only thing i know is that after setting acceleration to a higher value homing[xy] ceased to work. after lowering acceleration homing was working. --> https://forum.duet3d.com/topic/14614/unable-to-home-xyz-using-my-homing-scripts?_=1584452867098
AHHH! New data point! (Maybe I missed it earlier). Let me think about that for a while.
-
@bearer
I agree in practice - My comment in this thread was addressing how much harder it is to get a false positive (switch shows ON when it shouldn't be) connection with a N.O switch.
I recognize the preferred convention is to fail safe by having a NC switch that should error check that its a closed circuit.
@spllg No clue there - It has been working with these values for several months, only recently has there been an issue.
@Danal Lmk when you figure it out - no issues sofar in RC4, but that's 3 datapoints
-
@Luke-sLaboratory said in Homing Inconsistent Duet 3:
I agree in practice - My comment in this thread was addressing how much harder it is to get a false positive (switch shows ON when it shouldn't be) connection with a N.O switch.
i would think a hard pull down to ground is more stable than a weak pull up when it comes to coupled or induced noise?
-
-
@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
-
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.
-
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
-
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
-
@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...
-
The timezone / locale are correct - Europe/London
-
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...
-
The 'hang' was around 12:30 - I'll check the forum profile - I don't do 07:53 on Sundays ...
-
@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.
-
@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...
-
@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
-
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 ? -
-
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]
-
@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 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.
-
@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.