GcodeAsyncDriver and lumpnpnp (Marlin)

[Toby Dickenson]

Hi all,

I previously wrote how GcodeAsyncDriver was not working with my lumenpnp machine. Today I had a chance to try it again and capture some logs. I enabled GcodeAsyncDriver using I&S, but left NullMotionPlanner for now.

I have Confirmation Flow Control turned on.

My HOME_COMMAND is quite long:

M914 X100 Y80 ; set sensitivity
M204 T2000 ; Sets acceleration for homing
G28 X ; 1st attempt to home x
G4 P500
G28 X ; 2nd attempt to home x
G4 P500
G28 Y; 1st attempt to home y
G4 P500
G28 Y; 2nd attempt to home y
G4 P500
G28 Y ; 3rd attempt to home y
G28 Z
M204 S20000 ; acceleration for next move
G1 X0 Y100 F20000 ; move away from push pull feeders

Log during homing is below, with some comments inline. It looks to me like openpnp is running the homing fiducial locator long before the machine arrives at the fiducial, so its a synchronisation problem? I would appreciate any suggestions.

2025-03-12 20:55:30.642 ReferenceMachine DEBUG: homing machine
2025-03-12 20:55:30.643 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M914 X100 Y80 ; set sensitivity
2025-03-12 20:55:30.643 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M204 T2000 ; Sets acceleration for homing
2025-03-12 20:55:30.643 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G28 X ; 1st attempt to home x
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G4 P500
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G28 X ; 2nd attempt to home x
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G4 P500
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G28 Y; 1st attempt to home y
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G4 P500
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G28 Y; 2nd attempt to home y
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G4 P500
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G28 Y ; 3rd attempt to home y
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G28 Z
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M204 S20000 ; acceleration for next move
2025-03-12 20:55:30.644 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G1 X0 Y100 F20000 ; move away from push pull feeders
2025-03-12 20:55:30.645 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset
2025-03-12 20:55:30.645 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M114
2025-03-12 20:55:30.645 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M400 ; Wait for moves to complete before returning
2025-03-12 20:55:30.645 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M114 ; get position
2025-03-12 20:55:30.646 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M914X100Y80
2025-03-12 20:55:30.657 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:30.657 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M914X100Y80
2025-03-12 20:55:30.658 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M204T2000
2025-03-12 20:55:30.658 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:30.658 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M204T2000
2025-03-12 20:55:30.658 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G28X
2025-03-12 20:55:32.495 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:32.495 GcodeDriver TRACE: Position report: X:0.00 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:32.495 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset
2025-03-12 20:55:32.495 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:32.495 GcodeDriver TRACE: Lumen got lastReportedLocation (x:0.000000, y:187.930000, z1:0.000000, a:-20.160000, b:22.090000)
2025-03-12 20:55:32.495 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G28X
2025-03-12 20:55:32.496 GcodeAsyncDriver TRACE: Lumen confirmation complete.
2025-03-12 20:55:32.496 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G4P500
2025-03-12 20:55:32.496 AbstractMotionPlanner DEBUG: Reported location changes current location from (x:-0.037434, y:0.000000, z1:0.000000, a:-20.160000, b:22.090000) to (x:0.000000, y:187.930000, z1:0.000000, a:-20.160000, b:22.090000)
2025-03-12 20:55:32.496 Scripting TRACE: Scripting.on Machine.AfterDriverHoming
2025-03-12 20:55:32.496 Scripting TRACE: Scripting.on found Machine.AfterDriverHoming.bsh
2025-03-12 20:55:32.497 Scripting TRACE: bsh.engine.BshScriptEngine@257c910b scripting engine borrowed from pool in 0.060164 milliseconds
2025-03-12 20:55:32.502 Scripting TRACE: Script Machine.AfterDriverHoming.bsh executed in 4.801442 milliseconds
2025-03-12 20:55:32.502 ReferenceHead DEBUG: H1.home()
2025-03-12 20:55:32.502 ReferenceFiducialLocator DEBUG: Looking for FIDUCIAL-HOME at (218.148000, 187.429000, -28.170000, 0.000000 mm)
2025-03-12 20:55:32.502 ReferenceHead DEBUG: H1.moveToSafeZ(1.0)
2025-03-12 20:55:32.503 AbstractHeadMountable DEBUG: N1.moveToSafeZ(1.0)
2025-03-12 20:55:32.503 AbstractHeadMountable DEBUG: N2.moveToSafeZ(1.0)
2025-03-12 20:55:32.503 AbstractHeadMountable DEBUG: Top.moveToSafeZ(1.0)
2025-03-12 20:55:32.503 AbstractHeadMountable DEBUG: VAC1.moveToSafeZ(1.0)
2025-03-12 20:55:32.503 AbstractHeadMountable DEBUG: VAC2.moveToSafeZ(1.0)
2025-03-12 20:55:32.503 AbstractHeadMountable DEBUG: Hook.moveToSafeZ(1.0)
2025-03-12 20:55:32.504 AbstractHeadMountable DEBUG: Top.moveTo((218.148000, 187.429000, 0.000000, 0.000000 mm), 1.0)
2025-03-12 20:55:32.513 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M204 S1967
2025-03-12 20:55:32.513 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G1 X217.6350     F36000 ; move to target
2025-03-12 20:55:32.514 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M204 S11
2025-03-12 20:55:32.515 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G1  Y187.9268    F600 ; move to target
2025-03-12 20:55:32.515 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M400 ; Wait for moves to complete before returning
2025-03-12 20:55:32.515 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M114 ; get position
2025-03-12 20:55:32.995 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:32.996 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G4P500
2025-03-12 20:55:32.996 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G28X
2025-03-12 20:55:33.691 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:33.692 GcodeDriver TRACE: Position report: X:0.00 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:33.694 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset
2025-03-12 20:55:33.694 GcodeDriver TRACE: Lumen got lastReportedLocation (x:0.000000, y:187.930000, z1:0.000000, a:-20.160000, b:22.090000)
2025-03-12 20:55:33.695 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:33.695 GcodeAsyncDriver TRACE: Lumen confirmation complete.
2025-03-12 20:55:33.695 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G28X
2025-03-12 20:55:33.695 AbstractMotionPlanner DEBUG: Reported location changes current location from (x:217.597578, y:187.926798, z1:0.000000, a:-20.160000, b:22.090000) to (x:-0.037434, y:187.930000, z1:0.000000, a:-20.160000, b:22.090000)
2025-03-12 20:55:33.695 AbstractHeadMountable DEBUG: Top.moveTo((218.148000, 187.429000, -28.170000, 0.000000 mm), 1.0)
2025-03-12 20:55:33.698 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G4P500
2025-03-12 20:55:33.703 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M204 S1967
2025-03-12 20:55:33.703 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G1 X217.6350     F36000 ; move to target
2025-03-12 20:55:33.703 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M204 S11
2025-03-12 20:55:33.704 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> G1  Y187.9268    F600 ; move to target
2025-03-12 20:55:33.704 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M400 ; Wait for moves to complete before returning
2025-03-12 20:55:33.704 GcodeAsyncDriver DEBUG: [Lumen:ttyACM0] commandQueue offer >> M114 ; get position
2025-03-12 20:55:34.195 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:34.195 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G4P500
2025-03-12 20:55:34.196 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G28Y
2025-03-12 20:55:35.679 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << Selected home phase 896 too close to endstop trigger phase 850. Pick a different phase for Y
2025-03-12 20:55:35.867 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:35.868 GcodeDriver TRACE: Position report: X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:35.868 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset
2025-03-12 20:55:35.868 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:35.868 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G28Y
2025-03-12 20:55:35.868 GcodeDriver TRACE: Lumen got lastReportedLocation (x:0.000000, y:0.000000, z1:0.000000, a:-20.160000, b:22.090000)
2025-03-12 20:55:35.868 GcodeAsyncDriver TRACE: Lumen confirmation complete.
2025-03-12 20:55:35.868 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G4P500
2025-03-12 20:55:35.869 AbstractMotionPlanner DEBUG: Reported location changes current location from (x:217.597578, y:187.926798, z1:0.000000, a:-20.160000, b:22.090000) to (x:-0.037434, y:0.000000, z1:0.000000, a:-20.160000, b:22.090000)

