Merge branch 'master' of https://github.com/Arksine/moonraker

moonraker/app.py

@@ -881,6 +881,7 @@ def initialize(self,
 
     def prepare(self) -> None:
         super(FileUploadHandler, self).prepare()
+        logging.info(f"Upload Request Received from {self.request.remote_ip}")
         fm: FileManager = self.server.lookup_component("file_manager")
         fm.check_write_enabled()
         if self.request.method == "POST":
@@ -932,6 +933,7 @@ async def post(self) -> None:
             debug_msg += f"\n{name}: {value}"
         debug_msg += f"\nChecksum: {calc_chksum}"
         logging.debug(debug_msg)
+        logging.info(f"Processing Uploaded File: {self._file.multipart_filename}")
         try:
             result = await self.file_manager.finalize_upload(form_args)
         except ServerError as e:

moonraker/common.py

@@ -581,8 +581,8 @@ def build_error(
     ) -> Dict[str, Any]:
         if method_name:
             method_name = f"Requested Method: {method_name}, "
-        log_msg = f"JSON-RPC Request Error - {method_name}Code: {code}\n{msg}"
-        if is_exc:
+        log_msg = f"JSON-RPC Request Error - {method_name}Code: {code}, Message: {msg}"
+        if is_exc and self.verbose:
             logging.exception(log_msg)
         else:
             logging.info(log_msg)

moonraker/components/file_manager/file_manager.py

@@ -2468,9 +2468,11 @@ async def _run_extract_metadata(self,
         if self.enable_object_proc:
             timeout = 300.
             cmd += " --check-objects"
-        shell_cmd: SCMDComp = self.server.lookup_component('shell_command')
-        scmd = shell_cmd.build_shell_command(cmd, log_stderr=True)
-        result = await scmd.run_with_response(timeout=timeout)
+        result = bytearray()
+        sc: SCMDComp = self.server.lookup_component('shell_command')
+        scmd = sc.build_shell_command(cmd, callback=result.extend, log_stderr=True)
+        if not await scmd.run(timeout=timeout):
+            raise self.server.error("Extract Metadata returned with error")
         try:
             decoded_resp: Dict[str, Any] = json.loads(result.strip())
         except Exception:

moonraker/components/file_manager/metadata.py

@@ -17,6 +17,7 @@
 import zipfile
 import shutil
 import uuid
+import logging
 from PIL import Image
 
 # Annotation imports
@@ -35,9 +36,8 @@
 UFP_MODEL_PATH = "/3D/model.gcode"
 UFP_THUMB_PATH = "/Metadata/thumbnail.png"
 
-def log_to_stderr(msg: str) -> None:
-    sys.stderr.write(f"{msg}\n")
-    sys.stderr.flush()
+logging.basicConfig(stream=sys.stderr, level=logging.INFO)
+logger = logging.getLogger("metadata")
 
 # regex helpers
 def _regex_find_floats(pattern: str,
@@ -144,12 +144,12 @@ def _check_has_objects(self,
         if match is not None:
             # Objects already processed
             fname = os.path.basename(self.path)
-            log_to_stderr(
+            logger.info(
                 f"File '{fname}' currently supports cancellation, "
                 "processing aborted"
             )
             if match.group(1).startswith("DEFINE_OBJECT"):
-                log_to_stderr(
+                logger.info(
                     "Legacy object processing detected.  This is not "
                     "compatible with official versions of Klipper."
                 )
@@ -229,7 +229,7 @@ def parse_thumbnails(self) -> Optional[List[Dict[str, Any]]]:
             try:
                 os.mkdir(thumb_dir)
             except Exception:
-                log_to_stderr(f"Unable to create thumb dir: {thumb_dir}")
+                logger.info(f"Unable to create thumb dir: {thumb_dir}")
                 return None
         thumb_base = os.path.splitext(os.path.basename(self.path))[0]
         parsed_matches: List[Dict[str, Any]] = []
@@ -239,12 +239,12 @@ def parse_thumbnails(self) -> Optional[List[Dict[str, Any]]]:
             info = _regex_find_ints(r".*", lines[0])
             data = "".join(lines[1:-1])
             if len(info) != 3:
-                log_to_stderr(
+                logger.info(
                     f"MetadataError: Error parsing thumbnail"
                     f" header: {lines[0]}")
                 continue
             if len(data) != info[2]:
-                log_to_stderr(
+                logger.info(
                     f"MetadataError: Thumbnail Size Mismatch: "
                     f"detected {info[2]}, actual {len(data)}")
                 continue
@@ -283,7 +283,7 @@ def parse_thumbnails(self) -> Optional[List[Dict[str, Any]]]:
                         'relative_path': rel_path_small
                     })
             except Exception as e:
-                log_to_stderr(str(e))
+                logger.info(str(e))
         return parsed_matches
 
     def parse_layer_count(self) -> Optional[int]:
@@ -564,7 +564,7 @@ def parse_thumbnails(self) -> Optional[List[Dict[str, Any]]]:
                     'relative_path': rel_path_small
                 })
         except Exception as e:
-            log_to_stderr(str(e))
+            logger.info(str(e))
             return None
         return thumbs
 
@@ -978,10 +978,10 @@ def process_objects(file_path: str, slicer: BaseSlicer, name: str) -> bool:
             preprocess_m486
         )
     except ImportError:
-        log_to_stderr("Module 'preprocess-cancellation' failed to load")
+        logger.info("Module 'preprocess-cancellation' failed to load")
         return False
     fname = os.path.basename(file_path)
-    log_to_stderr(
+    logger.info(
         f"Performing Object Processing on file: {fname}, "
         f"sliced by {name}"
     )
@@ -999,15 +999,15 @@ def process_objects(file_path: str, slicer: BaseSlicer, name: str) -> bool:
                     elif isinstance(slicer, IdeaMaker):
                         processor = preprocess_ideamaker
                     else:
-                        log_to_stderr(
+                        logger.info(
                             f"Object Processing Failed, slicer {name}"
                             "not supported"
                         )
                         return False
                     for line in processor(in_file):
                         out_file.write(line)
                 except Exception as e:
-                    log_to_stderr(f"Object processing failed: {e}")
+                    logger.info(f"Object processing failed: {e}")
                     return False
         if os.path.islink(file_path):
             file_path = os.path.realpath(file_path)
@@ -1065,7 +1065,7 @@ def extract_metadata(
 
 def extract_ufp(ufp_path: str, dest_path: str) -> None:
     if not os.path.isfile(ufp_path):
-        log_to_stderr(f"UFP file Not Found: {ufp_path}")
+        logger.info(f"UFP file Not Found: {ufp_path}")
         sys.exit(-1)
     thumb_name = os.path.splitext(
         os.path.basename(dest_path))[0] + ".png"
@@ -1088,12 +1088,12 @@ def extract_ufp(ufp_path: str, dest_path: str) -> None:
                     os.mkdir(dest_thumb_dir)
                 shutil.move(tmp_thumb_path, dest_thumb_path)
     except Exception:
-        log_to_stderr(traceback.format_exc())
+        logger.info(traceback.format_exc())
         sys.exit(-1)
     try:
         os.remove(ufp_path)
     except Exception:
-        log_to_stderr(f"Error removing ufp file: {ufp_path}")
+        logger.info(f"Error removing ufp file: {ufp_path}")
 
 def main(path: str,
          filename: str,
@@ -1105,12 +1105,12 @@ def main(path: str,
         extract_ufp(ufp, file_path)
     metadata: Dict[str, Any] = {}
     if not os.path.isfile(file_path):
-        log_to_stderr(f"File Not Found: {file_path}")
+        logger.info(f"File Not Found: {file_path}")
         sys.exit(-1)
     try:
         metadata = extract_metadata(file_path, check_objects)
     except Exception:
-        log_to_stderr(traceback.format_exc())
+        logger.info(traceback.format_exc())
         sys.exit(-1)
     fd = sys.stdout.fileno()
     data = json.dumps(
@@ -1145,5 +1145,5 @@ def main(path: str,
     args = parser.parse_args()
     check_objects = args.check_objects
     enabled_msg = "enabled" if check_objects else "disabled"
-    log_to_stderr(f"Object Processing is {enabled_msg}")
+    logger.info(f"Object Processing is {enabled_msg}")
     main(args.path, args.filename, args.ufp, check_objects)

moonraker/components/shell_command.py

@@ -46,15 +46,13 @@ def __init__(
         self,
         limit: int,
         loop: asyncio.events.AbstractEventLoop,
-        program_name: str = "",
         std_out_cb: OutputCallback = None,
         std_err_cb: OutputCallback = None,
         log_stderr: bool = False
     ) -> None:
         self._loop = loop
         self._pipe_fds: List[int] = []
         super().__init__(limit, loop)
-        self.program_name = program_name
         self.std_out_cb = std_out_cb
         self.std_err_cb = std_err_cb
         self.log_stderr = log_stderr
@@ -94,7 +92,7 @@ def pipe_data_received(self, fd: int, data: bytes | str) -> None:
                     msg = data.decode(errors='ignore')
                 else:
                     msg = data
-                logging.info(f"{self.program_name}: {msg}")
+                logging.info(msg)
         if cb is not None:
             if isinstance(data, str):
                 data = data.encode()
@@ -288,9 +286,9 @@ async def _create_subprocess(
 
         def protocol_factory():
             return ShellCommandProtocol(
-                limit=2**20, loop=loop, program_name=self.command[0],
-                std_out_cb=self.std_out_cb, std_err_cb=self.std_err_cb,
-                log_stderr=self.log_stderr)
+                limit=2**20, loop=loop, std_out_cb=self.std_out_cb,
+                std_err_cb=self.std_err_cb, log_stderr=self.log_stderr
+            )
         try:
             stdpipe: Optional[int] = None
             if has_input: