2024-04-03 22:27:16.517 Main INFO: Bienvenue, Bienvenido, Willkommen, Hello, Namaskar, Welkom, Bonjour to OpenPnP version 2024-03-27_09-59-31.0b0aca0. 2024-04-03 22:27:16.519 Scripting TRACE: Scripting.on Startup 2024-04-03 22:27:18.050 AbstractBroadcastingCamera TRACE: Camera DOWN thread 49 started. 2024-04-03 22:27:18.892 AbstractBroadcastingCamera TRACE: Camera Up_Logitech thread 51 started. 2024-04-03 22:27:37.418 ReferenceMachine DEBUG: setEnabled(true) 2024-04-03 22:27:37.421 GcodeDriver DEBUG: [Smoothie:COM4] Connect 2024-04-03 22:27:37.453 GcodeDriver TRACE: Smoothie waiting for connection 15000ms 2024-04-03 22:27:52.455 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G21 ; 2024-04-03 22:27:52.455 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G90 ; Set absolute positioning mode 2024-04-03 22:27:52.457 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:27:52.456 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G21 ; 2024-04-03 22:27:52.467 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M82 ; Set absolute mode for extruder 2024-04-03 22:27:52.467 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset 2024-04-03 22:27:52.467 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G90 ; Set absolute positioning mode 2024-04-03 22:27:52.468 GcodeDriver DEBUG: [Schultz:COM3] Connect 2024-04-03 22:27:52.468 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:27:52.468 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M82 ; Set absolute mode for extruder 2024-04-03 22:27:52.468 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:27:52.480 GcodeDriver TRACE: Schultz waiting for connection 3000ms 2024-04-03 22:27:52.541 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << Controller starting... 2024-04-03 22:27:52.543 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << Controller ready. 2024-04-03 22:27:55.482 GcodeAsyncDriver DEBUG: [Schultz:COM3] commandQueue offer >> G21 ; Set millimeters mode 2024-04-03 22:27:55.482 GcodeAsyncDriver DEBUG: [Schultz:COM3] commandQueue offer >> G90 ; Set absolute positioning mode 2024-04-03 22:27:55.482 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset 2024-04-03 22:27:55.482 GcodeAsyncDriver$WriterThread TRACE: [Schultz:COM3] >> G21 ; Set millimeters mode 2024-04-03 22:27:55.484 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << G21 ; Set millimeters mode 2024-04-03 22:27:55.487 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << ok unknown or empty command ignored 2024-04-03 22:27:55.488 GcodeDriver TRACE: [Schultz:COM3] confirmed G21 ; Set millimeters mode 2024-04-03 22:27:55.488 GcodeAsyncDriver$WriterThread TRACE: [Schultz:COM3] >> G90 ; Set absolute positioning mode 2024-04-03 22:27:55.492 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << G90 ; Set absolute positioning mode 2024-04-03 22:27:55.495 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << ok unknown or empty command ignored 2024-04-03 22:27:55.498 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:02.605 ReferenceMachine DEBUG: homing machine 2024-04-03 22:28:02.607 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S1000 ; set a low acceleration 2024-04-03 22:28:02.607 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G28 A0 Z0 2024-04-03 22:28:02.607 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G28 X88 Y42 B0 C0; Home all axes 2024-04-03 22:28:02.608 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G92 X0 Y0 Z0 A0 B0 C0; Set coordinates to zero. 2024-04-03 22:28:02.608 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S1000 ; set a low acceleration 2024-04-03 22:28:02.608 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G28 A0 Z0 2024-04-03 22:28:02.608 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:02.609 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset 2024-04-03 22:28:02.609 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G28 X88 Y42 B0 C0; Home all axes 2024-04-03 22:28:02.609 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G92 X0 Y0 Z0 A0 B0 C0; Set coordinates to zero. 2024-04-03 22:28:02.609 GcodeAsyncDriver DEBUG: [Schultz:COM3] commandQueue offer >> G28 ; Home all axes 2024-04-03 22:28:02.609 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset 2024-04-03 22:28:02.609 GcodeDriver TRACE: [Schultz:COM3] confirmed G90 ; Set absolute positioning mode 2024-04-03 22:28:02.609 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:02.609 GcodeAsyncDriver$WriterThread TRACE: [Schultz:COM3] >> G28 ; Home all axes 2024-04-03 22:28:02.609 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M114 ; get position 2024-04-03 22:28:02.610 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:02.610 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M114 ; get position 2024-04-03 22:28:02.611 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << G28 ; Home all axes 2024-04-03 22:28:02.614 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << ok unknown or empty command ignored 2024-04-03 22:28:03.685 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:08.520 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:08.521 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:08.521 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:08.522 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok C: X:0.0000 Y:0.0000 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:08.522 GcodeDriver TRACE: Position report: ok C: X:0.0000 Y:0.0000 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:08.523 GcodeDriver TRACE: Smoothie got lastReportedLocation (x:0.000000, y:0.000000, z1:0.000000, z2:0.000000, c1:0.000000, c2:0.000000) 2024-04-03 22:28:08.523 GcodeAsyncDriver TRACE: Smoothie confirmation complete. 2024-04-03 22:28:08.524 GcodeAsyncDriver DEBUG: [Schultz:COM3] commandQueue offer >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:08.524 GcodeDriver TRACE: [Schultz:COM3] confirmed G28 ; Home all axes 2024-04-03 22:28:08.524 GcodeAsyncDriver$WriterThread TRACE: [Schultz:COM3] >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:08.529 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << M400 ; Wait for moves to complete before returning 2024-04-03 22:28:08.532 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << ok unknown or empty command ignored 2024-04-03 22:28:08.533 GcodeDriver TRACE: [Schultz:COM3] confirmed M400 ; Wait for moves to complete before returning 2024-04-03 22:28:08.533 GcodeAsyncDriver TRACE: Schultz waited 9ms to drain command queue. 2024-04-03 22:28:08.533 GcodeAsyncDriver TRACE: Schultz confirmation complete. 2024-04-03 22:28:08.534 ReferenceHead DEBUG: H1.home() 2024-04-03 22:28:08.534 ReferenceFiducialLocator DEBUG: Looking for FIDUCIAL-HOME at (110.000000, 43.500000, -25.000000, 0.000000 mm) 2024-04-03 22:28:08.535 ReferenceHead DEBUG: H1.moveToSafeZ(0.9) 2024-04-03 22:28:08.535 AbstractHeadMountable DEBUG: N1.moveToSafeZ(0.9) 2024-04-03 22:28:08.535 AbstractHeadMountable DEBUG: N2.moveToSafeZ(0.9) 2024-04-03 22:28:08.536 AbstractHeadMountable DEBUG: N3.moveToSafeZ(0.9) 2024-04-03 22:28:08.536 AbstractHeadMountable DEBUG: N4.moveToSafeZ(0.9) 2024-04-03 22:28:08.536 AbstractHeadMountable DEBUG: DOWN.moveToSafeZ(0.9) 2024-04-03 22:28:08.536 AbstractHeadMountable DEBUG: DOWN.moveTo((110.000000, 43.500000, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:08.562 AbstractHeadMountable DEBUG: DOWN.moveTo((110.000000, 43.500000, -25.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:08.567 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S767 G1 X109.3513 Y42.9913 F18008 ; move to target 2024-04-03 22:28:08.568 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S767 G1 X109.3513 Y42.9913 F18008 ; move to target 2024-04-03 22:28:08.569 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:08.569 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S9 G1 X109.3213 Y43.4438 F120 ; move to target 2024-04-03 22:28:08.569 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S9 G1 X109.3213 Y43.4438 F120 ; move to target 2024-04-03 22:28:08.570 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:08.570 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M114 ; get position 2024-04-03 22:28:08.570 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:08.571 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:08.571 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M114 ; get position 2024-04-03 22:28:09.701 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:09.702 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok C: X:109.3213 Y:43.4438 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:09.702 GcodeDriver TRACE: Position report: ok C: X:109.3213 Y:43.4438 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:09.702 GcodeDriver TRACE: Smoothie got lastReportedLocation (x:109.321300, y:43.443800, z1:0.000000, z2:0.000000, c1:0.000000, c2:0.000000) 2024-04-03 22:28:09.703 GcodeAsyncDriver TRACE: Smoothie confirmation complete. 2024-04-03 22:28:09.703 ReferenceActuator DEBUG: UpCamLight.actuate(false) 2024-04-03 22:28:09.703 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M811 ; turn off Light 2024-04-03 22:28:09.703 Scripting TRACE: Scripting.on Camera.BeforeSettle 2024-04-03 22:28:09.703 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M811 ; turn off Light 2024-04-03 22:28:09.704 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:09.704 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:09.718 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:09.723 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:09.740 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:09.747 AbstractSettlingCamera TRACE: autoSettleAndCapture t=41 auto settle score: 18.039 compute time: 4 2024-04-03 22:28:09.747 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:09.769 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:09.774 AbstractSettlingCamera TRACE: autoSettleAndCapture t=70 auto settle score: 27.059 compute time: 4 2024-04-03 22:28:09.774 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:09.800 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:09.806 AbstractSettlingCamera TRACE: autoSettleAndCapture t=102 auto settle score: 23.137 compute time: 5 2024-04-03 22:28:09.806 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 102 ms 2024-04-03 22:28:09.806 Scripting TRACE: Scripting.on Camera.AfterSettle 2024-04-03 22:28:09.825 CvPipeline DEBUG: Stage "6" throws CvException [org.opencv.core.CvException: cv::Exception: OpenCV(4.5.5) C:\build\master_winpack-bindings-win64-vc14-static\opencv\modules\imgproc\src\thresh.cpp:1555: error: (-2:Unspecified error) in function 'double __cdecl cv::threshold(const class cv::_InputArray &,const class cv::_OutputArray &,double,double,int)' > THRESH_OTSU mode: > 'src_type == CV_8UC1 || src_type == CV_16UC1' > where > 'src_type' is 16 (CV_8UC3) ] 2024-04-03 22:28:09.862 ReferenceFiducialLocator DEBUG: FIDUCIAL-HOME located at (112.612773, 44.856249, -25.000000, 0.000000 mm) 2024-04-03 22:28:09.862 AbstractHeadMountable DEBUG: DOWN.moveTo((112.612773, 44.856249, -25.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:09.873 Scripting TRACE: Scripting.on Camera.BeforeSettle 2024-04-03 22:28:09.875 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S218 G1 X111.9641 Y44.3475 F1481 ; move to target 2024-04-03 22:28:09.875 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S218 G1 X111.9641 Y44.3475 F1481 ; move to target 2024-04-03 22:28:09.876 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:09.876 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S9 G1 X111.9340 Y44.8001 F120 ; move to target 2024-04-03 22:28:09.876 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:09.877 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S9 G1 X111.9340 Y44.8001 F120 ; move to target 2024-04-03 22:28:09.877 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M114 ; get position 2024-04-03 22:28:09.877 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:09.877 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M114 ; get position 2024-04-03 22:28:09.877 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:10.451 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:10.452 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok C: X:111.9340 Y:44.8001 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:10.452 GcodeDriver TRACE: Position report: ok C: X:111.9340 Y:44.8001 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:10.453 GcodeDriver TRACE: Smoothie got lastReportedLocation (x:111.934000, y:44.800100, z1:0.000000, z2:0.000000, c1:0.000000, c2:0.000000) 2024-04-03 22:28:10.456 GcodeAsyncDriver TRACE: Smoothie confirmation complete. 2024-04-03 22:28:10.456 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:10.466 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:10.470 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:10.478 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:10.482 AbstractSettlingCamera TRACE: autoSettleAndCapture t=26 auto settle score: 21.569 compute time: 4 2024-04-03 22:28:10.483 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:10.507 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:10.511 AbstractSettlingCamera TRACE: autoSettleAndCapture t=55 auto settle score: 32.941 compute time: 4 2024-04-03 22:28:10.512 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:10.537 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:10.542 AbstractSettlingCamera TRACE: autoSettleAndCapture t=85 auto settle score: 23.529 compute time: 4 2024-04-03 22:28:10.542 Scripting TRACE: Scripting.on Camera.BeforeCapture 2024-04-03 22:28:10.569 Scripting TRACE: Scripting.on Camera.AfterCapture 2024-04-03 22:28:10.574 AbstractSettlingCamera TRACE: autoSettleAndCapture t=117 auto settle score: 17.647 compute time: 3 2024-04-03 22:28:10.575 AbstractSettlingCamera DEBUG: autoSettleAndCapture in 118 ms 2024-04-03 22:28:10.575 Scripting TRACE: Scripting.on Camera.AfterSettle 2024-04-03 22:28:10.592 CvPipeline DEBUG: Stage "6" throws CvException [org.opencv.core.CvException: cv::Exception: OpenCV(4.5.5) C:\build\master_winpack-bindings-win64-vc14-static\opencv\modules\imgproc\src\thresh.cpp:1555: error: (-2:Unspecified error) in function 'double __cdecl cv::threshold(const class cv::_InputArray &,const class cv::_OutputArray &,double,double,int)' > THRESH_OTSU mode: > 'src_type == CV_8UC1 || src_type == CV_16UC1' > where > 'src_type' is 16 (CV_8UC3) ] 2024-04-03 22:28:10.627 ReferenceFiducialLocator DEBUG: FIDUCIAL-HOME located at (112.513049, 44.936028, -25.000000, 0.000000 mm) 2024-04-03 22:28:10.627 ReferenceFiducialLocator TRACE: FIDUCIAL-HOME less than max. linear offset 0.128mm < 0.200mm, locator satisfied. 2024-04-03 22:28:10.630 AbstractHeadMountable DEBUG: DOWN.moveTo((112.513049, 44.936028, -25.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:10.644 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S61 G1 X111.8644 F124 ; move to target 2024-04-03 22:28:10.644 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S61 G1 X111.8644 F124 ; move to target 2024-04-03 22:28:10.645 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S5 G1 X111.8343 Y44.8798 F60 ; move to target 2024-04-03 22:28:10.645 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:10.645 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S5 G1 X111.8343 Y44.8798 F60 ; move to target 2024-04-03 22:28:10.646 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G92 X-0.6787 Y-0.0562 ; reset coordinates 2024-04-03 22:28:10.646 ReferenceNozzle DEBUG: N1.home() 2024-04-03 22:28:10.646 ReferenceNozzle DEBUG: N2.home() 2024-04-03 22:28:10.646 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G92 X-0.6787 Y-0.0562 ; reset coordinates 2024-04-03 22:28:10.646 ReferenceNozzle DEBUG: N3.home() 2024-04-03 22:28:10.647 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:10.647 ReferenceNozzle DEBUG: N3.home() nozzle tip 505 ID3.5 calibration reset 2024-04-03 22:28:10.647 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:10.647 ReferenceNozzle DEBUG: N3.home() nozzle tip 504 ID1.5 calibration reset 2024-04-03 22:28:10.647 ReferenceNozzle DEBUG: N3.home() nozzle tip 506 ID5.0 calibration reset 2024-04-03 22:28:10.647 ReferenceNozzle DEBUG: N4.home() 2024-04-03 22:28:10.647 ReferenceNozzle DEBUG: N4.home() nozzle tip 505 ID3.5 calibration reset 2024-04-03 22:28:10.648 ReferenceNozzle DEBUG: N4.home() nozzle tip 504 ID1.5 calibration reset 2024-04-03 22:28:10.648 ReferenceNozzle DEBUG: N4.home() nozzle tip 506 ID5.0 calibration reset 2024-04-03 22:28:11.148 Scripting TRACE: Scripting.on Machine.AfterHoming 2024-04-03 22:28:11.149 ReferenceMachine INFO: setHomed(true) 2024-04-03 22:28:11.150 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:28.761 AbstractHeadMountable DEBUG: N1.moveTo((45.600259, 22.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:28.768 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S322 G1 X9.3513 F3409 ; move to target 2024-04-03 22:28:28.769 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S322 G1 X9.3513 F3409 ; move to target 2024-04-03 22:28:28.769 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S46 G1 X9.3213 F71 ; move to target 2024-04-03 22:28:28.770 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:28.770 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:28.770 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S46 G1 X9.3213 F71 ; move to target 2024-04-03 22:28:28.771 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:29.517 AbstractHeadMountable DEBUG: N1.moveTo((55.600259, 22.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:29.522 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S322 G1 X19.3513 F3409 ; move to target 2024-04-03 22:28:29.523 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S322 G1 X19.3513 F3409 ; move to target 2024-04-03 22:28:29.523 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S46 G1 X19.3213 F71 ; move to target 2024-04-03 22:28:29.523 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:29.523 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S46 G1 X19.3213 F71 ; move to target 2024-04-03 22:28:29.524 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:29.524 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:30.525 AbstractHeadMountable DEBUG: N1.moveTo((55.600259, 32.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:30.531 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S317 G1 Y9.4913 F3298 ; move to target 2024-04-03 22:28:30.531 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S317 G1 Y9.4913 F3298 ; move to target 2024-04-03 22:28:30.532 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S9 G1 Y9.9438 F120 ; move to target 2024-04-03 22:28:30.532 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:30.532 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S9 G1 Y9.9438 F120 ; move to target 2024-04-03 22:28:30.533 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:30.533 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:31.016 AbstractHeadMountable DEBUG: N1.moveTo((55.600259, 42.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:31.021 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S317 G1 Y19.4913 F3298 ; move to target 2024-04-03 22:28:31.022 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S317 G1 Y19.4913 F3298 ; move to target 2024-04-03 22:28:31.022 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S9 G1 Y19.9438 F120 ; move to target 2024-04-03 22:28:31.022 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:31.022 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S9 G1 Y19.9438 F120 ; move to target 2024-04-03 22:28:31.023 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:31.024 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:32.899 AbstractHeadMountable DEBUG: N1.moveTo((155.600259, 42.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:32.902 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S693 G1 X119.3513 F15793 ; move to target 2024-04-03 22:28:32.903 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S693 G1 X119.3513 F15793 ; move to target 2024-04-03 22:28:32.903 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S46 G1 X119.3213 F71 ; move to target 2024-04-03 22:28:32.903 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:32.903 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S46 G1 X119.3213 F71 ; move to target 2024-04-03 22:28:32.903 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:32.903 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M114 ; get position 2024-04-03 22:28:32.903 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M400 ; Wait for moves to complete before returning 2024-04-03 22:28:32.904 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:32.904 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M114 ; get position 2024-04-03 22:28:32.904 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:33.715 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:33.716 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok C: X:119.3213 Y:19.9438 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:33.716 GcodeDriver TRACE: Position report: ok C: X:119.3213 Y:19.9438 Z:0.0000 A:0.0000 B:0.0000 C:0.0000 2024-04-03 22:28:33.717 GcodeDriver TRACE: Smoothie got lastReportedLocation (x:119.321300, y:19.943800, z1:0.000000, z2:0.000000, c1:0.000000, c2:0.000000) 2024-04-03 22:28:33.717 GcodeAsyncDriver TRACE: Smoothie confirmation complete. 2024-04-03 22:28:33.717 ReferenceActuator DEBUG: UpCamLight.actuate(true) 2024-04-03 22:28:33.717 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M810 ; turn on Light 2024-04-03 22:28:33.717 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M810 ; turn on Light 2024-04-03 22:28:33.718 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:33.803 AbstractHeadMountable DEBUG: N1.moveTo((155.600259, 142.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:33.806 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S684 G1 Y119.4913 F15658 ; move to target 2024-04-03 22:28:33.806 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S684 G1 Y119.4913 F15658 ; move to target 2024-04-03 22:28:33.806 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S9 G1 Y119.9438 F120 ; move to target 2024-04-03 22:28:33.807 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:33.807 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S9 G1 Y119.9438 F120 ; move to target 2024-04-03 22:28:33.807 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:33.808 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:45.970 AbstractHeadMountable DEBUG: N1.moveTo((155.600259, 142.600471, 0.000000, -10.000000 mm), 0.9) 2024-04-03 22:28:45.972 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S5 G1 B-10.0000 F429 ; move to target 2024-04-03 22:28:45.972 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:45.973 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S5 G1 B-10.0000 F429 ; move to target 2024-04-03 22:28:45.973 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:28:49.481 AbstractHeadMountable DEBUG: N1.moveTo((155.600259, 142.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:28:49.484 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S5 G1 B0.0000 F429 ; move to target 2024-04-03 22:28:49.484 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:28:49.486 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S5 G1 B0.0000 F429 ; move to target 2024-04-03 22:28:49.486 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:29:11.161 AbstractHeadMountable DEBUG: N1.moveTo((155.600259, 142.600471, 0.000000, 0.000000 mm), 0.9) 2024-04-03 22:29:11.162 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:29:14.340 ReferenceMachine DEBUG: homing machine 2024-04-03 22:29:14.340 ReferenceMachine INFO: setHomed(false) 2024-04-03 22:29:14.341 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M204 S1000 ; set a low acceleration 2024-04-03 22:29:14.341 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G28 A0 Z0 2024-04-03 22:29:14.341 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G28 X88 Y42 B0 C0; Home all axes 2024-04-03 22:29:14.341 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> G92 X0 Y0 Z0 A0 B0 C0; Set coordinates to zero. 2024-04-03 22:29:14.341 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset 2024-04-03 22:29:14.341 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M204 S1000 ; set a low acceleration 2024-04-03 22:29:14.341 GcodeAsyncDriver DEBUG: [Schultz:COM3] commandQueue offer >> G28 ; Home all axes 2024-04-03 22:29:14.341 GcodeDriver TRACE: Send-on-change logic for Feed Rate, Acceleration and Jerk reset 2024-04-03 22:29:14.341 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G28 A0 Z0 2024-04-03 22:29:14.341 GcodeAsyncDriver$WriterThread TRACE: [Schultz:COM3] >> G28 ; Home all axes 2024-04-03 22:29:14.341 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M400 ; Wait for moves to complete before returning 2024-04-03 22:29:14.341 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G28 X88 Y42 B0 C0; Home all axes 2024-04-03 22:29:14.342 GcodeAsyncDriver DEBUG: [Smoothie:COM4] commandQueue offer >> M114 ; get position 2024-04-03 22:29:14.342 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] << ok 2024-04-03 22:29:14.342 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> G92 X0 Y0 Z0 A0 B0 C0; Set coordinates to zero. 2024-04-03 22:29:14.342 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M400 ; Wait for moves to complete before returning 2024-04-03 22:29:14.342 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] >> M114 ; get position 2024-04-03 22:29:14.343 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << G28 ; Home all axes 2024-04-03 22:29:14.346 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] << ok unknown or empty command ignored 2024-04-03 22:30:07.128 ReferenceMachine DEBUG: setEnabled(false) 2024-04-03 22:30:07.128 ReferenceMachine INFO: setHomed(false) 2024-04-03 22:30:07.128 GcodeDriver TRACE: [Schultz:COM3] confirmed G28 ; Home all axes 2024-04-03 22:30:07.129 GcodeDriver$ReaderThread TRACE: [Schultz:COM3] Read error while disconnecting (expected) 2024-04-03 22:30:07.230 GcodeAsyncDriver$WriterThread TRACE: [Schultz:COM3] disconnectRequested, bye-bye. 2024-04-03 22:30:07.230 GcodeDriver$ReaderThread TRACE: [Smoothie:COM4] Read error while disconnecting (expected) 2024-04-03 22:30:07.331 GcodeAsyncDriver$WriterThread TRACE: [Smoothie:COM4] disconnectRequested, bye-bye. 2024-04-03 22:30:14.343 AbstractMachine TRACE: Exception caught, executing pending motion: java.lang.Exception: Smoothie timeout waiting for response to M114 ; get position at org.openpnp.machine.reference.driver.GcodeDriver.getReportedLocation(GcodeDriver.java:775) at org.openpnp.machine.reference.driver.GcodeAsyncDriver.waitForCompletion(GcodeAsyncDriver.java:383) at org.openpnp.machine.reference.driver.AbstractMotionPlanner.waitForDriverCompletion(AbstractMotionPlanner.java:853) at org.openpnp.machine.reference.driver.AbstractMotionPlanner.waitForCompletion(AbstractMotionPlanner.java:764) at org.openpnp.machine.reference.driver.AbstractMotionPlanner.home(AbstractMotionPlanner.java:115) at org.openpnp.machine.reference.ReferenceMachine.home(ReferenceMachine.java:530) at org.openpnp.gui.MachineControlsPanel$HomeAction.lambda$actionPerformed$0(MachineControlsPanel.java:420) 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:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:833) 2024-04-03 22:30:14.343 AbstractMotionPlanner DEBUG: Reported location changes current location from (x:119.321259, y:119.890471, z1:0.000000, z2:0.000000, c1:0.000000, c2:0.000000) to (x:0.000000, y:0.000000, z1:0.000000, z2:0.000000, c1:0.000000, c2:0.000000) 2024-04-03 22:30:14.344 AbstractMachine TRACE: Machine entering idle state. 2024-04-03 22:30:14.346 MessageBoxes DEBUG: Error: java.lang.Exception: Smoothie timeout waiting for response to M114 ; get position