openpnp is operating the camera here, so it must think the machine is over the homing fiducial. In reality the machine is still performing G28 homing.

2025-03-12 20:55:35.869 ReferenceFiducialLocator INFO: Setting maxDistance override because this pipeline does not have a maxDistance stage
2025-03-12 20:55:35.869 Scripting TRACE: Scripting.on Camera.BeforeSettle
2025-03-12 20:55:35.870 Scripting TRACE: Scripting.on Camera.BeforeCapture
2025-03-12 20:55:35.898 Scripting TRACE: Scripting.on Camera.AfterCapture
2025-03-12 20:55:35.902 Scripting TRACE: Scripting.on Camera.BeforeCapture
2025-03-12 20:55:35.936 Scripting TRACE: Scripting.on Camera.AfterCapture
2025-03-12 20:55:35.941 AbstractSettlingCamera TRACE: autoSettleAndCapture t=72 auto settle score: 1.961 compute time: 5
2025-03-12 20:55:35.942 Scripting TRACE: Scripting.on Camera.BeforeCapture
2025-03-12 20:55:35.966 Scripting TRACE: Scripting.on Camera.AfterCapture
2025-03-12 20:55:35.972 AbstractSettlingCamera TRACE: autoSettleAndCapture t=103 auto settle score: 1.961 compute time: 6
2025-03-12 20:55:35.975 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 106 ms
2025-03-12 20:55:35.977 Scripting TRACE: Scripting.on Camera.AfterSettle
2025-03-12 20:55:35.994 CvPipeline DEBUG: Stage "circleA" throws java.lang.Exception: Circular symmetry stage: search range is cropped to nothing.
2025-03-12 20:55:35.996 CvPipeline DEBUG: Stage "results" throws java.lang.Exception: Circular symmetry stage: search range is cropped to nothing.
2025-03-12 20:55:35.999 CvPipeline DEBUG: Stage "draw" throws java.lang.Exception: Circular symmetry stage: search range is cropped to nothing.
2025-03-12 20:55:36.016 AbstractMachine TRACE: Exception caught, executing pending motion: java.lang.Exception: Circular symmetry stage: search range is cropped to nothing.
at org.openpnp.vision.pipeline.stages.DetectCircularSymmetry.findCircularSymmetry(DetectCircularSymmetry.java:446)
at org.openpnp.vision.pipeline.stages.DetectCircularSymmetry.process(DetectCircularSymmetry.java:306)
at org.openpnp.vision.pipeline.CvPipeline.process(CvPipeline.java:274)
at org.openpnp.machine.reference.vision.ReferenceFiducialLocator.detectFiducialFromViewpoint(ReferenceFiducialLocator.java:620)
at org.openpnp.machine.reference.vision.ReferenceFiducialLocator.getFiducialLocation(ReferenceFiducialLocator.java:563)
at org.openpnp.machine.reference.vision.ReferenceFiducialLocator.getHomeFiducialLocation(ReferenceFiducialLocator.java:441)
at org.openpnp.machine.reference.ReferenceHead.visualHome(ReferenceHead.java:77)
at org.openpnp.machine.reference.ReferenceHead.home(ReferenceHead.java:56)
at org.openpnp.spi.base.AbstractMachine.home(AbstractMachine.java:301)
at org.openpnp.machine.reference.ReferenceMachine.home(ReferenceMachine.java:536)
at org.openpnp.gui.MachineControlsPanel$HomeAction.lambda$actionPerformed$0(MachineControlsPanel.java:427)
at org.openpnp.util.UiUtils.lambda$submitUiMachineTask$0(UiUtils.java:67)
at org.openpnp.spi.base.AbstractMachine$1.call(AbstractMachine.java:575)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2025-03-12 20:55:36.016 AbstractMachine TRACE: Machine entering idle state.
2025-03-12 20:55:36.150 MessageBoxes DEBUG: Error: java.lang.Exception: Circular symmetry stage: search range is cropped to nothing.
2025-03-12 20:55:36.368 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:36.368 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G4P500
2025-03-12 20:55:36.369 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G28Y
2025-03-12 20:55:37.079 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:37.080 GcodeDriver TRACE: Position report: X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:37.080 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:37.080 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G28Y
2025-03-12 20:55:37.081 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G4P500
2025-03-12 20:55:37.580 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:37.580 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G4P500
2025-03-12 20:55:37.580 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G28Y
2025-03-12 20:55:38.287 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:38.287 GcodeDriver TRACE: Position report: X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:38.288 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:38.288 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G28Y

