Skip to content

fix: stop scrape logger spam, refactor scrape logger design#1381

Merged
electron0zero merged 2 commits into
prometheus:masterfrom
tjhop:fix/scrape-logger-spam
May 21, 2025
Merged

fix: stop scrape logger spam, refactor scrape logger design#1381
electron0zero merged 2 commits into
prometheus:masterfrom
tjhop:fix/scrape-logger-spam

Conversation

@tjhop
Copy link
Copy Markdown
Contributor

@tjhop tjhop commented Mar 18, 2025

Based on discussion in #1377, slack, etc, it seems unclear what the
intended functionality/behavior of the probe scrape logger was supposed to be.
This is an attempt to align behavior with current user expectations. The
improved defaults and updated configs here should address the log spam
as well.

User facing changes:

  • the --log.prober flag now sets the level at which prober scrape
    logs will be emitted at
    .
  • the --log.prober flag now defaults to debug level. Because the
    default log level is info, this means that in order to see probe
    scrape logs, a user must either:
    • increase the level of the logger via --log.level to be >= that
      of --log.prober (ie, set both to debug)
    • decrease the level of the probe logger via --log.prober to be <=
      that of --log.level (ie, set both to info)

Note:
This approach (emitting all logs from the probe logger at the level
specified) involves hijacking calls to the logger and overriding the
level. This comes with the very obvious side effect that the developers
working on code using the probe scrape logger no longer have control
over the control over the level of the log that gets emitted. Regardless
of whether they use l.Info() or l.Debug(), it'll still get logged at
the configured log prober level. This approach likely would not be
compatible with some of the other discussions around how probe scrape
logs work, like #1401.

Signed-off-by: TJ Hoplock t.hoplock@gmail.com

@tjhop tjhop force-pushed the fix/scrape-logger-spam branch from bb17f7e to 7a291b8 Compare March 18, 2025 04:29
Based on discussion in prometheus#1377, slack, etc, it seems unclear what the
intended functionality/behavior of the probe scrape logger was supposed to be.
This is an attempt to align behavior with current user expectations. The
improved defaults and updated configs here should address the log spam
as well.

User facing changes:
- the `--log.prober` flag now sets the _level at which prober scrape
  logs will be emitted at_.
- the `--log.prober` flag now defaults to `debug` level. Because the
  default log level is info, this means that in order to see probe
scrape logs, a user must either:
    - increase the level of the logger via `--log.level` to be >= that
      of `--log.prober` (ie, set both to `debug`)
    - decrease the level of the probe logger via `--log.prober` to be <=
      that of `--log.level` (ie, set both to `info`)

Note:
This approach (emitting all logs from the probe logger at the level
specified) involves hijacking calls to the logger and overriding the
level. This comes with the very obvious side effect that the developers
working on code using the probe scrape logger no longer have control
over the control over the level of the log that gets emitted. Regardless
of whether they use `l.Info()` or `l.Debug()`, it'll still get logged at
the configured log prober level. This approach likely would not be
compatible with some of the other discussions around how probe scrape
logs work, like prometheus#1401.

Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
@tjhop tjhop force-pushed the fix/scrape-logger-spam branch from 7a291b8 to 7df3031 Compare May 8, 2025 03:52
@tjhop tjhop changed the title fix: stop scrape logger spam fix: stop scrape logger spam, refactor scrape logger design May 8, 2025
@tjhop tjhop mentioned this pull request May 8, 2025
@tjhop
Copy link
Copy Markdown
Contributor Author

tjhop commented May 19, 2025

@SuperQ @electron0zero I believe this is ready for review if you find yourselves with some spare time 🙃

Copy link
Copy Markdown
Member

@SuperQ SuperQ left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

@SuperQ SuperQ requested a review from electron0zero May 19, 2025 15:53
Comment thread main.go Outdated
Address PR feedback

Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
@electron0zero electron0zero merged commit a72fbd7 into prometheus:master May 21, 2025
5 checks passed
@electron0zero
Copy link
Copy Markdown
Member

thank you for your contribution 👏🏼

@paketb0te
Copy link
Copy Markdown

@tjhop I feel like I am misunderstanding the --log.prober flag, maybe you can help me understand it better? 😅

In the docs, you provide example output for different combinations of --log.level and --log.prober (which I think is a great way to illustrate this, btw) - to me it looks like the combination --log.level=info and --log.prober=info is more verbose than the (apparently default) combination --log.level=info and --log.prober=debug.

My understanding of log levels is that "increasing" the log level (e.g. going from INFO to DEBUG in this case) should only ever "add" log output, meaning that the log lines emitted at level DEBUG should also include all lines that would be emitted at level INFO (and the log level of those messages would still show up as "INFO").

Is my understanding of log levels incorrect, or am I maybe misunderstanding what we are trying to achieve here?

(I have read the discussion in #1377 but am still unsure...)

@paketb0te
Copy link
Copy Markdown

related question: Is it (still?) possible to configure log levels in the config file?
The docs mention this, but I see nothing related in the example config and also the actual code (the module structs) looks like this is not possible.

SuperQ added a commit that referenced this pull request Jun 26, 2025
* [FEATURE] Support matching JSON body with CEL expressions #1255
* [BUGFIX] Fix condition when local dns lookup should happen #1272
* [BUGFIX] Stop scrape logger spam #1381

Signed-off-by: SuperQ <superq@gmail.com>
@SuperQ SuperQ mentioned this pull request Jun 26, 2025
SuperQ added a commit that referenced this pull request Jun 30, 2025
* [FEATURE] Support matching JSON body with CEL expressions #1255
* [BUGFIX] Fix condition when local dns lookup should happen #1272
* [BUGFIX] Stop scrape logger spam #1381

Signed-off-by: SuperQ <superq@gmail.com>
@tentakle
Copy link
Copy Markdown

tentakle commented Jul 7, 2025

Now when I run the curl command:
curl -s 'http://localhost:9115/probe?module=http_2xx&debug=true&target=https://example.com'
it outputs empty logs?

Logs for the probe:  
  

We did something strange.

@tjhop
Copy link
Copy Markdown
Contributor Author

tjhop commented Jul 8, 2025

@paketb0te no worries, this is a non-standard feature anyway, and the way it "merges" log streams isn't super intuitive (which is why it's taking us so long to work out exactly how this should work). Here's an analogy/mental model that I find helpful when trying to understand what the scrape probe logger is doing now:

Let's imagine logging is like a railroad system, with an individual railway for each of the log levels: info, warn, error, debug. These are the only railways that are routeable to a destination, and the verbosity levels in the --log.level flag control how many of these level railways route to the same "destination", ie the user.
We also have a 5th railway for the probe logger. The --log.prober flag acts as a railway switch to route this 5th railway onto one of the other existing tracks -- the leveled railway it joins determines where the logs go.

Here's a decent text diagram I was able to get of the logical flow that I was able to get gemini to make for me:

                                      +------------------+
                                      |   --log.prober   |
[probe logger]----------------------->|      SWITCH      |---+
                                      +------------------+   |
                                                             |
   +---------------------------------------------------------+
   |             |                   |                       |
   v             v                   v                       v
[info] track  [warn] track      [error] track           [debug] track
   |             |                   |                       |
   |             |                   |                       |
   v             v                   v                       v
+-----------------------------------------------------------------+
|                          --log.level                            |
|                  (Controls which tracks are active)             |
+-----------------------------------------------------------------+
   |             |                   |                       |
   |             |                   |                       |
   +-------------+-------------------+-----------------------+---> [FINAL OUTPUT]


Does that help to clarify things at all?

@tjhop
Copy link
Copy Markdown
Contributor Author

tjhop commented Jul 8, 2025

@tentakle yea, this whole feature is a tad strange 🙃

Good catch, though! I was able to replicate, and I'm working on a fix for use with the debug param output. I'll open a PR when it's ready and ask for a patch release. bug fix for the bug fix, heh. Here's to hoping we've uncovered the last of the behavioral quirks

tjhop added a commit to tjhop/blackbox_exporter that referenced this pull request Jul 8, 2025
Fixes issue reported here:
prometheus#1381 (comment)

In aligning behavior for how the `--log.prober` flag is currently
expected to work, I didn't test it's effect on logs when used with the
`debug` URL parameter, as is often done for testing.

This changes the handler to always write to the internal buffer logger
(which is what is used to store the logs for displaying with the `debug`
url param), and it only writes through to the real logger if it's
enabled for the level the prober is set to. This ensures that logs are
always available with the `debug` param, while still correctly filtering
levels for console output at stderr.

As a consequence of thinking about how to make this work, I also
realized it wasn't necessary to manually iterate record attrs or
maintain our own attr list when hijacking the log call -- the level can
be overridden directly from the record, we just need to grab a copy via
Clone() first. So should be more efficient, as well.

Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
SuperQ pushed a commit that referenced this pull request Jul 26, 2025
Fixes issue reported here:
#1381 (comment)

In aligning behavior for how the `--log.prober` flag is currently
expected to work, I didn't test it's effect on logs when used with the
`debug` URL parameter, as is often done for testing.

This changes the handler to always write to the internal buffer logger
(which is what is used to store the logs for displaying with the `debug`
url param), and it only writes through to the real logger if it's
enabled for the level the prober is set to. This ensures that logs are
always available with the `debug` param, while still correctly filtering
levels for console output at stderr.

As a consequence of thinking about how to make this work, I also
realized it wasn't necessary to manually iterate record attrs or
maintain our own attr list when hijacking the log call -- the level can
be overridden directly from the record, we just need to grab a copy via
Clone() first. So should be more efficient, as well.

Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
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.

5 participants