Log current command being processed

[rhapsodyv]

This is a time saver for debugging, specially macros development.

Maybe it could be enabled with verbose logging. But testing it, it showed so useful that perhaps it could be enabled by default.

[JamesH1978]

Thank you for submitting a PR, pleas refer to point 3 in "What to expect in a review" in https://github.com/Klipper3d/klipper/blob/master/docs/CONTRIBUTING.md and provide a signed off by line.

I doubt this would be merged in its current form, as this would be very much log bulk and overwhelm smaller file system sizes and make the nornal log hard to read.

Thanks James

[rhapsodyv]

@JamesH1978 the stats logging generate very much more log than this in my tests.

It will, by average, generate log of the size of the gcode file per print.

It could be changed to debug output, but users may not benefit from it because I suspect not many users run klipply with -v flag.

I did it only to find the cause of an issue, but it showed so useful to understand any issue or the overall execution path that I did this PR.

[rhapsodyv]

A simple example of the output. It shows all execution path, even nested calls, and with expanded parameters.

G0 Z10 F1800
_KM_PRINT_STATUS ACTION=CHANGE STATUS=pop_status
G90
_KM_PRINT_STATUS ACTION=CHANGE STATUS=bed_heating RESET_STACK=1
SET_GCODE_VARIABLE MACRO=_km_print_status VARIABLE=last_status VALUE="'bed_heating'"
PARK
M400
Stats 1539557.7: gcodein=0  mcu: mcu_awake=0.220 mcu_task_avg=0.000096 mcu_task_stddev=0.000075 bytes_write=8128364 bytes_read=10696136 bytes_retransmit=9 bytes_invalid=0 send_seq=255608 receive_seq=255608 retransmit_seq=2 srtt=0.001 rttvar=0.001 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180003625 sb_can_th: mcu_awake=0.033 mcu_task_avg=0.000040 mcu_task_stddev=0.000066 bytes_write=1318747 bytes_read=4774048 bytes_retransmit=0 bytes_invalid=18 send_seq=148136 receive_seq=148136 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=48000240 adj=47999334 sd_pos=6324 heater_bed: target=82 temp=40.6 pwm=0.600 chamber: temp=25.7 bed_surface: temp=25.9 host: temp=48.9 sysload=1.36 cputime=5751.293 memavail=1448884 print_time=53475.814 buffer_time=0.599 print_stall=6 extruder: target=160 temp=112.4 pwm=0.500
_CHECK_KINEMATIC_LIMITS X="340.0" Y="355.0" Z="20.0"
_PARK_INNER X="340.0" Y="355.0" Z="20.0" P="2" LAZY="1"
SAVE_GCODE_STATE NAME=_KM_PARK
_KM_SAVE_GCODE_STATE NAME=_KM_PARK
_km_save_state NAME=_KM_PARK SAVE=1
SET_GCODE_VARIABLE MACRO=_km_save_state VARIABLE=is_ephemeral VALUE="1"
G90
G0 Z30.0 F600
G0 X340.0 Y355.0 F3000
RESTORE_GCODE_STATE NAME=_KM_PARK MOVE=0
_KM_RESTORE_GCODE_STATE NAME=_KM_PARK MOVE=0
_km_save_state NAME=_KM_PARK SAVE=0
SET_GCODE_VARIABLE MACRO=_km_save_state VARIABLE=is_ephemeral VALUE="1"
M190 S82.0
_KM_PRINT_STATUS ACTION=PUSH_STATUS
_KM_PRINT_STATUS ACTION=CHANGE STATUS=bed_heating
_GCODE_WAIT_WRAPPER HEATER=heater_bed  M="190" S="82.0"
SET_HEATER_TEMPERATURE_SCALED HEATER="heater_bed" TARGET=82.0
SET_HEATER_TEMPERATURE HEATER="heater_bed" TARGET=82.0
_GCODE_WAIT_WRAPPER_INNER HEATER="heater_bed" M="190" S="82.0"
TEMPERATURE_WAIT SENSOR="heater_bed" MINIMUM=82.0
Stats 1539558.7: gcodein=0  mcu: mcu_awake=0.220 mcu_task_avg=0.000096 mcu_task_stddev=0.000075 bytes_write=8134498 bytes_read=10697401 bytes_retransmit=9 bytes_invalid=0 send_seq=255759 receive_seq=255759 retransmit_seq=2 srtt=0.001 rttvar=0.001 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180003626 sb_can_th: mcu_awake=0.033 mcu_task_avg=0.000040 mcu_task_stddev=0.000066 bytes_write=1319347 bytes_read=4774538 bytes_retransmit=0 bytes_invalid=18 send_seq=148183 receive_seq=148183 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=48000241 adj=47999277 sd_pos=6324 heater_bed: target=82 temp=41.2 pwm=0.600 chamber: temp=25.3 bed_surface: temp=25.9 host: temp=48.8 sysload=1.33 cputime=5751.566 memavail=1448904 print_time=53481.177 buffer_time=4.961 print_stall=6 extruder: target=160 temp=116.3 pwm=0.500

[rhapsodyv]

Maybe two commands:

ENABLE_GCODE_LOGGING and DISABLE_GCODE_LOGGING, similar as ENABLE_FILAMENT_WIDTH_LOG.

So, anyone can enable/disable it at runtime. What do you think?

[github-actions[bot]]

Thank you for your contribution to Klipper. Unfortunately, a reviewer has not assigned themselves to this GitHub Pull Request. All Pull Requests are reviewed before merging, and a reviewer will need to volunteer. Further information is available at: https://www.klipper3d.org/CONTRIBUTING.html

There are some steps that you can take now:

1. Perform a self-review of your Pull Request by following the steps at: https://www.klipper3d.org/CONTRIBUTING.html#what-to-expect-in-a-review If you have completed a self-review, be sure to state the results of that self-review explicitly in the Pull Request comments. A reviewer is more likely to participate if the bulk of a review has already been completed.
2. Consider opening a topic on the Klipper Discourse server to discuss this work. The Discourse server is a good place to discuss development ideas and to engage users interested in testing. Reviewers are more likely to prioritize Pull Requests with an active community of users.
3. Consider helping out reviewers by reviewing other Klipper Pull Requests. Taking the time to perform a careful and detailed review of others work is appreciated. Regular contributors are more likely to prioritize the contributions of other regular contributors.

Unfortunately, if a reviewer does not assign themselves to this GitHub Pull Request then it will be automatically closed. If this happens, then it is a good idea to move further discussion to the Klipper Discourse server. Reviewers can reach out on that forum to let you know if they are interested and when they are available.

Best regards, ~ Your friendly GitIssueBot

PS: I'm just an automated script, not a human being.