This G28Z command is near the end of the homing gcode. The timestamp for this is correct.

2025-03-12 20:55:38.288 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G28Z
2025-03-12 20:55:40.288 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << echo:busy: processing
2025-03-12 20:55:41.019 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:41.019 GcodeDriver TRACE: Position report: X:0.00 Y:0.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:0 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:41.020 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.020 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G28Z
2025-03-12 20:55:41.020 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M204S20000
2025-03-12 20:55:41.020 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.020 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M204S20000
2025-03-12 20:55:41.021 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.021 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G1X0Y100F20000
2025-03-12 20:55:41.021 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G1X0Y100F20000
2025-03-12 20:55:41.021 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M400
2025-03-12 20:55:41.583 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.584 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M400

This is the M400 which I understood should should be the trigger to start using the camera.

2025-03-12 20:55:41.584 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M114
2025-03-12 20:55:41.585 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:0.00 Y:100.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:32000 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:41.585 GcodeDriver TRACE: Position report: X:0.00 Y:100.00 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:0 Y:32000 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:41.585 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset
2025-03-12 20:55:41.586 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.586 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M114
2025-03-12 20:55:41.586 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M204S1967
2025-03-12 20:55:41.587 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.587 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M204S1967
2025-03-12 20:55:41.588 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.588 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G1X217.635F36000
2025-03-12 20:55:41.588 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G1X217.635F36000
2025-03-12 20:55:41.588 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M204S11
2025-03-12 20:55:41.588 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.589 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M204S11
2025-03-12 20:55:41.589 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:41.589 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G1Y187.9268F600
2025-03-12 20:55:41.589 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G1Y187.9268F600
2025-03-12 20:55:41.590 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M400
2025-03-12 20:55:43.590 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << echo:busy: processing
2025-03-12 20:55:45.590 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << echo:busy: processing
2025-03-12 20:55:47.590 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << echo:busy: processing
2025-03-12 20:55:49.590 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << echo:busy: processing
2025-03-12 20:55:51.590 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << echo:busy: processing
2025-03-12 20:55:53.247 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.247 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M400
2025-03-12 20:55:53.247 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M114
2025-03-12 20:55:53.248 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:217.63 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:69643 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:53.248 GcodeDriver TRACE: Position report: X:217.63 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:69643 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:53.248 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset
2025-03-12 20:55:53.248 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.248 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M114
2025-03-12 20:55:53.249 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M204S1967
2025-03-12 20:55:53.249 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.249 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M204S1967
2025-03-12 20:55:53.249 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G1X217.635F36000
2025-03-12 20:55:53.249 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.250 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G1X217.635F36000
2025-03-12 20:55:53.250 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M204S11
2025-03-12 20:55:53.251 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.251 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M204S11
2025-03-12 20:55:53.251 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> G1Y187.9268F600
2025-03-12 20:55:53.251 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.251 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed G1Y187.9268F600
2025-03-12 20:55:53.251 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M400
2025-03-12 20:55:53.252 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok
2025-03-12 20:55:53.252 GcodeDriver TRACE: [Lumen:ttyACM0] confirmed M400
2025-03-12 20:55:53.252 GcodeAsyncDriver$WriterThread TRACE: [Lumen:ttyACM0] >> M114
2025-03-12 20:55:53.252 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << X:217.63 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:69643 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:53.252 GcodeDriver TRACE: Position report: X:217.63 Y:187.93 Z:0.00 A:-20.16 B:22.09 C:10000.00 Count X:69643 Y:60137 Z:1260 A:-90 B:98 C:400000
2025-03-12 20:55:53.253 GcodeDriver$ReaderThread TRACE: [Lumen:ttyACM0] << ok

