Skip to content

Make the log level selectable instead of always DEBUG - #351

Open
dchaudhari7177 wants to merge 1 commit into
RyanDFIR:mainfrom
dchaudhari7177:fix/336-log-level
Open

Make the log level selectable instead of always DEBUG#351
dchaudhari7177 wants to merge 1 commit into
RyanDFIR:mainfrom
dchaudhari7177:fix/336-log-level

Conversation

@dchaudhari7177

Copy link
Copy Markdown
Contributor

Closes #336.

logging.basicConfig(..., level=logging.DEBUG) was hardcoded in both hindsight.py and hindsight_gui.py, so every run wrote a full debug trace and there was no way to ask for less.

What this adds

--log-level {debug,info,warning,error}, defaulting to info, and a matching dropdown in the web UI. The explicit form rather than -v/-q counters, because it is the one that maps onto a dropdown.

Both entry points now go through one helper, pyhindsight/logging_setup.py. That is the "or the two will drift" point from the issue, and the drift had already happened: the CLI passed encoding="utf-8" with a comment explaining why, and the GUI did not — so the GUI was silently losing anything outside cp1252 on Windows, in a logging call that swallows handler errors. Sharing the helper fixes that as a side effect.

Dependencies stay quiet

The issue notes basicConfig configures the root logger, so the hardcoded DEBUG pulled in third-party debug output too. The root logger now stays at WARNING and only Hindsight's own loggers carry the requested level. Records from a child logger are handed to the root handler, which has no level of its own, so this filters other libraries without filtering us:

level     what reaches the log
debug  -> OURS-debug, OURS-info, OURS-warning, MAIN-info, THIRDPARTY-warning
info   ->             OURS-info, OURS-warning, MAIN-info, THIRDPARTY-warning
warning->                        OURS-warning,            THIRDPARTY-warning

THIRDPARTY-debug is absent from all three, including debug.

End to end

Against tests/fixtures:

--log-level debug : 192 lines, 43 DEBUG
--log-level info  : 149 lines,  0 DEBUG

INFO keeps the per-artifact counts, the skip and failure lines and the Not Parsed items summary, and drops the directory listings and options dump — the split the issue describes.

The trap

The run reports unparsed totals at WARNING but logs each individual unparsed record at DEBUG, and the summary told the reader those detail lines were "logged above". At the default level they are not.

Of the issue's two options I took the second: the per-record call stays at DEBUG, because a large sweep can produce very many of them and promoting them to INFO would undo much of what raising the default buys. The summary line now says so explicitly:

- Local Storage: parsed 412, 2 source(s) and 7 record(s) unparsed; each unparsed
  source is logged above as "Unparsed source in local_storage", and each unparsed
  record as "Unparsed record in local_storage" at the debug level (--log-level debug)

Per-source detail is already WARNING and is unaffected. tests/test_partial_results.py::test_detail_line_count_equals_the_reported_totals is unaffected too — it installs its own handler at DEBUG, so it pins the collector rather than the default level, which is the right thing for it to pin.

Not in scope

Console verbosity. The progress display is not driven by logging, so a quiet flag for it is a separate decision — and #339 is already about that surface.

Verification

python -m pytest tests/ -q --ignore=tests/corpus
258 passed, 2 skipped, 80 subtests passed

tests/test_logging_setup.py adds 10 cases: every documented level name, case and whitespace tolerance, the web-form fallback for a bad value (which must not take a run down), the level boundaries in both directions, that dependencies stay at warning under --log-level debug, that a second configure_logging in one process takes the new level (the GUI serves many runs, and basicConfig is a no-op once the root logger has handlers), and that the log is written as UTF-8.

Both entry points called logging.basicConfig(..., level=logging.DEBUG),
so every run wrote a full debug trace with no way to ask for less. On a
real profile that is 1,655 lines of which 90% are DEBUG and 9 are
WARNING or ERROR, which is a log nobody reads.

Add --log-level {debug,info,warning,error}, defaulting to info, and a
matching dropdown in the web UI. Both go through one helper in
pyhindsight.logging_setup so the two cannot drift, which is what
happened to the encoding argument: the CLI passed encoding='utf-8' and
the GUI did not, so the GUI silently lost anything outside cp1252 on
Windows.

basicConfig configures the root logger, so the hardcoded DEBUG also
turned on debug output for every dependency. The root now stays at
WARNING and only Hindsight's own loggers carry the requested level, so
third-party debug never appears even at --log-level debug.

INFO keeps the per-artifact counts, the skip and failure lines and the
Not Parsed items summary, and drops the directory listings and options
dump. On the test fixtures that is 149 lines against 192.

That raises the trap the issue names: the unparsed totals are reported
at WARNING but each individual unparsed record is logged at DEBUG, so at
the default level the summary pointed at detail lines a reader would not
find. The per-record call stays at DEBUG, because a large sweep can
produce very many of them; the summary now says the record-level detail
needs --log-level debug. Per-source detail is already WARNING.

Closes RyanDFIR#336
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Log level is hardcoded to DEBUG with no way to ask for less

1 participant