Homing Inconsistent Duet 3

Luke'sLaboratory

I hear ya, I hear ya

The problem is that N.O can't randomly close the connection, Both ends on my switches are heat shrunk, and the other ends are properly sitting in their crimped spots.

If it was NC, yeah, if i had a poor connection, it would make sense if something broke, but here wires would have to wear+arc, and that isn't the case, at least as long as I can see, nor does it show up in firmware.

I found that If i power restart the machine, the first home works correctly, but any subsequent homes do not until reset again.

We'll see what RC4 brings us.

A Former User

@Luke-sLaboratory said in Homing Inconsistent Duet 3:

The problem is that N.O can't randomly close the connection, Both ends on my switches are heat shrunk, and the other ends are properly sitting in their crimped spots.

it has more to do connections breaking rather than being made; if the NO switch gets disconnected your homing will crash. If your NC switch becomes disconnected it can be detected and crashes avoided (although the common homing sequences does not seem to take advantage of that)

Danal

Bearer is correct on one of the prime underlying reasons for the industry "best practice" for NC.

Luke, in your case, I don't suspect wiring causing an issue in terms of a wire itself causing a false trigger... I've worked with you on other discords and you "do things right" on crimping and wiring and such... Instead, I suspect "noise" or a "floating wire" or "capacitance" or something similar. Can't prove it... really don't know why it used to work and works once after a power cycle... but I do know that NC puts the wiring in a "known state", namely hard pull to ground, until that switch clicks.

Danal

The more I think about that "works once after a power cycle" the more I become convinced this is a "floating wire" issue. After power cycle, that wire is ???? Neutral ??? I don't know what word to use.

After the first home (that works), the wire becomes "charged" or "discharged" or something.

Maybe.

spllg

@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

Danal

@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.

Luke'sLaboratory

@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

A Former User

@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?

Danal

@Luke-sLaboratory said in Homing Inconsistent Duet 3:

but that's 3 datapoints

lol

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