[jbussmann]

Hi Toby,

Coincidentally I'm at my LumenPnP right no so I gave it a go. I have also replaced the GcodeDriver using Issues & Solutions but left everything else like NullMotionPlanner and Flow Control is on. Your configurations file suggests though, that you turned it off. Are you sure it is on? I don't think it matters though.

For me homing with a single G28 command works as expected. If I use multiple G28 commands, I observe the exact same behaviour as you. What is the reason for your long homing sequence? 

I think what happens is the following:

- Homing commands are queued and OpenPnP waits for standstill.

- First homing G28X returns with position report, which is interpreted as standstill.

- The driver is considered homed (Script Machine.AfterDriverHoming).

- Commands for moving camera to fiducial location at safe z are queued and OpenPnP waits for standstill.

- Second homing G28X returns with position report, which is interpreted as standstill.

- The machine is considered to be at the fiducial location.

- Commands for moving camera to fiducial location at effective z are queued and OpenPnP waits for standstill.

- Homing G28Y returns with position report, which is interpreted as standstill.

- The machine is considered ready for fiducial detection and camera is actuated.

- Interestingly, at this very moment G4P500 is executed and the head is at standstill which makes camera settling work but detection fail none the less.

After skimming through the code, it seems to me as if the issue lies here, where in AbstractMotionPlanner.home() GcodeAsyncDriver.waitForCompletion(null, CompletionType.WaitForStillstandIndefinitely) is called. BTW: this must be from a German speaking programmer, as in English it's standstill and not standstill, fell for it too. GcodeDriver.waitForCompletion() falls through because MOVE_TO_COMPLETE_REGEX == null. GcodeAsyncDriver.waitForCompletion() somewhat catches this by calling getReportedLocation(). Unfortunately, the G28 command's response matches the POSITION_REPORT_REGEX and therefore returns the waitForCompletion().

