Basic Information:
Printer Model: Ender-3 Pro
MCU / Printerboard: Creality v4.2.7
Host / SBC: Raspberry Pi 3 Model B running arch
klippy.log
Starting Klippy...
Args: ['/data/klipper/klipper/klippy/klippy.py', '/data/klipper/printers/ender3/config/printer.cfg', '-I', '/data/klipper/printers/ender3/klippy_tty', '-a', '/data/klipper/printers/ender3/klippy_uds', '-l', '/data/log/klipper/klipper-ender3.log']
Git version: 'v0.12.0-189-ge0cbd7b5'
Branch: master
Remote: origin
Tracked URL: https://github.com/Klipper3d/klipper.git
CPU: 4 core ARMv7 Processor rev 4 (v7l)
Python: '3.12.3 (main, Apr 27 2024, 17:17:26) [GCC 12.1.0]'
Start printer at Thu May 16 12:22:59 2024 (1715854980.0 4143.9)
===== Config file =====
(...snip...)
=======================
Extruder max_extrude_ratio=0.266081
mcu 'mcu': Starting serial connect
mcu 'mcu': Unable to open serial port: [Errno 2] could not open port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0: [Errno 2] No such file or directory: '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0'
webhooks client 3037281808: New connection
webhooks client 3037281808: Client info {'program': 'Moonraker', 'version': 'v0.8.0-358-gfca0cf3'}
mcu 'mcu': Unable to open serial port: [Errno 2] could not open port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0: [Errno 2] No such file or directory: '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0'
mcu 'mcu': Unable to open serial port: [Errno 2] could not open port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0: [Errno 2] No such file or directory: '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0'
mcu 'mcu': Unable to open serial port: [Errno 2] could not open port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0: [Errno 2] No such file or directory: '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0'
(...switching power ON...)
Loaded MCU 'mcu' 112 commands (v0.12.0-189-ge0cbd7b5 / gcc: (Arch Repository) 13.2.0 binutils: (GNU Binutils) 2.42)
MCU 'mcu' config: ADC_MAX=4095 BUS_PINS_i2c1=PB6,PB7 BUS_PINS_i2c1a=PB8,PB9 BUS_PINS_i2c2=PB10,PB11 BUS_PINS_spi1=PA6,PA7,PA5 BUS_PINS_spi1a=PB4,PB5,PB3 BUS_PINS_spi2=PB14,PB15,PB13 BUS_PINS_spi3=PB4,PB5,PB3 CLOCK_FREQ=72000000 MCU=stm32f103xe PWM_MAX=255 RECEIVE_WINDOW=192 RESERVE_PINS_serial=PA10,PA9 SERIAL_BAUD=250000 STATS_SUMSQ_BASE=256 STEPPER_BOTH_EDGE=1
Sending MCU 'mcu' printer configuration...
Configured MCU 'mcu' (1024 moves)
bed_mesh: generated points
Index | Tool Adjusted | Probe
0 | (43.0, 11.0) | (0.0, 4.0)
(...snip...)
24 | (248.0, 235.0) | (205.0, 228.0)
Starting heater checks for heater_bed
Starting heater checks for extruder
Stats 4169.4: gcodein=0 mcu: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=2069 bytes_read=4437 bytes_retransmit=9 bytes_invalid=0 send_seq=145 receive_seq=142 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=1685 upcoming_bytes=106 freq=72000705 heater_bed: target=0 temp=20.7 pwm=0.000 pi_soc: temp=58.0 sysload=0.82 cputime=4.815 memavail=812532 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=21.0 pwm=0.000
webhooks: registering remote method 'shutdown_machine' for connection id: 3037281808
webhooks: registering remote method 'reboot_machine' for connection id: 3037281808
webhooks: registering remote method 'pause_job_queue' for connection id: 3037281808
webhooks: registering remote method 'start_job_queue' for connection id: 3037281808
webhooks: registering remote method 'set_device_power' for connection id: 3037281808
Stats 4170.4: gcodein=0 mcu: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=4046 bytes_read=4753 bytes_retransmit=9 bytes_invalid=0 send_seq=182 receive_seq=182 retransmit_seq=2 srtt=0.004 rttvar=0.001 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72000858 heater_bed: target=0 temp=20.8 pwm=0.000 pi_soc: temp=58.0 sysload=0.82 cputime=4.865 memavail=812228 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
(...snip...)
Stats 4180.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5933 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72001545 heater_bed: target=0 temp=20.7 pwm=0.000 pi_soc: temp=56.4 sysload=0.77 cputime=5.264 memavail=813200 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
(...switching power OFF...)
b'Got EOF when reading from device'
Stats 4181.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5948 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=11 freq=72001545 heater_bed: target=0 temp=18.6 pwm=0.000 pi_soc: temp=56.4 sysload=0.77 cputime=5.302 memavail=812848 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
Stats 4182.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5948 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=12 freq=72001545 heater_bed: target=0 temp=18.6 pwm=0.000 pi_soc: temp=56.4 sysload=0.77 cputime=5.333 memavail=811684 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
Stats 4183.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5948 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=13 freq=72001545 heater_bed: target=0 temp=18.6 pwm=0.000 pi_soc: temp=56.4 sysload=0.77 cputime=5.366 memavail=811684 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
Stats 4184.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5948 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=14 freq=72001545 heater_bed: target=0 temp=18.6 pwm=0.000 pi_soc: temp=56.4 sysload=0.87 cputime=5.397 memavail=812196 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
Timeout with MCU 'mcu' (eventtime=4185.367193)
Transition to shutdown state: Lost communication with MCU 'mcu'
Dumping gcode input 0 blocks
Dumping 20 requests for client 3037281808
Received 4169.392833: b'{"id": 2807614656, "method": "objects/subscribe", "params": {"objects": {"webhooks": null}, "response_template": {"method": "process_status_update"}}}'
Received 4169.396740: b'{"id": 2807614728, "method": "gcode/subscribe_output", "params": {"response_template": {"method": "process_gcode_response"}}}'
Received 4169.400153: b'{"id": 2807615424, "method": "list_endpoints", "params": {}}'
Received 4169.407942: b'{"id": 2807619632, "method": "objects/subscribe", "params": {"objects": {"webhooks": null, "print_stats": null}, "response_template": {"method": "process_status_update"}}}'
Received 4169.592461: b'{"id": 2807621432, "method": "info", "params": {}}'
Received 4169.648771: b'{"id": 2807623160, "method": "objects/list", "params": {}}'
Received 4169.652461: b'{"id": 2807614728, "method": "objects/query", "params": {"objects": {"configfile": null}}}'
Received 4169.904380: b'{"id": 2807620208, "method": "register_remote_method", "params": {"response_template": {"method": "shutdown_machine"}, "remote_method": "shutdown_machine"}}'
Received 4169.906969: b'{"id": 2807447720, "method": "register_remote_method", "params": {"response_template": {"method": "reboot_machine"}, "remote_method": "reboot_machine"}}'
Received 4169.912745: b'{"id": 2807447720, "method": "register_remote_method", "params": {"response_template": {"method": "pause_job_queue"}, "remote_method": "pause_job_queue"}}'
Received 4169.918806: b'{"id": 2807447720, "method": "register_remote_method", "params": {"response_template": {"method": "start_job_queue"}, "remote_method": "start_job_queue"}}'
Received 4169.922038: b'{"id": 2807447720, "method": "register_remote_method", "params": {"response_template": {"method": "set_device_power"}, "remote_method": "set_device_power"}}'
Received 4169.929516: b'{"id": 2807623472, "method": "objects/query", "params": {"objects": {"heaters": null}}}'
Received 4169.931840: b'{"id": 2807623160, "method": "objects/query", "params": {"objects": {"heaters": null}}}'
Received 4170.149500: b'{"id": 2807622440, "method": "objects/subscribe", "params": {"objects": {"webhooks": null, "print_stats": null, "heater_bed": null, "temperature_sensor pi_soc": null, "extruder": null}, "response_template": {"method": "process_status_update"}}}'
Received 4170.401737: b'{"id": 2807622944, "method": "objects/subscribe", "params": {"objects": {"webhooks": null, "print_stats": null, "heater_bed": null, "temperature_sensor pi_soc": null, "extruder": null}, "response_template": {"method": "process_status_update"}}}'
Received 4171.706002: b'{"id": 2798805280, "method": "info", "params": {}}'
Received 4171.707627: b'{"id": 2807623616, "method": "objects/list", "params": {}}'
Received 4171.905094: b'{"id": 2807621672, "method": "objects/subscribe", "params": {"objects": {"gcode": null, "webhooks": null, "configfile": null, "mcu": null, "gcode_move": null, "probe": null, "bed_mesh": null, "screws_tilt_adjust": null, "heaters": null, "heater_bed": null, "fan": null, "display_status": null, "pwm_cycle_time BEEPER": null, "pause_resume": null, "idle_timeout": null, "gcode_macro stay_on": null, "gcode_macro allow_off": null, "gcode_macro START_PRINT": null, "gcode_macro END_PRINT": null, "gcode_macro PAUSE": null, "gcode_macro RESUME": null, "gcode_macro CANCEL_PRINT": null, "gcode_macro UNLOAD_FILAMENT": null, "gcode_macro LOAD_FILAMENT": null, "gcode_macro SET_FLOW": null, "gcode_macro M300": null, "gcode_macro BEEP": null, "gcode_macro BED_MESH_CALIBRATE_AREA": null, "gcode_macro PRIME_EXTRUDER": null, "print_stats": null, "virtual_sdcard": null, "gcode_macro POWER_ON": null, "gcode_macro POWER_OFF": null, "gcode_macro LED_ON": null, "gcode_macro LED_OFF": null, "gcode_macro REPORT": null, "temperature_host pi_soc": null, "temperature_sensor pi_soc": null, "stepper_enable": null, "motion_report": null, "query_endstops": null, "system_stats": null, "manual_probe": null, "toolhead": null, "extruder": null}, "response_template": {"method": "process_status_update"}}}'
Received 4172.464046: b'{"id": 2807623184, "method": "gcode/help", "params": {}}'
gcode state: absolute_coord=True absolute_extrude=True base_position=[0.0, 0.0, 0.0, 0.0] last_position=[0.0, 0.0, 0.0, 0.0] homing_position=[0.0, 0.0, 0.0, 0.0] speed_factor=0.016666666666666666 extrude_factor=1.0 speed=25.0
Reactor garbage collection: (4171.874275336, 0.0, 0.0)
Stats 4185.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5948 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=15 freq=72001545 heater_bed: target=0 temp=18.6 pwm=0.000 pi_soc: temp=55.8 sysload=0.87 cputime=5.431 memavail=812196 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
(...snip...)
Stats 4194.4: gcodein=0 mcu: mcu_awake=0.001 mcu_task_avg=0.000015 mcu_task_stddev=0.000010 bytes_write=4106 bytes_read=5948 bytes_retransmit=9 bytes_invalid=0 send_seq=192 receive_seq=192 retransmit_seq=2 srtt=0.004 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=25 freq=72001545 heater_bed: target=0 temp=18.6 pwm=0.000 pi_soc: temp=56.9 sysload=0.74 cputime=5.740 memavail=813156 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
(...Switching power ON...)
Unable to issue reset command on MCU 'mcu'
webhooks client 3037281808: Disconnected
Restarting printer
Start printer at Thu May 16 12:23:52 2024 (1715855032.5 4196.4)
===== Config file =====
(...snip...)
=======================
Extruder max_extrude_ratio=0.266081
mcu 'mcu': Starting serial connect
webhooks client 3027825816: New connection
webhooks client 3027825816: Client info {'program': 'Moonraker', 'version': 'v0.8.0-358-gfca0cf3'}
Loaded MCU 'mcu' 112 commands (v0.12.0-189-ge0cbd7b5 / gcc: (Arch Repository) 13.2.0 binutils: (GNU Binutils) 2.42)
MCU 'mcu' config: ADC_MAX=4095 BUS_PINS_i2c1=PB6,PB7 BUS_PINS_i2c1a=PB8,PB9 BUS_PINS_i2c2=PB10,PB11 BUS_PINS_spi1=PA6,PA7,PA5 BUS_PINS_spi1a=PB4,PB5,PB3 BUS_PINS_spi2=PB14,PB15,PB13 BUS_PINS_spi3=PB4,PB5,PB3 CLOCK_FREQ=72000000 MCU=stm32f103xe PWM_MAX=255 RECEIVE_WINDOW=192 RESERVE_PINS_serial=PA10,PA9 SERIAL_BAUD=250000 STATS_SUMSQ_BASE=256 STEPPER_BOTH_EDGE=1
Sending MCU 'mcu' printer configuration...
Configured MCU 'mcu' (1024 moves)
bed_mesh: generated points
Index | Tool Adjusted | Probe
0 | (43.0, 11.0) | (0.0, 4.0)
(...snip...)
24 | (248.0, 235.0) | (205.0, 228.0)
Starting heater checks for heater_bed
Starting heater checks for extruder
Stats 4201.4: gcodein=0 mcu: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=1950 bytes_read=4375 bytes_retransmit=0 bytes_invalid=0 send_seq=141 receive_seq=138 retransmit_seq=0 srtt=0.005 rttvar=0.002 rto=0.025 ready_bytes=1875 upcoming_bytes=10 freq=72001150 heater_bed: target=0 temp=0.0 pwm=0.000 pi_soc: temp=56.9 sysload=0.76 cputime=8.935 memavail=811692 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=0.0 pwm=0.000
webhooks: registering remote method 'shutdown_machine' for connection id: 3027825816
webhooks: registering remote method 'reboot_machine' for connection id: 3027825816
webhooks: registering remote method 'pause_job_queue' for connection id: 3027825816
webhooks: registering remote method 'start_job_queue' for connection id: 3027825816
webhooks: registering remote method 'set_device_power' for connection id: 3027825816
Stats 4202.4: gcodein=0 mcu: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=4062 bytes_read=4716 bytes_retransmit=0 bytes_invalid=0 send_seq=181 receive_seq=181 retransmit_seq=0 srtt=0.005 rttvar=0.002 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72001877 heater_bed: target=0 temp=20.7 pwm=0.000 pi_soc: temp=56.9 sysload=0.76 cputime=8.991 memavail=811704 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=21.0 pwm=0.000
Stats 4203.4: gcodein=0 mcu: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=4068 bytes_read=4837 bytes_retransmit=0 bytes_invalid=0 send_seq=182 receive_seq=182 retransmit_seq=0 srtt=0.005 rttvar=0.002 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72001277 heater_bed: target=0 temp=20.8 pwm=0.000 pi_soc: temp=56.9 sysload=0.76 cputime=9.031 memavail=811704 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=20.9 pwm=0.000
Stats 4204.4: gcodein=0 mcu: mcu_awake=0.055 mcu_task_avg=0.000195 mcu_task_stddev=0.000398 bytes_write=4074 bytes_read=4960 bytes_retransmit=0 bytes_invalid=0 send_seq=183 receive_seq=183 retransmit_seq=0 srtt=0.005 rttvar=0.001 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72002134 heater_bed: target=0 temp=20.7 pwm=0.000 pi_soc: temp=56.4 sysload=0.86 cputime=9.072 memavail=812976 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=21.0 pwm=0.000
Stats 4205.4: gcodein=0 mcu: mcu_awake=0.055 mcu_task_avg=0.000195 mcu_task_stddev=0.000398 bytes_write=4080 bytes_read=5081 bytes_retransmit=0 bytes_invalid=0 send_seq=184 receive_seq=184 retransmit_seq=0 srtt=0.005 rttvar=0.001 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72001743 heater_bed: target=0 temp=20.8 pwm=0.000 pi_soc: temp=56.9 sysload=0.86 cputime=9.118 memavail=812976 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=21.0 pwm=0.000
Stats 4206.4: gcodein=0 mcu: mcu_awake=0.055 mcu_task_avg=0.000195 mcu_task_stddev=0.000398 bytes_write=4086 bytes_read=5202 bytes_retransmit=0 bytes_invalid=0 send_seq=185 receive_seq=185 retransmit_seq=0 srtt=0.005 rttvar=0.001 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=72001701 heater_bed: target=0 temp=20.7 pwm=0.000 pi_soc: temp=56.4 sysload=0.86 cputime=9.163 memavail=812752 print_time=0.000 buffer_time=0.000 print_stall=0 extruder: target=0 temp=21.0 pwm=0.000
(...Switching power OFF => core dump ...)
Describe your issue:
After updating Klipper yesterday from 5edc7fee to commit e0cbd7b5, I’m getting systematic core dumps the second time the MCU is powered off (via a gpio-controlled relay).
Here is the traceback when that happens:
Fatal Python error: PyGILState_Release: auto-releasing thread-state, but no thread-state for this thread
Python runtime state: initialized
Thread 0xb46cf400 (most recent call first):
<no Python frame>
Thread 0xb3ece400 (most recent call first):
File "/data/klipper/klipper/klippy/serialhdl.py", line 39 in _bg_thread
File "/usr/lib/python3.12/threading.py", line 1010 in run
File "/usr/lib/python3.12/threading.py", line 1073 in _bootstrap_inner
File "/usr/lib/python3.12/threading.py", line 1030 in _bootstrap
Thread 0xb5bef400 (most recent call first):
File "/usr/lib/python3.12/threading.py", line 355 in wait
File "/usr/lib/python3.12/queue.py", line 171 in get
File "/data/klipper/klipper/klippy/queuelogger.py", line 34 in _bg_thread
File "/usr/lib/python3.12/threading.py", line 1010 in run
File "/usr/lib/python3.12/threading.py", line 1073 in _bootstrap_inner
File "/usr/lib/python3.12/threading.py", line 1030 in _bootstrap
Thread 0xb6830020 (most recent call first):
File "/data/klipper/klipper/klippy/reactor.py", line 342 in _dispatch_loop
Extension modules: greenlet._greenlet, _cffi_backend, markupsafe._speedups (total: 3)
I can work around the issue (manually restarting the service or using moonraker’s “bound_services” to do it automatically when switching the GPIO pin), but since this was not happening before, I figured this would not classify as expected behaviour.
The previous version I was using was commit 5edc7fee (last updated around October, 2023) and dit not have that issue.
Let me know if there is any additional info I can provide.