Fix logger.exception() calls.
authorScott Gasch <[email protected]>
Sun, 26 Feb 2023 17:02:45 +0000 (09:02 -0800)
committerScott Gasch <[email protected]>
Sun, 26 Feb 2023 17:02:45 +0000 (09:02 -0800)
src/pyutils/argparse_utils.py
src/pyutils/datetimes/dateparse_utils.py
src/pyutils/exec_utils.py
src/pyutils/files/file_utils.py
src/pyutils/files/lockfile.py
src/pyutils/parallelize/executors.py
src/pyutils/parallelize/smart_future.py
src/pyutils/persistent.py
src/pyutils/remote_worker.py
src/pyutils/unittest_utils.py

index 0ce429f1e4957b6c8d469ca555eb3f6f07147e7b..4d23314e55dd6998c3be32ca9b68bed30de1ecdf 100644 (file)
@@ -455,7 +455,7 @@ def valid_duration(txt: str) -> datetime.timedelta:
         secs = parse_duration(txt, raise_on_error=True)
         return datetime.timedelta(seconds=secs)
     except Exception as e:
-        logger.exception(e)
+        logger.exception("Exception while parsing a supposed duration: %s", txt)
         raise argparse.ArgumentTypeError(e) from e
 
 
index fcdaffe131b4c958d9ae2b6573c0d26dd1e4c605..d83f2d972bea3b733f3a4f4af6ee35122a79fa18 100755 (executable)
@@ -1174,8 +1174,8 @@ def main() -> None:
             continue
         try:
             dt = parser.parse(line)
-        except Exception as e:
-            logger.exception(e)
+        except Exception:
+            logger.exception("Could not parse supposed date expression: %s", line)
             print("Unrecognized.")
         else:
             assert dt is not None