How to go about this?

- Home all exes with one single G28 command.

- Ideally, there would be a MOVE_TO_COMPLETE_REGEX, which matches the M400's response which would solve everything. Since M400 simply returns ok, I don't see how this can be done reliably.

- Instead of getReportedLocation(), drainCommandQueue() could be called, if reportedLocationConfirmation == false. Disabling location confirmation indeed solves the problem for me. I can only find the ContactProbeNozzle to use this, which you don't seem to use.

- Maybe drainCommandQueue() either way? If WaitForStillstandIndefinitely is requested, I don't see why draining the queue altogether would be bad? 

[Toby Dickenson]

Hi jbussman, thank you for the help here

 

If I use multiple G28 commands, I observe the exact same behaviour as you. What is the reason for your long homing sequence? 

Your v4 lumenpnp has microswitches for reliable homing. My v3 uses sensorless homing. It detects the increase in stepper motor current when the gantry crashes into the end of the rail, but quite often this triggers prematurely.

Have you been using the GcodeAsyncDriver previously?

 

- First homing G28X returns with position report, which is interpreted as standstill.

Aha! Well spotted. G28 generates a position report. In Marlin source code this comes from the report_current_position function. I only see this called from M114, G28, and various other gcodes that openpnp doesnt use. So it should all be ok once it gets beyond homing.

 

- Maybe drainCommandQueue() either way? If WaitForStillstandIndefinitely is requested, I don't see why draining the queue altogether would be bad? 

That makes sense to me. Thank you again :-)

This might also be the kick I need to recompile Marlin and fit some microswitches.

Toby

[Jan]

Resend.

On 13.03.2025 10:48, Jan wrote:
> Hi Toby!
>     First off, your log does not look like Confirmation Flow Control is
> enabled and the machine.xml confirms "confirmation-flow-
> control="false"" (line 2129).
>     I tried to understand your log and it seems, that Marlin is
> returning something that looks like a position report for G28. This may
> confuse the logic that waits for homing to complete. I'm not an expert
> in that, so this conclusion might be wrong. I'd suggest to find a
> POSITION_REPORT_REGEX that only matches the data returned by M114.
>
>     Jan

>> --
>> You received this message because you are subscribed to the Google
>> Groups "OpenPnP" group.
>> To unsubscribe from this group and stop receiving emails from it, send
>> an email to openpnp+u...@googlegroups.com
>> <mailto:openpnp+u...@googlegroups.com>.
>> To view this discussion visit https://groups.google.com/d/msgid/
>> openpnp/
>> CAH35urcLGLrE18trJ8jSmBWLq5oFSUHNPZGG64%3DmWuLm%2Bv1KOQ%40mail.gmail.com <https://groups.google.com/d/msgid/openpnp/ CAH35urcLGLrE18trJ8jSmBWLq5oFSUHNPZGG64%3DmWuLm%2Bv1KOQ%40mail.gmail.com?utm_medium=email&utm_source=footer>.
>

