dirac-institute / kbmod-wf

MIT License
0 stars 0 forks source link

Fixup logging. #39

Closed DinoBektesevic closed 2 months ago

DinoBektesevic commented 2 months ago

Change Description

Changes to logging structure that collate logs of kbmod-wf and kbmod into a single file. These are what the logs look like:

(lsst-scipipe-8.0.0) n3011:escience/.../workflows:$ cat test_wf/2024-08-30/000/kbmod.log 
[HTEX-Worker-0-78833 MainThread-140518745498112 2024-08-30 10:02:32,960 INFO task.create_manifest] Looking for staged files in /gscratch/escience/dinob/kbmod/workflows/local_wf
[HTEX-Worker-0-78833 MainThread-140518745498112 2024-08-30 10:02:32,964 INFO task.create_manifest] Found 1 files in /gscratch/escience/dinob/kbmod/workflows/local_wf
[HTEX-Worker-0-78833 MainThread-140518745498112 2024-08-30 10:02:32,965 INFO task.create_manifest] Writing manifest file: /gscratch/escience/dinob/kbmod/workflows/local_wf/output/manifest.txt
[HTEX-Worker-0-58206 MainThread-22433947394560 2024-08-30 17:02:48,429 WARNING kbmod.configuration] Setting unknown parameter: cluster_function
[HTEX-Worker-0-58206 MainThread-22433947394560 2024-08-30 17:02:48,451 WARNING kbmod.configuration] Setting unknown parameter: num_cores
[HTEX-Worker-0-58206 MainThread-22433947394560 2024-08-30 17:02:48,451 INFO kbmod.image_collection] Building WorkUnit from ImageCollection
[HTEX-Worker-0-58206 MainThread-22433947394560 2024-08-30 17:03:15,609 INFO kbmod.work_unit] Writing WorkUnit shards with 3 images with main file 20190707_B0b_005.collection.wu in /gscratch/escience/dinob/kbmod/workflows/local_wf/output
[HTEX-Worker-0-40904 MainThread-23135824900608 2024-08-30 17:03:31,765 INFO kbmod.work_unit] Loading WorkUnit from primary FITS file 20190707_B0b_005.collection.wu in /gscratch/escience/dinob/kbmod/workflows/local_wf/output.
[HTEX-Worker-0-40904 MainThread-23135824900608 2024-08-30 17:03:31,825 WARNING kbmod.configuration] Setting unknown parameter: cluster_function
[HTEX-Worker-0-40904 MainThread-23135824900608 2024-08-30 17:03:31,828 WARNING kbmod.configuration] Setting unknown parameter: num_cores
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:21,909 INFO kbmod.work_unit] Loading WorkUnit from primary FITS file 20190707_B0b_005.collection.wu.0.repro in /gscratch/escience/dinob/kbmod/workflows/local_wf/output.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:21,974 WARNING kbmod.configuration] Setting unknown parameter: cluster_function
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:21,976 WARNING kbmod.configuration] Setting unknown parameter: num_cores
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:23,362 WARNING kbmod.configuration] Setting unknown parameter: cluster_function
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:23,362 WARNING kbmod.configuration] Setting unknown parameter: num_cores
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:23,492 INFO kbmod.search.psi_phi_array] Building 6 temporary 2094 by 4175 images, requiring 209818800 bytes.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:24,181 INFO kbmod.search.run_search] Preparing to search 65536 trajectories.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:05:24,183 INFO kbmod.search.run_search] Searching X=[0, 4175] Y=[0, 2094]
Allocating space for 69939600 results.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,269 INFO kbmod.run_search] Retrieving Results (total=69939600)
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,269 INFO kbmod.run_search] Chunk Start = 0 (size=500000)
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,448 INFO kbmod.run_search] Chunk Max Likelihood = -1.0
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,448 INFO kbmod.run_search] Chunk Min. Likelihood = -1.0
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,448 INFO kbmod.run_search] Extracted batch of 0 results for total of 0
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,541 INFO kbmod.filters.stamp_filters] Creating coadds : skipping, nothing to filter.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,543 INFO kbmod.filters.clustering_filters] Clustering : skipping, no results.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,543 INFO kbmod.run_search] Found 0 potential trajectories.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,543 INFO kbmod.results] Saving result trajectories to /gscratch/escience/dinob/kbmod/workflows/local_wf/output/results_20190707_B0b_005.collection.wu.0.repro.search.txt
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,569 INFO kbmod.results] Saving results filter statistics to /gscratch/escience/dinob/kbmod/workflows/local_wf/output/filter_stats_20190707_B0b_005.collection.wu.0.repro.search.csv.
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,571 INFO kbmod.results] Saving results to /gscratch/escience/dinob/kbmod/workflows/local_wf/output/20190707_B0b_005.collection.wu.0.repro.search.ecsv
[HTEX-Worker-0-2679 MainThread-22797229048320 2024-08-30 17:06:23,589 INFO kbmod.results] Saving results to /gscratch/escience/dinob/kbmod/workflows/local_wf/output/20190707_B0b_005.collection.wu.0.repro.search.ecsv

and if an error is raised it's logged for practicality and then, by default, propagated to trigger parsl's error handling. There is an option to silence the propagation (but it shouldn't be/isn't useful because it can break execution chain in a more confusing way).

