Repository navigation
Simplify ingestion logging and run metrics - #365
tomvothecoder merged 14 commits into
Conversation
Chrysalis dry-run checkI tested the logging changes on Chrysalis against the development API. The test completed successfully and did not upload data or update ingestion state. The output is now easier to review:
Reference: Ingestion logging definitions. Command usedRun from the branch checkout’s (
set -e
set -a
source /lcrc/group/e3sm2/simboard/operations/env.dev.sh
source app/scripts/ingestion/sites/configs/chrysalis.config
set +a
export SCAN_MODE=staging
export DRY_RUN=true
export DRY_RUN_USE_REMOTE_STATE=true
.venv/bin/python -m app.scripts.ingestion.hpc_upload_archive_ingestor
)Full logExpand dry-run output
2026-09-30 23:51:33,538Z INFO CONFIG event=invocation_started Run ID: c160c6e1-4290-428a-a45b-eb4576f5a185
2026-09-30 23:51:33,588Z INFO CONFIG Machine: chrysalis
2026-09-30 23:51:33,588Z INFO CONFIG Mode: dry run
2026-09-30 23:51:33,588Z INFO CONFIG Scan: staging
2026-09-30 23:51:33,588Z INFO CONFIG API: https://simboard-dev-api.e3sm.org
2026-09-30 23:51:33,588Z INFO CONFIG Remote state: enabled (read-only)
2026-09-30 23:51:33,588Z INFO CONFIG API token: configured
2026-09-30 23:51:33,588Z INFO CONFIG Archive root: /lcrc/group/e3sm/PERF_Chrysalis/performance_archive
2026-09-30 23:51:33,588Z INFO CONFIG Archive range: not applicable (staging)
2026-09-30 23:51:33,588Z INFO CONFIG Maximum cases: unlimited
2026-09-30 23:51:33,588Z INFO CONFIG Maximum attempts: 3
2026-09-30 23:51:33,588Z INFO CONFIG Request timeout: 60 seconds
2026-09-30 23:51:43,110Z INFO CASE_SUMMARY event=case_discovered case=ac.cbegeman/20260918.v3.SORRME3r3.CRYO1950.bluepulse-control.chrysalis executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,110Z INFO CASE_SUMMARY event=case_discovered case=ac.jeffery/09292026.rebaseOmegaDev.GMPAS.omega-coupling.lcrc executions.total=1 executions.selected=0 executions.skipped=1 executions.incomplete=0 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,110Z INFO CASE_SUMMARY event=case_discovered case=ac.jeffery/09302026.allOn.GMPAS.omega-coupling.lcrc executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,110Z INFO CASE_SUMMARY event=case_discovered case=ac.jtang/I1850GSWCNPRDCTCBCTOPPHSWFMCROP.r025 executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,110Z INFO CASE_SUMMARY event=case_discovered case=ac.jwolfe/20210201.testRRM.chrysalis executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,111Z INFO CASE_SUMMARY event=case_discovered case=ac.jwolfe/20210302.test-V1ocnwbug.chrysalis executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,111Z INFO CASE_SUMMARY event=case_discovered case=ac.jwolfe/20260601.LRW.WCYCL2010WW3.bluepulse.chrysalis executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,111Z INFO CASE_SUMMARY event=case_discovered case=ac.jwolfe/v3.HR.control-1950 executions.total=3 executions.selected=0 executions.skipped=1 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,111Z INFO CASE_SUMMARY event=case_discovered case=ac.kpeterson/09302026.rebaseOmegaDev.GMPAS.omega-coupling.var_salinity.lcrc executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,111Z INFO CASE_SUMMARY event=case_discovered case=ac.odiazib/F2010-EAMxx-MAM4xx_ne30pg2_ne30pg2_L72_mam4xx_pr_8799 executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,111Z INFO CASE_SUMMARY event=case_discovered case=ac.odiazib/F2010-EAMxx-MAM4xx_ne30pg2_ne30pg2_L72_mam4xx_pr_master executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,112Z INFO CASE_SUMMARY event=case_discovered case=ac.sfeng1/A_WCYCL20TRS_CMIP6.DOCN executions.total=3 executions.selected=0 executions.skipped=0 executions.incomplete=3 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,113Z INFO CASE_SUMMARY event=case_discovered case=ac.sfeng1/CBGCv1.LR.BGC-LNDATM.20TR executions.total=54 executions.selected=0 executions.skipped=0 executions.incomplete=54 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,113Z INFO CASE_SUMMARY event=case_discovered case=ac.sfeng1/DATMCLM executions.total=4 executions.selected=0 executions.skipped=0 executions.incomplete=4 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,114Z INFO CASE_SUMMARY event=case_discovered case=ac.sfeng1/F20TRC5-CMIP6 executions.total=15 executions.selected=0 executions.skipped=0 executions.incomplete=15 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,114Z INFO CASE_SUMMARY event=case_discovered case=ac.sfeng1/F20TRC5-CMIP6.CO2 executions.total=9 executions.selected=0 executions.skipped=0 executions.incomplete=9 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,114Z INFO CASE_SUMMARY event=case_discovered case=ac.vanroekel/new_kpp_omega_smoke_test executions.total=1 executions.selected=0 executions.skipped=1 executions.incomplete=0 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,115Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_-0.01 executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,115Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_-0.1 executions.total=3 executions.selected=0 executions.skipped=0 executions.incomplete=3 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,115Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_-0.3 executions.total=3 executions.selected=0 executions.skipped=0 executions.incomplete=3 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,115Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_0 executions.total=3 executions.selected=0 executions.skipped=0 executions.incomplete=3 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,115Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_0.01 executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,115Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_0.1 executions.total=4 executions.selected=0 executions.skipped=0 executions.incomplete=4 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,116Z INFO CASE_SUMMARY event=case_discovered case=ac.whannah/E3SM.2026-ZM-DEV-01.F2010xx-ZM-CICE.ne30pg2.NN_4.mscp_new.mcsp_mom_coeff_0.3 executions.total=3 executions.selected=0 executions.skipped=0 executions.incomplete=3 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,116Z INFO CASE_SUMMARY event=case_discovered case=ac.wlin/20210420.F2010-UMrad1_2.ne30_oECv3.chrysalis executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,116Z INFO CASE_SUMMARY event=case_discovered case=ac.wlin/20210421.F2010-UMrad2.ne30_oECv3.chrysalis executions.total=10 executions.selected=0 executions.skipped=0 executions.incomplete=10 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,116Z INFO CASE_SUMMARY event=case_discovered case=ac.wlin/20210516.F2010-UMich10.ne30_oECv3.chrysalis executions.total=5 executions.selected=0 executions.skipped=0 executions.incomplete=5 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,117Z INFO CASE_SUMMARY event=case_discovered case=ac.wlin/20210516.FC5AV1C-04P2.UMich10.ne30_oECv3.chrysalis executions.total=3 executions.selected=0 executions.skipped=0 executions.incomplete=3 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,117Z INFO CASE_SUMMARY event=case_discovered case=ac.xie7/v3_ne4pg2_oQU480 executions.total=1 executions.selected=0 executions.skipped=0 executions.incomplete=1 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,117Z INFO CASE_SUMMARY event=case_discovered case=ac.ztan/lakebgc_sens_RU-Tub_I20TRGSWCNPRDCTCBC executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,117Z INFO CASE_SUMMARY event=case_discovered case=ac.ztan/lakebgc_sens_RU-Tub_ICB20TRCNPRDCTCBC executions.total=2 executions.selected=0 executions.skipped=0 executions.incomplete=2 executions.invalid=0 executions.unreadable=0 executions.deferred=0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Cases found: 31
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Cases eligible: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Selected: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Deferred: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Selected case outcomes: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Succeeded: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Failed: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Not attempted: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Executions found: 146
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Selected: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Skipped: 3
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Incomplete: 143
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Invalid: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Unreadable: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY Deferred: 0
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY status=success exit_code=0 duration_seconds=9.583
2026-09-30 23:51:43,121Z INFO RUN_SUMMARY event=run_metrics payload={"schema_version":1,"run_id":"c160c6e1-4290-428a-a45b-eb4576f5a185","runner":"app.scripts.ingestion.hpc_upload_archive_ingestor","machine":"chrysalis","environment":null,"scan_mode":"staging","dry_run":true,"started_at":"2026-09-30T23:51:33.537922+00:00","finished_at":"2026-09-30T23:51:43.121388+00:00","duration_seconds":9.583,"status":"success","exit_code":0,"discovery_complete":true,"submission_complete":false,"cases":{"found":31,"eligible":0,"selected":0,"deferred":0,"succeeded":0,"failed":0,"not_attempted":0},"executions":{"total":146,"selected":0,"skipped":3,"incomplete":143,"invalid":0,"unreadable":0,"deferred":0}}How to read the output
ResultsThe scan found 31 cases with 146 executions:
The scan finished successfully in approximately 8 seconds. This confirms the updated logging works during a staging dry run on Chrysalis. It does not test uploads, since no cases were eligible. If we expected eligible cases, the incomplete results should be investigated separately using DEBUG logging. |
|
@TonyB9000 This PR is ready for review. Please read the PR description and the dry-run I performed above. There is an example of the log file for a dry-run on the staging directory in the second comment I cited. Next step is to test this on a |
|
@tomvothecoder "Added canonical document on latest, simplified ingestion logging terms". A great document - had to read it through a few times. Still could use a Venn diagram or a spreadsheet-style breakdown, to be clear on partitioning results. The description of changes is very good - I agree with everything I've read. I'm not quite sure where to find the log_file of the dry_run mentioned above ("example of the log file for a dry-run on the staging directory in the second comment I cited"). Did you mean the "FULL LOG: Expand dry_run output"? I think the INFO (CONFIG, CASE_SUMMARY, RUN_SUMMARY) section identification is great! For the CASE_SUMMARIES, I note that beyond case-name, all tallies are "executions.", Unless there are expected to be non-"executions" tallies, once could reduce this: In a future summary report, a table format could even reduce these to column headers and place just the counts into cells. (I am rambling a bit, sorry). To perform a "DRY_RUN=false" test, I ordinarily just comment out "DRY_RUN=false" from the crontab, and allow cron to invoke the process. How else should I conduct testing? (and should I pull down specific fork/branch codes to the repository? What about the currently running ingestion jobs?) |
Yes, click the drop-down arrow to view the embedded log.
Good idea! I'll look into this.
Also a good.
First, checkout this branch from my fork. Then follow the docs which show how to invoke a local ingestion run without cron: https://simboard.readthedocs.io/en/latest/operations/setup-ingestion-operations/#e3sm-v3-metadata-backfill-operation. Skip the first step of initializing the operations directory and update |
|
@tomvothecoder So I first obtain the code with: THEN I issue (output so far): After pausing here for a few minutes, it finally outputs hundreds to "CASE_SUMMARY" lines, But then it continues with a series of new "INFO CONFIG" linesL and finally end on some CONFIG errors, and then the RUN_SUMMARY lines: I don't know what to make of this. (I think I inadvertently skipped the other step 1: "make v3-ingest-dry-run") (Officially, I am on vacation. But I'll poke my head in occasionally to see if I can help.) (BTW, did the permissions update help?) |
@TonyB9000 Sorry Tony, I pointed you to the wrong docs. That section is for v3 specific data ingestion, not the general ingestion command. At least it looks like it's printing out the correct information for v3 data! The correct docs are here: https://github.com/tomvothecoder/simboard/blob/devops/321-refactor-log-output/docs/operations/setup-ingestion-operations.md#chrysalis The command you should run is: make ingest-dry-run machine=chrysalis SIMBOARD_ROOT=/lcrc/group/e3sm2/simboard env=dev scan_mode=staging
No worries. Enjoy your time off and I'll catch you next week.
I'll check it out next week. Thanks! |
|
@tomvothecoder Early Friday evening. Once I did "git pull" I was able to run "make ingest-dry-run": It ran for about a minute, I think. But no output appeared at the terminal. Enjoy the weekend! |
The issue is that these Make commands redirects all output to My latest commit also prints to the console. Can you pull and re-run? It works for me now. make ingest-dry-run machine=chrysalis SIMBOARD_ROOT=/lcrc/group/e3sm2/simboard env=dev scan_mode=staging |
|
@TonyB9000 I saw your email this morning.
These two logs have dry_run=True, which follows what I said in my previous comment above. Should we consider just not saving the logs for dry runs? I think we usually want to see the immediate results in the console and move on. |
|
@tomvothecoder You wrote: "These two logs have dry_run=True" I beg to differ, which is why I was curious: As far as logging goes, I still prefer to have a written record (I suppose I can always ">> dry_run_log 2>&1" to capture the console output anyway.) BTW, is it safe to pull down changes during a run? Should I de-cron, wait for all exits, then do a pull and re-establish cron? PPS: It used to be easy to edit the cron - now I need to be far more careful and search for the proper lines. It took me some time to find "# dry_run=false" among all of the commentary. |
|
@tomvothecoder I tried "git pull" and got this Am I in the Twilight Zone? |
|
I'll pull from this branch, and reload. |
|
Latest logs. The last is post-pull: Here is the full content of that latest log: |
|
The full run looks like it works in your comment above. The RUN_SUMMARY at the end is clear now: it says 22 cases found and none are eligible because 124 of the executions are incomplete. Remaining Work
Explanation: In
This www.github.com/E3SM-Project/simboard/pull/365/commits/606dfdf1e407a38f83c83034626a7ff5eedd75cc added added the PID suffix to distinguish invocations starting in the same second. The earlier logs used the old naming format; the linked comment explicitly identifies the suffixed log as post-pull. This is expected behavior, not malformed timestamp data. Updated the operations documentation to explain it.
|
|
@tomvothecoder OK, great. Let me know what tests I can perform - as needed. |
61e0078 to
6eea91a
Compare
ba322c7 to
fd84413
Compare
There was a problem hiding this comment.
Copilot review overview
🟡 Changes recommended
Address the three moderate ingestion configuration and metrics issues before approval.
Review effort: Lite
Findings: 1
Open (1)
What changed in this PR
Refactors ingestion logging, run metrics, machine dispatch, documentation, and regression tests.
Changes:
- Adds configurable logging levels, shared event categories, run IDs, and JSON metrics.
- Unifies dry-run and live-ingestion reporting across runners and launchers.
- Updates operational documentation and ingestion tests.
| File | Review summary |
|---|---|
Makefile |
Machine targets added; exports must forward ingestion options. |
docs/operations/setup-ingestion-operations.md |
Documents logging and manual ingestion. |
docs/operations/nersc-spin-runbook.md |
Adds NERSC guidance; remove standalone 1 artifact. |
docs/github-issues/321-refactor-log-output/plan.md |
Documents refactor scope; reconcile launcher-change wording. |
docs/architecture/metadata-ingestion.md |
Links to logging documentation. |
docs/architecture/ingestion-logging.md |
Defines logging contract; document or suppress v3_case_match. |
backend/tests/features/ingestion/test_site_collection_launcher.py |
Covers launcher behavior. |
backend/tests/features/ingestion/test_nersc_archive_ingestor.py |
Updates NERSC logging assertions. |
backend/tests/features/ingestion/test_machine_ingestion.py |
Tests machine dispatch. |
backend/tests/features/ingestion/test_lcrc_v3_archive_ingestor.py |
Updates v3 fixtures. |
backend/tests/features/ingestion/test_ingestion_logging.py |
Tests logging and metrics. |
backend/tests/features/ingestion/test_hpc_upload_archive_ingestor.py |
Updates HPC logging assertions. |
backend/tests/features/ingestion/test_archive_workflow.py |
Updates workflow tests. |
backend/tests/features/ingestion/test_archive_discovery.py |
Updates discovery tests. |
backend/tests/features/ingestion/test_archive_client.py |
Updates timing tests. |
backend/app/scripts/ingestion/v3_data/lcrc_v3_archive_ingestor.py |
Applies shared v3 logging. |
backend/app/scripts/ingestion/sites/templates/crontab.example |
Documents log-level configuration. |
backend/app/scripts/ingestion/sites/site_ingestion_launcher.sh |
Adds launcher failure capture and logging. |
backend/app/scripts/ingestion/sites/README.md |
References logging guidance. |
backend/app/scripts/ingestion/sites/configs/perlmutter.config |
Adds Perlmutter configuration. |
backend/app/scripts/ingestion/run_machine_ingestion.sh |
Adds machine dispatch; clear archive bounds in staging mode. |
backend/app/scripts/ingestion/nersc_archive_ingestor.py |
Applies shared runner logging. |
backend/app/scripts/ingestion/hpc_upload_archive_ingestor.py |
Applies shared upload logging. |
backend/app/scripts/ingestion/archive_workflow.py |
Simplifies workflow logging and submission handling. |
backend/app/scripts/ingestion/archive_logging.py |
Implements shared logging and metrics; derive v3 environment from ENV_FILE. |
backend/app/scripts/ingestion/archive_ingestor_core.py |
Integrates event rendering and filtering. |
backend/app/scripts/ingestion/archive_discovery.py |
Streamlines discovery diagnostics. |
backend/app/scripts/ingestion/archive_client.py |
Removes redundant retry timing logs. |
💡 Configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>

Summary
Closes #321
Closes #357
SIMBOARD_INGESTION_LOG_LEVELto control verbosity. Keep case summaries at INFO and move execution decisions, missing-file details, and scan progress to DEBUG.Validation
No migrations or new dependencies. Keep this PR in draft for human review.