Add TRACE debug level to show each line that is being parsed

[mishaschwartz]

See discussion here: bird-house/birdhouse-deploy#550 (comment)

[tlvu]

@mishaschwartz

The prometheus-log-parser is live on our production instance.

We do have export PROMETHEUS_LOG_PARSER_LOG_LEVEL=DEBUG in env.local but this is all we see in docker logs prometheus-log-parser, basically nothing useful.

2026-04-14 21:36:27,775 - log_parser.log_parser - INFO - file '/var/log/proxy/access_file.log' has been replaced. Tracking will resume from the beginning of the file.
2026-04-14 21:40:46,854 - log_parser.log_parser - INFO - file '/var/log/proxy/access_file.log' has been replaced. Tracking will resume from the beginning of the file.
2026-04-14 21:42:03,771 - log_parser.log_parser - INFO - file '/var/log/proxy/access_file.log' has been replaced. Tracking will resume from the beginning of the file.
2026-04-14 21:45:02,613 - log_parser.log_parser - INFO - file '/var/log/proxy/access_file.log' has been replaced. Tracking will resume from the beginning of the file.
2026-04-14 21:46:00,297 - log_parser.log_parser - INFO - file '/var/log/proxy/access_file.log' has been replaced. Tracking will resume from the beginning of the file.
2026-04-14 21:52:01,214 - log_parser.log_parser - INFO - file '/var/log/proxy/access_file.log' has been replaced. Tracking will resume from the beginning of the file.

The exporter do not seem to work anymore and we do not know why.

[mishaschwartz]

@tlvu

Which version of the log parser are you using?

I have export PROMETHEUS_LOG_PARSER_LOG_LEVEL=DEBUG in env.local as well and this is what I see for example from the top:

2026-04-16 13:57:53,542 - log_parser.cli - DEBUG - appended '/parsers.d' to sys.path
2026-04-16 13:57:53,542 - log_parser.cli - INFO - loading parser from: /parsers.d/thredds-prometheus-log-exporter.py
2026-04-16 13:57:53,545 - log_parser.cli - DEBUG - removed '/parsers.d' from sys.path
2026-04-16 13:57:53,545 - log_parser.log_parser - DEBUG - calling: track({'/var/log/proxy/access_file.log': [<function parse_line at 0x7f879f04a340>]}, 1, True, None, )
2026-04-16 13:57:53,545 - log_parser.log_parser - DEBUG - calling: track_async({'/var/log/proxy/access_file.log': [<function parse_line at 0x7f879f04a340>]}, 1, True, None, )
2026-04-16 13:57:53,546 - asyncio - DEBUG - Using selector: EpollSelector
2026-04-16 13:57:53,546 - log_parser.log_parser - DEBUG - calling: track_file(/var/log/proxy/access_file.log, [<function parse_line at 0x7f879f04a340>], 1, True, timeout=None)
2026-04-16 13:57:53,546 - log_parser.log_parser - INFO - tracking '/var/log/proxy/access_file.log' starting from the end.
2026-04-16 13:57:53,553 - log_parser.log_parser - DEBUG - file '/var/log/proxy/access_file.log' opened for reading

Can you check higher up in your logs to see if there are other debug statements that you're missing?

For the issue with prometheus... that scrape duration seems really really long. Are you able to access the log-parser's /metrics endpoint through curl or something and see if you're getting reasonable amounts of data when you do that?
See a possible explanation here (bird-house/birdhouse-deploy#682 (review))

[tlvu]

Can you check higher up in your logs to see if there are other debug statements that you're missing?

$ docker logs prometheus-log-parser 2>&1 | grep -i debug

(...)

2026-03-26 22:09:02,801 - log_parser.cli - DEBUG - appended '/parsers.d' to sys.path
2026-03-26 22:09:02,804 - log_parser.cli - DEBUG - removed '/parsers.d' from sys.path
2026-03-26 22:09:02,805 - log_parser.log_parser - DEBUG - calling: track({'/var/log/proxy/access_file.log': [<function parse_line at 0x7f5d924a45e0>]}, 1, True, None, )
2026-03-26 22:09:02,805 - log_parser.log_parser - DEBUG - calling: track_async({'/var/log/proxy/access_file.log': [<function parse_line at 0x7f5d924a45e0>]}, 1, True, None, )
2026-03-26 22:09:02,805 - asyncio - DEBUG - Using selector: EpollSelector
2026-03-26 22:09:02,805 - log_parser.log_parser - DEBUG - calling: track_file(/var/log/proxy/access_file.log, [<function parse_line at 0x7f5d924a45e0>], 1, True, timeout=None)
2026-03-26 22:09:02,820 - log_parser.log_parser - DEBUG - file '/var/log/proxy/access_file.log' opened for reading
2026-04-16 05:10:36,304 - log_parser.cli - DEBUG - appended '/parsers.d' to sys.path
2026-04-16 05:10:36,307 - log_parser.cli - DEBUG - removed '/parsers.d' from sys.path
2026-04-16 05:10:36,308 - log_parser.log_parser - DEBUG - calling: track({'/var/log/proxy/access_file.log': [<function parse_line at 0x7f4775f485e0>]}, 1, True, None, )
2026-04-16 05:10:36,308 - log_parser.log_parser - DEBUG - calling: track_async({'/var/log/proxy/access_file.log': [<function parse_line at 0x7f4775f485e0>]}, 1, True, None, )
2026-04-16 05:10:36,308 - asyncio - DEBUG - Using selector: EpollSelector
2026-04-16 05:10:36,308 - log_parser.log_parser - DEBUG - calling: track_file(/var/log/proxy/access_file.log, [<function parse_line at 0x7f4775f485e0>], 1, True, timeout=None)
2026-04-16 05:10:36,321 - log_parser.log_parser - DEBUG - file '/var/log/proxy/access_file.log' opened for reading

I did not meant export PROMETHEUS_LOG_PARSER_LOG_LEVEL=DEBUG in env.local do not work. It does work.

What I meant is the DEBUG info are not giving anything useful.

[mishaschwartz]

Oh right, well that's because the logger isn't logging anything at the DEBUG level once we start reading the file.