Skip to content

Add tracing's EnvFilter-like log filtering with PHILOMENA_LOG env var #495

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
May 12, 2025

Conversation

MareStare
Copy link
Contributor

@MareStare MareStare commented Apr 7, 2025

Before you begin

  • I understand my contributions may be rejected for any reason
  • I understand my contributions are for the benefit of Derpibooru and/or the Philomena software
  • I understand my contributions are licensed under the GNU AGPLv3
  • I understand all of the above

I've been debugging way too many things with the #481, and the lack of the logs has been a really big problem. I haven't found a good way to configure filtering the logs from different modules and third-party libraries dynamically with Elixir's logger, so I rolled my own solution with the PHILOMENA_LOG env var.

Also had to add more logs to some places to see what's actually happening there. For example, there was a bug in s3-proxy with uploading large files, but the error wasn't properly logged, now it is:

image
image

You can enable debug logging in the Objects module like this:

PHILOMENA_LOG-Ecto=none,Exq=none,PhilomenaMedia.Objects=debug,debug

And then see these logs:
image

As for the thumbnail generation logs - without them I would never know that my valkey job queue was completely full with a bunch of duplicate thumbnail generation jobs, and that I needed to clean it up manually.

On an unrelated note. I had experience with implementing a job queue at work, and we used a job fingerprint mechanism that was designed to solve this exact problem - if there is already a job in the queue with the same fingerprint, then a new one is not queued to avoid duplicate work. The fingerprint is derived from what makes the job's "identity" - i.e. its kind and parameters.

@MareStare MareStare changed the title Add tracing's EnvFilter-like log filtering with PHILOMENA_LOG env var Add tracing's EnvFilter-like log filtering with PHILOMENA_LOG env var Apr 7, 2025
# event's module and function. The last entry in the list of filters should
# be a bare `level` which will be used as a catch-all for all other log
# events that do not match any of the previous filters.
- PHILOMENA_LOG=${PHILOMENA_LOG-Ecto=none,Exq=none,PhilomenaMedia.Objects=info,debug}
Copy link
Member

Choose a reason for hiding this comment

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

why not log ecto? i often resort to seeing the exact SQL executed to see where i screwed up

Copy link
Contributor Author

@MareStare MareStare May 7, 2025

Choose a reason for hiding this comment

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

By default - SQL logging is just extremely noisy, but anyway I can keep it on by default if you insist.

To explain my thinking for the long term:

My reason to disable it by default is that I found them extremely noisy, but anyway I can't do anything with that in the terminal. Terminal is too limited for working with logs at large.

My long-term wish is to send logs to Loki and view them in Grafana where it's easy to have a brids-eye view on the general state of the app via a dashboard like this. (this is a screenshot from my Telegram bot that uses Grafana, Loki, VictoriaMetrics):

image

From this view you can quickly see the general metrics, and the last panic / error / warning logs.

Then you can drill down into the gory details of the logs using the LogQL syntax, narrow it down by time and request span IDs.
image

Then expand the details of every log event you are interested in
image

This way there is no noise by default, it's convenient to view logs, and debug any request.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I've rebased this branch since it's been rather old. I pushed a single commit new change a94c676 to set ecto logging level to debug. Everything else is the same

@MareStare MareStare force-pushed the feat/better-logging branch from 53352ae to a94c676 Compare May 7, 2025 15:39
@MareStare MareStare requested a review from Meow May 7, 2025 15:40
@Meow Meow added this to the 1.2 milestone May 9, 2025
Copy link
Member

@Meow Meow left a comment

Choose a reason for hiding this comment

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

You seem to have refactored philomena_media/objects.ex in this PR, please pull that out to a separate PR, as a change like this isn't within the scope of a simple logging change.

@MareStare
Copy link
Contributor Author

Moved the S3 changes to #570

@MareStare MareStare requested a review from Meow May 12, 2025 10:20
@Meow Meow merged commit 23c0421 into philomena-dev:master May 12, 2025
6 checks passed
Meow pushed a commit that referenced this pull request May 12, 2025
…nv var (#495)

* Add `tracing`'s `EnvFilter`-like log filtering with `PHILOMENA_LOG` env var

* Add logs about thumbnails generation

* Better comment

* Remove nesting via `with`

* Use `debug` logging level for ecto by default as per Meow
MareStare added a commit to MareStare/philomena that referenced this pull request May 20, 2025
…nv var (philomena-dev#495)

* Add `tracing`'s `EnvFilter`-like log filtering with `PHILOMENA_LOG` env var

* Add logs about thumbnails generation

* Better comment

* Remove nesting via `with`

* Use `debug` logging level for ecto by default as per Meow
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.

2 participants