[jbussmann]

> My v3 uses sensorless homing. It detects the increase in stepper motor current when the gantry crashes into the end of the rail, but quite often this triggers prematurely.

Is it not possible to tune the sensitivity in such a way that it works reliably?

> Have you been using the GcodeAsyncDriver previously?

Only for small tests. I think as long as I'm using the NullMotionPlanner, it doesn't bring much of a benefit? What is your motivation to use the GcodeAsyncDriver ?

>  I'd suggest to find a POSITION_REPORT_REGEX that only matches the data returned by M114.

Thought about this too, but since it seems to be the same position report, it's probably impossible.

@Toby

Since you already have Machine.AfterDriverHoming.bsh, why not use this to drain the command queue?

[Toby Dickenson]

> Have you been using the GcodeAsyncDriver previously?

Only for small tests. I think as long as I'm using the NullMotionPlanner, it doesn't bring much of a benefit?

Yes, it is much smoother. The synchronous driver operates in ping-pong mode between java, usb (in my case), and machine firmware, so there is an inevitable pause between *every* movement. The asynchronous driver can eliminate that if you enable "allow continuous motion". After only a few hours of having it working I am looking forward to seeing the results in a production run. A comparison: https://www.youtube.com/shorts/csXjDh3k38k

What is your motivation to use the GcodeAsyncDriver ?

Jan was surprised that I was using NullMotionPlanner when I reported the prerotate-all-nozzles feedback, so I thought I would give it another chance.

(https://groups.google.com/d/msgid/openpnp/c1206f63-083e-4beb-ad46-b14f4464facb%40googlemail.com)

@Toby

Since you already have Machine.AfterDriverHoming.bsh, why not use this to drain the command queue?  

Thread.sleep(12*1000) in that script was the first thing that got this working.  But your "Maybe drainCommandQueue() either way" suggestion is cleaner (thank you again!) so I will do a PR for that.

 

Toby

[jbussmann]

> Yes, it is much smoother.

The "much" might be a bit of a stretch, but I see what you mean. :)

> Jan was surprised that I was using NullMotionPlanner when I reported the prerotate-all-nozzles feedback, so I thought I would give it another chance.

I have seen that and it motivated me to do some research. So you want to switch to AdvancedMotionPlanner and then, which motion control type will you go for. To be honest, I would really like to give simulated 3rd order a try. But in the default config, Marlin can only queue 4 commands. Do you have any thoughts on that?

> Thread.sleep(12*1000) in that script was the first thing that got this working.

Was my first thought too, but felt too hacky of a suggestion to mention it.

>  I will do a PR for that.

Looking forward to what you come up with. I couldn't really think of a way to go about it, that doesn't potentially affect many other things.

[Toby Dickenson]

On Thu, 13 Mar 2025 at 19:26, jbussmann <j.bus...@hotmail.com> wrote:

So you want to switch to AdvancedMotionPlanner and then,

Yes

 

which motion control type will you go for.

I have been using ModeratedConstantAcceleration with NullMotionPlanner for a while now, and that still looks to be the best choice with AdvancedMotionPlanner.

 

To be honest, I would really like to give simulated 3rd order a try. But in the default config, Marlin can only queue 4 commands. Do you have any thoughts on that?

I tried it today and had glitches on long movements. There was no difference after reducing the Maximum Number of Jerk Steps, or disabling Confirmation Flow Control. I can try again if anyone has any suggestions for other parameters that might help.

[Toby Dickenson]

>  I will do a PR for that.

Looking forward to what you come up with. I couldn't really think of a way to go about it, that doesn't potentially affect many other things.

We dont need any code changes here. The HOME_COMPLETE_REGEX feature is enough for openpnp to skip over the unexpected output during homing. This just needs a command with a distinctive output to act as a barrier at the end of homing. I added M404 at the end of my HOME_COMMAND, which has the response:

Unknown command: "M404"

Which I matched with the regex:

.*Unknown.*M404.*

:-)