index 2158e4560ffa4fa56b3c3011b01467ea8eef048c..6d50194389dbf5bf494173fd61cc17c056471fde 100644 (file)
@@ -46,7 +46,7 @@ def cmd_showing_output(
         p.kill()
         raise subprocess.TimeoutExpired(command, timeout_seconds)
 
-    line_enders = set([b'\n', b'\r'])
+    line_enders = set([b"\n", b"\r"])
     sel = selectors.DefaultSelector()
     with subprocess.Popen(
         command,
@@ -213,11 +213,13 @@ def cmd_in_background(command: str, *, silent: bool = False) -> subprocess.Popen
     def kill_subproc() -> None:
         try:
             if subproc.poll() is None:
-                logger.info('At exit handler: killing %s (%s)', subproc, command)
+                logger.info("At exit handler: killing %s (%s)", subproc, command)
                 subproc.terminate()
                 subproc.wait(timeout=10.0)
-        except BaseException as be:
-            logger.exception(be)
+        except BaseException:
+            logger.exception(
+                "Failed to terminate background process %s; giving up.", subproc
+            )
 
     atexit.register(kill_subproc)
     return subproc
@@ -231,7 +233,7 @@ def cmd_list(command: List[str]) -> str:
     return ret.decode("utf-8")
 
 
-if __name__ == '__main__':
+if __name__ == "__main__":
     import doctest
 
     doctest.testmod()
index af44dbc7b226f494bef3a8b421ef474e1644adb7..513131206c243a98fca15753fe63dee1dd65cce9 100644 (file)
@@ -533,8 +533,8 @@ def get_file_raw_timestamps(filename: str) -> Optional[os.stat_result]:
     """
     try:
         return os.stat(filename)
-    except Exception as e:
-        logger.exception(e)
+    except Exception:
+        logger.exception("Failed to stat path %s; returning None", filename)
         return None
 
 
index 158a636653eefd7b66ee31c698a7dc909dc0e770..47673098f536e1ab3ff779bd3c74d9b753771ab8 100644 (file)
@@ -220,8 +220,8 @@ class LockFile(contextlib.AbstractContextManager):
         if not self.zk_client:
             try:
                 os.unlink(self.lockfile)
-            except Exception as e:
-                logger.exception(e)
+            except Exception:
+                logger.exception("Failed to unlink path %s; giving up.", self.lockfile)
         else:
             if self.zk_lease:
                 self.zk_lease.release()
@@ -287,8 +287,10 @@ class LockFile(contextlib.AbstractContextManager):
                 with open(self.lockfile, "r") as rf:
                     lines = rf.readlines()
                     return lines[0]
-            except Exception as e:
-                logger.exception(e)
+            except Exception:
+                logger.exception(
+                    "Failed to read from path %s; giving up.", self.lockfile
+                )
         return None
 
     def _detect_stale_lockfile(self) -> None:
index e8f8d40dd30b1eb1ca52c95d0ab282e43e17ea79..0fb47dda6e946fe1171a2c8529b15d8507546c52 100644 (file)
@@ -1094,7 +1094,7 @@ class RemoteExecutor(BaseExecutor):
         if self._check_if_cancelled(bundle):
             try:
                 return self._process_work_result(bundle)
-            except Exception as e:
+            except Exception:
                 logger.warning(
                     '%s: bundle says it\'s cancelled upfront but no results?!', bundle
                 )
@@ -1107,10 +1107,10 @@ class RemoteExecutor(BaseExecutor):
                     # it is done but we can't find the results it
                     # should have copied over.  Reschedule the whole
                     # thing.
-                    logger.exception(e)
-                    logger.error(
+                    logger.exception(
                         '%s: We are the original owner thread and yet there are '
-                        'no results for this bundle.  This is unexpected and bad.',
+                        'no results for this bundle.  This is unexpected and bad. '
+                        'Attempting an emergency retry...',
                         bundle,
                     )
                     return self._emergency_retry_nasty_bundle(bundle)
@@ -1134,14 +1134,13 @@ class RemoteExecutor(BaseExecutor):
                 logger.debug(
                     "%s: Copying to %s took %.1fs.", bundle, worker, xfer_latency
                 )
-            except Exception as e:
+            except Exception:
                 self._release_worker(bundle)
                 if is_original:
                     # Weird.  We tried to copy the code to the worker
                     # and it failed...  And we're the original bundle.
                     # We have to retry.
-                    logger.exception(e)
-                    logger.error(
+                    logger.exception(
                         "%s: Failed to send instructions to the worker machine?! "
                         "This is not expected; we\'re the original bundle so this shouldn\'t "
                         "be a race condition.  Attempting an emergency retry...",
@@ -1245,9 +1244,8 @@ class RemoteExecutor(BaseExecutor):
         # unpickle the results we got from the remove machine.  If we
         # still have an active ssh subprocess, keep waiting on it.
         # Otherwise, time for an emergency reschedule.
-        except Exception as e:
-            logger.exception(e)
-            logger.error('%s: Something unexpected just happened...', bundle)
+        except Exception:
+            logger.exception('%s: Something unexpected just happened...', bundle)
             if p is not None:
                 logger.warning(
                     "%s: Failed to wrap up \"done\" bundle, re-waiting on active ssh.",
@@ -1323,8 +1321,7 @@ class RemoteExecutor(BaseExecutor):
                     serialized = rb.read()
                 result = cloudpickle.loads(serialized)
             except Exception as e:
-                logger.exception(e)
-                logger.error('Failed to load %s... this is bad news.', result_file)
+                logger.exception('Failed to load %s... this is bad news.', result_file)
                 self._release_worker(bundle)
 
                 # Re-raise the exception; the code in _wait_for_process may
index b722cfecb5d6e4b525bf5770ae1014634fd5d787..9753e6f50a07e6bcdb297378000dc6ade506d0cf 100644 (file)
@@ -79,11 +79,11 @@ def wait_any(
                 if log_exceptions and not f.cancelled():
                     exception = f.exception()
                     if exception is not None:
-                        logger.warning(
+                        logger.exception(
                             "Future 0x%x raised an unhandled exception and exited.",
                             id(f),
+                            exc_info=exception,
                         )
-                        logger.exception(exception)
                         raise exception
                 yield smart_future_by_real_future[f]
         except concurrent.futures.TimeoutError:
@@ -125,11 +125,11 @@ def wait_all(
             if not f.cancelled():
                 exception = f.exception()
                 if exception is not None:
-                    logger.warning(
+                    logger.exception(
                         "Future 0x%x raised an unhandled exception and exited.",
                         id(f),
+                        exc_info=exception,
                     )
-                    logger.exception(exception)
                     raise exception
     assert len(done) == len(real_futures)
     assert len(not_done) == 0
index b55577573b85372679cc810dcfb0996b9b4907a6..cc165aeadafc12c4982baacf80ba7a6980eae027 100644 (file)
@@ -265,7 +265,9 @@ class JsonFileBasedPersistent(FileBasedPersistent):
                 return cls(json_dict)
 
             except Exception as e:
-                logger.exception(e)
+                logger.exception(
+                    "Failed to load path %s; raising an exception", filename
+                )
                 raise Exception(f"Failed to load {filename}.") from e
         return None
 
index af0968ca93f3b06ba362c3110cd12640aab0da0a..a9b6d6c7647f178575f67b6df9353e7ea3b647be 100755 (executable)
@@ -40,30 +40,30 @@ cfg = config.add_commandline_args(
     "Helper to run pickled code remotely and return results",
 )
 cfg.add_argument(
-    '--code_file',
+    "--code_file",
     type=str,
     required=True,
-    metavar='FILENAME',
-    help='The location of the bundle of code to execute.',
+    metavar="FILENAME",
+    help="The location of the bundle of code to execute.",
 )
 cfg.add_argument(
-    '--result_file',
+    "--result_file",
     type=str,
     required=True,
-    metavar='FILENAME',
-    help='The location where we should write the computation results.',
+    metavar="FILENAME",
+    help="The location where we should write the computation results.",
 )
 cfg.add_argument(
-    '--watch_for_cancel',
+    "--watch_for_cancel",
     action=argparse_utils.ActionNoYes,
     default=True,
-    help='Should we watch for the cancellation of our parent ssh process?',
+    help="Should we watch for the cancellation of our parent ssh process?",
 )
 
 
 @background_thread
 def _watch_for_cancel(terminate_event: threading.Event) -> None:
-    logger.debug('Starting up background thread...')
+    logger.debug("Starting up background thread...")
     p = psutil.Process(os.getpid())
     while True:
         saw_sshd = False
@@ -71,15 +71,15 @@ def _watch_for_cancel(terminate_event: threading.Event) -> None:
         for ancestor in ancestors:
             name = ancestor.name()
             pid = ancestor.pid
-            logger.debug('Ancestor process %s (pid=%d)', name, pid)
-            if 'ssh' in name.lower():
+            logger.debug("Ancestor process %s (pid=%d)", name, pid)
+            if "ssh" in name.lower():
                 saw_sshd = True
                 break
         if not saw_sshd:
             logger.error(
-                'Did not see sshd in our ancestors list?!  Committing suicide.'
+                "Did not see sshd in our ancestors list?!  Committing suicide."
             )
-            os.system('pstree')
+            os.system("pstree")
             os.kill(os.getpid(), signal.SIGTERM)
             time.sleep(5.0)
             os.kill(os.getpid(), signal.SIGKILL)
@@ -105,56 +105,52 @@ def _cleanup_and_exit(
 def main() -> None:
     """Remote worker entry point."""
 
-    in_file = config.config['code_file']
+    in_file = config.config["code_file"]
     assert in_file and type(in_file) == str
-    out_file = config.config['result_file']
+    out_file = config.config["result_file"]
     assert out_file and type(out_file) == str
 
     thread = None
     stop_event = None
-    if config.config['watch_for_cancel']:
+    if config.config["watch_for_cancel"]:
         thread, stop_event = _watch_for_cancel()
 
-    logger.debug('Reading %s.', in_file)
+    logger.debug("Reading %s.", in_file)
     try:
-        with open(in_file, 'rb') as rb:
+        with open(in_file, "rb") as rb:
             serialized = rb.read()
-    except Exception as e:
-        logger.exception(e)
-        logger.critical('Problem reading %s. Aborting.', in_file)
+    except Exception:
+        logger.exception("Problem reading %s; aborting.", in_file)
         _cleanup_and_exit(thread, stop_event, 1)
 
-    logger.debug('Deserializing %s', in_file)
+    logger.debug("Deserializing %s", in_file)
     try:
         fun, args, kwargs = cloudpickle.loads(serialized)
-    except Exception as e:
-        logger.exception(e)
-        logger.critical('Problem deserializing %s. Aborting.', in_file)
+    except Exception:
+        logger.exception("Problem deserializing %s. Aborting.", in_file)
         _cleanup_and_exit(thread, stop_event, 2)
 
-    logger.debug('Invoking user-defined code...')
+    logger.debug("Invoking user-defined code...")
     with Timer() as t:
         ret = fun(*args, **kwargs)
-    logger.debug('User code took %.1fs', t())
+    logger.debug("User code took %.1fs", t())
 
-    logger.debug('Serializing results')
+    logger.debug("Serializing results")
     try:
         serialized = cloudpickle.dumps(ret)
-    except Exception as e:
-        logger.exception(e)
-        logger.critical('Could not serialize result (%s). Aborting.', type(ret))
+    except Exception:
+        logger.exception("Could not serialize result (%s). Aborting.", type(ret))
         _cleanup_and_exit(thread, stop_event, 3)
 
-    logger.debug('Writing %s', out_file)
+    logger.debug("Writing %s", out_file)
     try:
-        with open(out_file, 'wb') as wb:
+        with open(out_file, "wb") as wb:
             wb.write(serialized)
-    except Exception as e:
-        logger.exception(e)
-        logger.critical('Error writing %s. Aborting.', out_file)
+    except Exception:
+        logger.exception("Error writing %s. Aborting.", out_file)
         _cleanup_and_exit(thread, stop_event, 4)
     _cleanup_and_exit(thread, stop_event, 0)
 
 
-if __name__ == '__main__':
+if __name__ == "__main__":
     main()
index 52f4f5319ac68e569dba7f12bb3c72506811839f..abbc09c201c2f44ac57410aaf5991f9f36d82fa0 100644 (file)
@@ -31,46 +31,46 @@ from pyutils import bootstrap, config, function_utils
 
 logger = logging.getLogger(__name__)
 cfg = config.add_commandline_args(
-    f'Logging ({__file__})', 'Args related to function decorators'
+    f"Logging ({__file__})", "Args related to function decorators"
 )
 cfg.add_argument(
-    '--unittests_ignore_perf',
-    action='store_true',
+    "--unittests_ignore_perf",
+    action="store_true",
     default=False,
-    help='Ignore unittest perf regression in @check_method_for_perf_regressions',
+    help="Ignore unittest perf regression in @check_method_for_perf_regressions",
 )
 cfg.add_argument(
-    '--unittests_num_perf_samples',
+    "--unittests_num_perf_samples",
     type=int,
     default=50,
-    help='The count of perf timing samples we need to see before blocking slow runs on perf grounds',
+    help="The count of perf timing samples we need to see before blocking slow runs on perf grounds",
 )
 cfg.add_argument(
-    '--unittests_drop_perf_traces',
+    "--unittests_drop_perf_traces",
     type=str,
     nargs=1,
     default=None,
-    help='The identifier (i.e. file!test_fixture) for which we should drop all perf data',
+    help="The identifier (i.e. file!test_fixture) for which we should drop all perf data",
 )
 cfg.add_argument(
-    '--unittests_persistance_strategy',
-    choices=['FILE', 'DATABASE'],
-    default='FILE',
-    help='Should we persist perf data in a file or db?',
+    "--unittests_persistance_strategy",
+    choices=["FILE", "DATABASE"],
+    default="FILE",
+    help="Should we persist perf data in a file or db?",
 )
 cfg.add_argument(
-    '--unittests_perfdb_filename',
+    "--unittests_perfdb_filename",
     type=str,
-    metavar='FILENAME',
+    metavar="FILENAME",
     default=f'{os.environ["HOME"]}/.python_unittest_performance_db',
-    help='File in which to store perf data (iff --unittests_persistance_strategy is FILE)',
+    help="File in which to store perf data (iff --unittests_persistance_strategy is FILE)",
 )
 cfg.add_argument(
-    '--unittests_perfdb_spec',
+    "--unittests_perfdb_spec",
     type=str,
-    metavar='DBSPEC',
-    default='mariadb+pymysql://python_unittest:<PASSWORD>@db.house:3306/python_unittest_performance',
-    help='Db connection spec for perf data (iff --unittest_persistance_strategy is DATABASE)',
+    metavar="DBSPEC",
+    default="mariadb+pymysql://python_unittest:<PASSWORD>@db.house:3306/python_unittest_performance",
+    help="Db connection spec for perf data (iff --unittest_persistance_strategy is DATABASE)",
 )
 
 unittest.main = bootstrap.initialize(unittest.main)
@@ -123,7 +123,7 @@ class FileBasedPerfRegressionDataPersister(PerfRegressionDataPersister):
         self.traces_to_delete: List[str] = []
 
     def load_performance_data(self, method_id: str) -> Dict[str, List[float]]:
-        with open(self.filename, 'rb') as f:
+        with open(self.filename, "rb") as f:
             return pickle.load(f)
 
     def save_performance_data(self, method_id: str, data: Dict[str, List[float]]):
@@ -131,7 +131,7 @@ class FileBasedPerfRegressionDataPersister(PerfRegressionDataPersister):
             if trace in data:
                 data[trace] = []
 
-        with open(self.filename, 'wb') as f:
+        with open(self.filename, "wb") as f:
             pickle.dump(data, f, pickle.HIGHEST_PROTOCOL)
 
     def delete_performance_data(self, method_id: str):
@@ -191,35 +191,34 @@ def check_method_for_perf_regressions(func: Callable) -> Callable:
 
     @functools.wraps(func)
     def wrapper_perf_monitor(*args, **kwargs):
-        if config.config['unittests_ignore_perf']:
+        if config.config["unittests_ignore_perf"]:
             return func(*args, **kwargs)
 
-        if config.config['unittests_persistance_strategy'] == 'FILE':
-            filename = config.config['unittests_perfdb_filename']
+        if config.config["unittests_persistance_strategy"] == "FILE":
+            filename = config.config["unittests_perfdb_filename"]
             helper = FileBasedPerfRegressionDataPersister(filename)
-        elif config.config['unittests_persistance_strategy'] == 'DATABASE':
+        elif config.config["unittests_persistance_strategy"] == "DATABASE":
             raise NotImplementedError(
-                'Persisting to a database is not implemented in this version'
+                "Persisting to a database is not implemented in this version"
             )
         else:
-            raise Exception('Unknown/unexpected --unittests_persistance_strategy value')
+            raise Exception("Unknown/unexpected --unittests_persistance_strategy value")
 
         func_id = function_utils.function_identifier(func)
         func_name = func.__name__
-        logger.debug('Watching %s\'s performance...', func_name)
+        logger.debug("Watching %s's performance...", func_name)
         logger.debug('Canonical function identifier = "%s"', func_id)
 
         try:
             perfdb = helper.load_performance_data(func_id)
-        except Exception as e:
-            logger.exception(e)
-            msg = 'Unable to load perfdb; skipping it...'
-            logger.warning(msg)
+        except Exception:
+            msg = "Unable to load perfdb; skipping it..."
+            logger.exception(msg)
             warnings.warn(msg)
             perfdb = {}
 
         # cmdline arg to forget perf traces for function
-        drop_id = config.config['unittests_drop_perf_traces']
+        drop_id = config.config["unittests_drop_perf_traces"]
         if drop_id is not None:
             helper.delete_performance_data(drop_id)
 
@@ -231,28 +230,28 @@ def check_method_for_perf_regressions(func: Callable) -> Callable:
 
         # See if it was unexpectedly slow.
         hist = perfdb.get(func_id, [])
-        if len(hist) < config.config['unittests_num_perf_samples']:
+        if len(hist) < config.config["unittests_num_perf_samples"]:
             hist.append(run_time)
-            logger.debug('Still establishing a perf baseline for %s', func_name)
+            logger.debug("Still establishing a perf baseline for %s", func_name)
         else:
             stdev = statistics.stdev(hist)
-            logger.debug('For %s, performance stdev=%.2f', func_name, stdev)
+            logger.debug("For %s, performance stdev=%.2f", func_name, stdev)
             slowest = hist[-1]
-            logger.debug('For %s, slowest perf on record is %.2fs', func_name, slowest)
+            logger.debug("For %s, slowest perf on record is %.2fs", func_name, slowest)
             limit = slowest + stdev * 4
-            logger.debug('For %s, max acceptable runtime is %.2fs', func_name, limit)
+            logger.debug("For %s, max acceptable runtime is %.2fs", func_name, limit)
             logger.debug(
-                'For %s, actual observed runtime was %.2fs', func_name, run_time
+                "For %s, actual observed runtime was %.2fs", func_name, run_time
             )
             if run_time > limit:
-                msg = f'''{func_id} performance has regressed unacceptably.
+                msg = f"""{func_id} performance has regressed unacceptably.
 {slowest:f}s is the slowest runtime on record in {len(hist)} perf samples.
 It just ran in {run_time:f}s which is 4+ stdevs slower than the slowest.
 Here is the current, full db perf timing distribution:
 
-'''
+"""
                 for x in hist:
-                    msg += f'{x:f}\n'
+                    msg += f"{x:f}\n"
                 logger.error(msg)
                 slf = args[0]  # Peek at the wrapped function's self ref.
                 slf.fail(msg)  # ...to fail the testcase.
@@ -261,7 +260,7 @@ Here is the current, full db perf timing distribution:
 
         # Don't spam the database with samples; just pick a random
         # sample from what we have and store that back.
-        n = min(config.config['unittests_num_perf_samples'], len(hist))
+        n = min(config.config["unittests_num_perf_samples"], len(hist))
         hist = random.sample(hist, n)
         hist.sort()
         perfdb[func_id] = hist
@@ -271,7 +270,7 @@ Here is the current, full db perf timing distribution:
     return wrapper_perf_monitor
 
 
-def check_all_methods_for_perf_regressions(prefix='test_'):
+def check_all_methods_for_perf_regressions(prefix="test_"):
     """This decorator is meant to apply to classes that subclass from
     :class:`unittest.TestCase` and, when applied, has the affect of
     decorating each method that matches the `prefix` given with the
@@ -305,7 +304,7 @@ def check_all_methods_for_perf_regressions(prefix='test_'):
             for name, m in inspect.getmembers(cls, inspect.isfunction):
                 if name.startswith(prefix):
                     setattr(cls, name, check_method_for_perf_regressions(m))
-                    logger.debug('Wrapping %s:%s.', cls.__name__, name)
+                    logger.debug("Wrapping %s:%s.", cls.__name__, name)
         return cls
 
     return decorate_the_testcase
@@ -324,7 +323,7 @@ class RecordStdout(contextlib.AbstractContextManager):
 
     def __init__(self) -> None:
         super().__init__()
-        self.destination = tempfile.SpooledTemporaryFile(mode='r+')
+        self.destination = tempfile.SpooledTemporaryFile(mode="r+")
         self.recorder: Optional[contextlib.redirect_stdout] = None
 
     def __enter__(self) -> Callable[[], tempfile.SpooledTemporaryFile]:
@@ -354,7 +353,7 @@ class RecordStderr(contextlib.AbstractContextManager):
 
     def __init__(self) -> None:
         super().__init__()
-        self.destination = tempfile.SpooledTemporaryFile(mode='r+')
+        self.destination = tempfile.SpooledTemporaryFile(mode="r+")
         self.recorder: Optional[contextlib.redirect_stdout[Any]] = None
 
     def __enter__(self) -> Callable[[], tempfile.SpooledTemporaryFile]:
@@ -388,7 +387,7 @@ class RecordMultipleStreams(contextlib.AbstractContextManager):
     def __init__(self, *files) -> None:
         super().__init__()
         self.files = [*files]
-        self.destination = tempfile.SpooledTemporaryFile(mode='r+')
+        self.destination = tempfile.SpooledTemporaryFile(mode="r+")
         self.saved_writes: List[Callable[..., Any]] = []
 
     def __enter__(self) -> Callable[[], tempfile.SpooledTemporaryFile]:
@@ -404,7 +403,7 @@ class RecordMultipleStreams(contextlib.AbstractContextManager):
         return False
 
 
-if __name__ == '__main__':
+if __name__ == "__main__":
     import doctest
 
     doctest.testmod()