(lsst-scipipe-8.0.0) n3011:escience/.../workflows:$ cat test_wf/2024-08-30/000/kbmod.log 
[HTEX-Worker-0-75012 MainThread-140362146664960 2024-08-30 10:00:58,877 INFO task.create_manifest] Looking for staged files in /gscratch/escience/dinob/kbmod/workflows/local_wf
[HTEX-Worker-0-75012 MainThread-140362146664960 2024-08-30 10:00:58,880 INFO task.create_manifest] Found 1 files in /gscratch/escience/dinob/kbmod/workflows/local_wf
[HTEX-Worker-0-75012 MainThread-140362146664960 2024-08-30 10:00:58,880 INFO task.create_manifest] Writing manifest file: /gscratch/escience/dinob/kbmod/workflows/local_wf/output/manifest.txt
[HTEX-Worker-0-57556 MainThread-22618070303232 2024-08-30 17:01:14,131 INFO kbmod.image_collection] Reading ('/gscratch/escience/dinob/kbmod/workflows/local_wf/output/20190707_B0b_005.collection',)
[HTEX-Worker-0-57556 MainThread-22618070303232 2024-08-30 17:01:14,160 INFO task.ic_to_wu] Starting ic_to_wu
[HTEX-Worker-0-57556 MainThread-22618070303232 2024-08-30 17:01:14,160 INFO kbmod.image_collection] Reading ('/gscratch/escience/dinob/kbmod/workflows/local_wf/output/20190707_B0b_005.collection',)
[HTEX-Worker-0-57556 MainThread-22618070303232 2024-08-30 17:01:14,163 ERROR task.ic_to_wu] Traceback (most recent call last):
  File "/mmfs1/gscratch/escience/dinob/kbmod/workflows/kbmod-wf/src/kbmod_wf/workflow_tasks/ic_to_wu.py", line 37, in ic_to_wu
    ic_to_wu(
  File "/mmfs1/gscratch/escience/dinob/kbmod/workflows/kbmod-wf/src/kbmod_wf/task_impls/ic_to_wu.py", line 37, in ic_to_wu
    return ic_to_wu_converter.create_work_unit()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mmfs1/gscratch/escience/dinob/kbmod/workflows/kbmod-wf/src/kbmod_wf/task_impls/ic_to_wu.py", line 64, in create_work_unit
    ic = ImageCollection.read(self.ic_filepath, format="ascii.ecsv")
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/mmfs1/gscratch/escience/dinob/kbmod/builds/kbmod_latest/src/kbmod/image_collection.py", line 634, in read
    raise ValueError("This is a test error!")
ValueError: This is a test error!

Closes https://github.com/dirac-institute/kbmod-wf/issues/36 Closes https://github.com/dirac-institute/kbmod-wf/issues/31 Closes https://github.com/dirac-institute/kbmod-wf/issues/26

The timestamps are different because Parsl is lying when it says their defualts are not to log anything. Probably a bug that is addresses in different versions of Parsl, or isn't visible when no log collection happens but is triggered when we keep them.

Solution Description

Pre-registers all loggers in a config, and then edits the shared config's file-handler's file location entry.

Code Quality

Pre-commit is broken and doesn't register the correct Python.

### version information

pre-commit version: 3.8.0
git --version: git version 2.45.1
sys.version:
    3.11.9 | packaged by conda-forge | (main, Apr 19 2024, 18:36:13) [GCC 12.3.0]
sys.executable: /mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/bin/python3.11
os.name: posix
sys.platform: linux

### error information

An unexpected error has occurred: CalledProcessError: command: ('/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/bin/python3.11', '-mvirtualenv', '/mmfs1/home/dinob/.cache/pre-commit/reposua9repc/py_env-python3.12', '-p', 'python3.12')
return code: 1
stdout:
    RuntimeError: failed to find interpreter for Builtin discover of python_spec='python3.12'
stderr: (none)

Traceback (most recent call last):
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/error_handler.py", line 73, in error_handler
    yield
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/main.py", line 389, in main
    return hook_impl(
           ^^^^^^^^^^
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/commands/hook_impl.py", line 271, in hook_impl
    return retv | run(config, store, ns)
                  ^^^^^^^^^^^^^^^^^^^^^^
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/commands/run.py", line 442, in run
    install_hook_envs(to_install, store)
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/repository.py", line 238, in install_hook_envs
    _hook_install(hook)
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/repository.py", line 94, in _hook_install
    lang.install_environment(
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/languages/python.py", line 212, in install_environment
    cmd_output_b(*venv_cmd, cwd='/')
  File "/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/lib/python3.11/site-packages/pre_commit/util.py", line 111, in cmd_output_b
    raise CalledProcessError(returncode, cmd, stdout_b, stderr_b)
pre_commit.util.CalledProcessError: command: ('/mmfs1/gscratch/escience/dinob/kbmod/stacks/w_2024_09/conda/envs/lsst-scipipe-8.0.0/bin/python3.11', '-mvirtualenv', '/mmfs1/home/dinob/.cache/pre-commit/reposua9repc/py_env-python3.12', '-p', 'python3.12')
return code: 1
stdout:
    RuntimeError: failed to find interpreter for Builtin discover of python_spec='python3.12'
stderr: (none)

I ran black. Moved __all__ into modules where I saw them.