Closed Cellivar closed 3 months ago
Arksine
commented
3 months ago Hi. Can you reproduce with verbose logging enabled? Set the following environment variable:
MOONRAKER_VERBOSE_LOGGING="y"This will print out the actual data its attempting to decode, along with any potential errors during metadata extraction.
You could also try disabling msgspec and/or uvloop by modifying the environment.
MOONRAKER_ENABLE_MSGSPEC="n"
MOONRAKER_ENABLE_UVLOOP="n"
Cellivar
commented
3 months ago I would tell you when my print is going to finish and I can try those, but because of the failure I can't quite tell :D
I should be able to try those later today and report back.
Cellivar
commented
3 months ago Well that certainly explains the json error, it's blank.
...
[shell_command.py:_check_proc_success()] - Command (/home/moonraker/venv/bin/python /home/moonraker/moonraker/moonraker/components/file_manager/metadata.py -p /home/moonraker/printer_data/gcodes -f "test_file.gcode" --check-objects) successfully finished
[file_manager.py:_run_extract_metadata()] - Invalid metadata response:
bytearray(b'')
[file_manager.py:_process_metadata_update()] - Error running extract_metadata.py
Traceback (most recent call last):
...I can pretty reliably trigger this behavior, in my limited testing time right now I can't seem to cause a successful run to see how that differs from the blank value.
I then applied your suggested env vars to disable both libs with env vars. Success on the first try!
[application.py:post()] - Processing Uploaded File: test_file.gcode
[file_manager.py:_process_file_event()] - Inotify writable file closed: /home/moonraker/printer_data/gcodes/test_file.gcode
[shell_command.py:pipe_data_received()] - INFO:metadata:Object Processing is enabled
[shell_command.py:pipe_data_received()] - INFO:metadata:File 'test_file.gcode' currently supports cancellation, processing aborted
[file_manager.py:_process_file_event()] - Inotify writable file closed: /home/moonraker/printer_data/gcodes/.thumbs/test_file-48x48.png
[file_manager.py:_process_file_event()] - Inotify writable file closed: /home/moonraker/printer_data/gcodes/.thumbs/test_file-300x300.png
[file_manager.py:_process_file_event()] - Inotify writable file closed: /home/moonraker/printer_data/gcodes/.thumbs/test_file-32x32.png
[shell_command.py:_check_proc_success()] - Command (/home/moonraker/venv/bin/python /home/moonraker/moonraker/moonraker/components/file_manager/metadata.py -p /home/moonraker/printer_data/gcodes -f "test_file.gcode" --check-objects) successfully finished
[application.py:post()] - Upload Location header set: https://bildhauerkabine-moonraker.squeak.house/server/files/gcodes/test_file.gcode
[application.py:log_request()] - 201 POST /server/files/upload (192.168.1.57) [_TRUSTED_USER_] 1976.61ms
[common.py:_log_request()] - TransportType.WEBSOCKET Received::{"id": 64194, "method": "server.files.metadata", "jsonrpc": "2.0", "params": {"filename": "test_file.gcode"}}
[common.py:_log_response()] - TransportType.WEBSOCKET Response::{"jsonrpc": "2.0", "result": {"size": 8148280, "modified": 1722757041.1942768, "uuid": "ddbe5f94-d8a8-4321-8dd8-d9a8d48aceec", "slicer": "OrcaSlicer", "slicer_version": "2.1.1", "gcode_start_byte": 31185, "gcode_end_byte": 8132452, "layer_count": 98, "object_height": 19.6, "estimated_time": 10052, "nozzle_diameter": 0.4, "layer_height": 0.2, "first_layer_height": 0.2, "first_layer_extr_temp": 220.0, "first_layer_bed_temp": 60.0, "chamber_temp": 0.0, "filament_name": "Generic PLA", "filament_type": "PLA", "filament_total": 25679.95, "filament_weight_total": 76.59, "thumbnails": [{"width": 32, "height": 32, "size": 1495, "relative_path": ".thumbs/test_file-32x32.png"}, {"width": 48, "height": 48, "size": 1348, "relative_path": ".thumbs/test_file-48x48.png"}, {"width": 300, "height": 300, "size": 10264, "relative_path": ".thumbs/test_file-300x300.png"}], "print_start_time": null, "job_id": null, "filename": "test_file.gcode"}, "id": 64194}A stress test is in order. for f in *.gcode; do echo -e "\n" >> "${f}"; done;
And lo!
I need to kick off another print and head to bed, so I can't untangle whether msgspec or uvloop was the specific which fixed it. I should have time tomorrow to poke at it again, and I'm happy to perform any other specific debugging steps you think might help narrow down what's going on.
Arksine
commented
3 months ago My guess is the problem is uvloop. The msgspec package is just a replacement python's standard json encoder/decoder.
The uvloop module replaces the built-in asyncio eventloop. This could impact launching subprocesses. I don't know if its an issue with Python 3.12 or if there is something about the environment it doesn't like.
Arksine
commented
3 months ago This appears to be resolved (issue with uvloop), so I am going to close this.
nelsongraca
commented
2 months ago @Arksine I'm seeing this error as well, with python 3.12, anything I can do to help troubleshoot this?
Arksine
commented
2 months ago @nelsongraca Do you have uvloop installed? Attach moonraker.log and I will look into it.
What happened
Most of the time, but not all of the time, Moonraker fails to extract metadata from gcode files. The file prints correctly.
The logs show this line loading the json as the problem. It doesn't look like there's a lot of logging right around there so I'm uncertain if more verbose logging will help.
This is the error I see in my logs related to metadata parsing:
Additional context logs, though not particularly helpful
``` [application.py:prepare()] - Upload Request Received from 192.168.1.44 Content-Type: [application.py:prepare()] - Upload Request Received from 192.168.1.44 Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryFov2ibiAVBTX5PEA [application.py:post()] - Processing Uploaded File: test_file.gcode [shell_command.py:pipe_data_received()] - INFO:metadata:Object Processing is enabled [shell_command.py:pipe_data_received()] - INFO:metadata:File 'test_file.gcode' currently supports cancellation, processing aborted [shell_command.py:_check_proc_success()] - Command (/home/moonraker/venv/bin/python /home/moonraker/moonraker/moonraker/components/file_manager/metadata.py -p /home/moonraker/printer_data/gcodes -f "test_file.gcode" --check-objects) successfully finished [file_manager.py:_process_metadata_update()] - Error running extract_metadata.py Traceback (most recent call last): File "/home/moonraker/moonraker/moonraker/components/file_manager/file_manager.py", line 2520, in _process_metadata_update await self._run_extract_metadata(fname, ufp_path) File "/home/moonraker/moonraker/moonraker/components/file_manager/file_manager.py", line 2564, in _run_extract_metadata decoded_resp: Dict[str, Any] = jsonw.loads(result.strip()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ msgspec.DecodeError: Input data was truncated [shell_command.py:pipe_data_received()] - INFO:metadata:Object Processing is enabled [shell_command.py:pipe_data_received()] - INFO:metadata:File 'test_file.gcode' currently supports cancellation, processing aborted [shell_command.py:_check_proc_success()] - Command (/home/moonraker/venv/bin/python /home/moonraker/moonraker/moonraker/components/file_manager/metadata.py -p /home/moonraker/printer_data/gcodes -f "test_file.gcode" --check-objects) successfully finished [file_manager.py:_process_metadata_update()] - Error running extract_metadata.py Traceback (most recent call last): File "/home/moonraker/moonraker/moonraker/components/file_manager/file_manager.py", line 2520, in _process_metadata_update await self._run_extract_metadata(fname, ufp_path) File "/home/moonraker/moonraker/moonraker/components/file_manager/file_manager.py", line 2564, in _run_extract_metadata decoded_resp: Dict[str, Any] = jsonw.loads(result.strip()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ msgspec.DecodeError: Input data was truncated [shell_command.py:pipe_data_received()] - INFO:metadata:Object Processing is enabled [shell_command.py:pipe_data_received()] - INFO:metadata:File 'test_file.gcode' currently supports cancellation, processing aborted [shell_command.py:_check_proc_success()] - Command (/home/moonraker/venv/bin/python /home/moonraker/moonraker/moonraker/components/file_manager/metadata.py -p /home/moonraker/printer_data/gcodes -f "test_file.gcode" --check-objects) successfully finished [file_manager.py:_process_metadata_update()] - Error running extract_metadata.py Traceback (most recent call last): File "/home/moonraker/moonraker/moonraker/components/file_manager/file_manager.py", line 2520, in _process_metadata_update await self._run_extract_metadata(fname, ufp_path) File "/home/moonraker/moonraker/moonraker/components/file_manager/file_manager.py", line 2564, in _run_extract_metadata decoded_resp: Dict[str, Any] = jsonw.loads(result.strip()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ msgspec.DecodeError: Input data was truncated [file_manager.py:_process_metadata_update()] - Unable to extract medatadata from file: test_file.gcode [application.py:log_request()] - 201 POST /server/files/upload (192.168.1.44) [_TRUSTED_USER_] 4595.43ms [proc_stats.py:_watchdog_callback()] - EVENT LOOP BLOCKED: 4.22 seconds, total blocked count: 17 [proc_stats.py:log_last_stats()] - System Time: 1722658371.720620, Usage: 39.01%, Memory: 57932 kB System Time: 1722658372.722029, Usage: 3.92%, Memory: 57932 kB System Time: 1722658373.722189, Usage: 2.9%, Memory: 57932 kB System Time: 1722658374.721972, Usage: 1.49%, Memory: 57932 kB System Time: 1722658377.782000, Usage: 92.12%, Memory: 57932 kB ```This results in an amusing print history in Fluidd.
Client
Fluidd
Browser
Other or N/A
How to reproduce
The error occurs whenever Moonraker attempts to extract metadata. The behavior doesn't change depending on how Moonraker is triggered to read the metadata. I'm still trying to figure out why it sometimes works, but then a few hours later it will stop working.
This is the file I'm using for testing. It has printed successfully several times today.
test_file.zip
To test a bit more I connected to Moonraker and ran the command from the logs directly. The output appears to be well formed JSON:
Additional information
I run my printer software stack in Nomad using Docker. I construct a custom Docker image using this dockerfile which is deployed into my cluster with these docker parameters and this moonraker config file. The current image I'm running is based on this commit from July 5th.
My config disables file-based logging as I use a centralized log management system instead. If you would really prefer a file I can generate something close to a moonraker.log for you.
I suspect I'm the only one running Moonraker in the particular system configuration I use, and I am very willing to perform more debugging on my end if you can toss me some pointers. Python is not my forte so I will need a bit of guidance to help me help you :)
Thank you for all of your work on this software package, it's made my printing experience delightful.