2022-08-03 19:45:18.633 AbstractHeadMountable DEBUG: Top.moveTo((358.437000, 18.190000, -17.800000, 0.000000 mm), 1.0) 2022-08-03 19:45:18.634 Scripting TRACE: Scripting.on Camera.BeforeSettle 2022-08-03 19:45:18.635 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(M400 ; Wait for moves to complete before returning, 45000)... 2022-08-03 19:45:18.635 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(M114 ; get position, -1)... 2022-08-03 19:45:18.635 GcodeDriver TRACE: [serial://COM23] confirmed G1X358.8323F165.77 2022-08-03 19:45:18.635 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> M400 2022-08-03 19:45:18.641 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:18.641 GcodeDriver TRACE: [serial://COM23] confirmed M400 2022-08-03 19:45:18.641 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> M114 2022-08-03 19:45:18.663 GcodeDriver$ReaderThread TRACE: [serial://COM23] << X:358.8323 Y:16.6508 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2022-08-03 19:45:18.663 GcodeDriver TRACE: Position report: X:358.8323 Y:16.6508 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2022-08-03 19:45:18.664 GcodeDriver TRACE: TinyG got lastReportedLocation (x:358.832300, y:16.650800, Z:0.000000, C:0.000000) 2022-08-03 19:45:18.664 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:18.664 GcodeAsyncDriver TRACE: TinyG confirmation complete. 2022-08-03 19:45:18.664 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:18.794 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:18.795 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:19.114 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:19.119 AbstractSettlingCamera TRACE: autoSettleAndCapture t=455 auto settle score: 0.156 compute time: 5 2022-08-03 19:45:19.119 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:19.449 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:19.454 AbstractSettlingCamera TRACE: autoSettleAndCapture t=791 auto settle score: 0.156 compute time: 5 2022-08-03 19:45:19.454 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 791 ms 2022-08-03 19:45:19.454 Scripting TRACE: Scripting.on Camera.AfterSettle 2022-08-03 19:45:19.520 ReferencePushPullFeeder$FindFeatures DEBUG: calibrated vision offset is: (-0.000385, -0.000283, 0.000000, 0.222076 mm), length is: 0.000mm 2022-08-03 19:45:19.520 ReferencePushPullFeeder$FindFeatures DEBUG: calibrated pick location is: (358.437000, 18.190000, -17.800000, 89.777924 mm) 2022-08-03 19:45:19.547 AbstractHeadMountable DEBUG: Top.moveTo((358.437000, 18.190000, -17.800000, 0.000000 mm), 1.0) 2022-08-03 19:45:19.547 ReferencePushPullFeeder DEBUG: calibrating sprocket holes pass 0 midPoint is (354.891351, 18.174717, -17.800000, 0.000000 mm) 2022-08-03 19:45:19.547 ReferenceHead DEBUG: H1.moveToSafeZ(1.0) 2022-08-03 19:45:19.547 AbstractHeadMountable DEBUG: N.moveToSafeZ(1.0) 2022-08-03 19:45:19.548 AbstractHeadMountable DEBUG: Top.moveToSafeZ(1.0) 2022-08-03 19:45:19.548 AbstractHeadMountable DEBUG: Top.moveTo((358.437000, 18.190000, 0.000000, 0.000000 mm), 1.0) 2022-08-03 19:45:19.548 AbstractHeadMountable DEBUG: HEAD.moveToSafeZ(1.0) 2022-08-03 19:45:19.548 AbstractHeadMountable DEBUG: CPROBE.moveToSafeZ(1.0) 2022-08-03 19:45:19.548 AbstractHeadMountable DEBUG: Top.moveTo((354.891351, 18.174717, 0.000000, 0.000000 mm), 1.0) 2022-08-03 19:45:19.550 AbstractHeadMountable DEBUG: Top.moveTo((354.891351, 18.174717, -17.800000, 0.000000 mm), 1.0) 2022-08-03 19:45:19.552 Scripting TRACE: Scripting.on Camera.BeforeSettle 2022-08-03 19:45:19.553 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(M201.3 X59998 Y538, 45000)... 2022-08-03 19:45:19.553 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(G1 X355.4538 Y16.6205 F3331.72 ; move to target, 45000)... 2022-08-03 19:45:19.553 GcodeDriver TRACE: [serial://COM23] confirmed M114 2022-08-03 19:45:19.553 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(M201.3 X937, 45000)... 2022-08-03 19:45:19.553 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(G1 X355.1539 F165.77 ; move to target, 45000)... 2022-08-03 19:45:19.553 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(M400 ; Wait for moves to complete before returning, 45000)... 2022-08-03 19:45:19.553 GcodeAsyncDriver DEBUG: serial://COM23 commandQueue.offer(M114 ; get position, -1)... 2022-08-03 19:45:19.553 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> M201.3X59998Y538 2022-08-03 19:45:19.561 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:19.561 GcodeDriver TRACE: [serial://COM23] confirmed M201.3X59998Y538 2022-08-03 19:45:19.561 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> G1X355.4538Y16.6205F3331.72 2022-08-03 19:45:19.576 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:19.576 GcodeDriver TRACE: [serial://COM23] confirmed G1X355.4538Y16.6205F3331.72 2022-08-03 19:45:19.577 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> M201.3X937 2022-08-03 19:45:19.593 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:19.593 GcodeDriver TRACE: [serial://COM23] confirmed M201.3X937 2022-08-03 19:45:19.593 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> G1X355.1539F165.77 2022-08-03 19:45:19.609 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:19.609 GcodeDriver TRACE: [serial://COM23] confirmed G1X355.1539F165.77 2022-08-03 19:45:19.609 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> M400 2022-08-03 19:45:19.913 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:19.913 GcodeDriver TRACE: [serial://COM23] confirmed M400 2022-08-03 19:45:19.913 GcodeAsyncDriver$WriterThread TRACE: [serial://COM23] >> M114 2022-08-03 19:45:19.936 GcodeDriver$ReaderThread TRACE: [serial://COM23] << X:355.1539 Y:16.6205 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2022-08-03 19:45:19.936 GcodeDriver TRACE: Position report: X:355.1539 Y:16.6205 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2022-08-03 19:45:19.936 GcodeDriver$ReaderThread TRACE: [serial://COM23] << tinyg [mm] ok> 2022-08-03 19:45:19.936 GcodeDriver TRACE: TinyG got lastReportedLocation (x:355.153900, y:16.620500, Z:0.000000, C:0.000000) 2022-08-03 19:45:19.936 GcodeAsyncDriver TRACE: TinyG confirmation complete. 2022-08-03 19:45:19.936 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:19.943 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:19.945 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:20.106 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:20.110 AbstractSettlingCamera TRACE: autoSettleAndCapture t=174 auto settle score: 4.237 compute time: 4 2022-08-03 19:45:20.110 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:20.441 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:20.446 AbstractSettlingCamera TRACE: autoSettleAndCapture t=510 auto settle score: 0.165 compute time: 5 2022-08-03 19:45:20.446 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:20.777 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:20.782 AbstractSettlingCamera TRACE: autoSettleAndCapture t=846 auto settle score: 0.165 compute time: 5 2022-08-03 19:45:20.782 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 846 ms 2022-08-03 19:45:20.782 Scripting TRACE: Scripting.on Camera.AfterSettle 2022-08-03 19:45:20.849 ReferencePushPullFeeder$FindFeatures TRACE: [ReferencePushPullFeeder] calibrated hole locations are: (354.952483, 16.174717, -0.000000, 0.000000 mm), (354.952483, 20.174717, 0.000000, 0.000000 mm) 2022-08-03 19:45:20.850 ReferencePushPullFeeder$FindFeatures DEBUG: calibrated vision offset is: (-0.015483, 0.015283, 0.000000, 0.000000 mm), length is: 0.022mm 2022-08-03 19:45:20.850 ReferencePushPullFeeder$FindFeatures DEBUG: calibrated pick location is: (358.452483, 18.174717, -17.800000, 90.000000 mm) 2022-08-03 19:45:20.875 ReferencePushPullFeeder TRACE: new vision offset (-0.015483, 0.015283, 0.000000, 0.000000 mm) vs. previous vision offset (0.000000, 0.000000, 0.000000, 0.000000 mm) results in error 0.022mm at the (farthest) pick location 2022-08-03 19:45:20.875 ReferencePushPullFeeder TRACE: got OCR text 2022-08-03 19:45:20.879 Scripting TRACE: Scripting.on Camera.BeforeSettle 2022-08-03 19:45:20.879 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:21.100 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:21.102 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:21.435 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:21.441 AbstractSettlingCamera TRACE: autoSettleAndCapture t=562 auto settle score: 0.165 compute time: 6 2022-08-03 19:45:21.441 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:21.753 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:21.757 AbstractSettlingCamera TRACE: autoSettleAndCapture t=878 auto settle score: 0.164 compute time: 4 2022-08-03 19:45:21.758 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 878 ms 2022-08-03 19:45:21.758 Scripting TRACE: Scripting.on Camera.AfterSettle 2022-08-03 19:45:21.770 MaskHsv TRACE: Fraction actually masked = 2.5321584118387364E-6 2022-08-03 19:45:21.814 Scripting TRACE: Scripting.on Camera.BeforeSettle 2022-08-03 19:45:21.814 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:22.089 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:22.091 Scripting TRACE: Scripting.on Camera.BeforeCapture 2022-08-03 19:45:22.426 Scripting TRACE: Scripting.on Camera.AfterCapture 2022-08-03 19:45:22.431 AbstractSettlingCamera TRACE: autoSettleAndCapture t=617 auto settle score: 0.164 compute time: 5 2022-08-03 19:45:22.431 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 617 ms 2022-08-03 19:45:22.431 Scripting TRACE: Scripting.on Camera.AfterSettle 2022-08-03 19:45:22.486 AbstractMachine TRACE: Exception caught, executing pending motion: java.lang.Exception: No line of sprocket holes can be recognized at org.openpnp.machine.reference.feeder.ReferencePushPullFeeder$FindFeatures.invoke(ReferencePushPullFeeder.java:1563) at org.openpnp.machine.reference.feeder.ReferencePushPullFeeder.autoSetupPipeline(ReferencePushPullFeeder.java:1794) at org.openpnp.machine.reference.feeder.ReferencePushPullFeeder.autoSetup(ReferencePushPullFeeder.java:1775) at org.openpnp.machine.reference.feeder.wizards.ReferencePushPullFeederConfigurationWizard$9.lambda$null$0(ReferencePushPullFeederConfigurationWizard.java:763) at org.openpnp.util.UiUtils.lambda$submitUiMachineTask$0(UiUtils.java:39) at org.openpnp.spi.base.AbstractMachine$1.call(AbstractMachine.java:571) at java.util.concurrent.FutureTask.run(Unknown Source) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) 2022-08-03 19:45:22.487 MessageBoxes DEBUG: Error: java.lang.Exception: No line of sprocket holes can be recognized