Skip to content
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

Structlog #5687

Merged
merged 14 commits into from
May 23, 2024
Merged

Structlog #5687

merged 14 commits into from
May 23, 2024

Conversation

snaselj
Copy link
Contributor

@snaselj snaselj commented May 8, 2024

Closes NaN

What's Changed

  • Added structlog logging.
  • Added NAUTOBOT_LOG_DEBUG_DB environment variable to enable Django database logs.
  • Added NAUTOBOT_LOG_PLAIN environment variable to switch to plaintext structlog output from JSON.

To Do

@snaselj snaselj self-assigned this May 8, 2024
@glennmatthews
Copy link
Contributor

Can you provide some examples of the resulting Nautobot logs both with and without DEBUG enabled?

Copy link
Contributor

@glennmatthews glennmatthews left a comment

Choose a reason for hiding this comment

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

Since this is a non-trivial feature, would you please target the PR to next (2.3.0) rather than develop (2.2.x)?

Comment on lines 519 to 520
INSTALLED_APPS,
MIDDLEWARE,
Copy link
Contributor

Choose a reason for hiding this comment

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

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Works well with both EXTRA_INSTALLED_APPS and EXTRA_MIDDLEWARE.

Comment on lines 523 to 524
debug_db=is_truthy(os.getenv("NAUTOBOT_LOG_DEBUG_DB", "False")),
plain_format=is_truthy(os.getenv("NAUTOBOT_LOG_PLAIN", "False")),
Copy link
Contributor

Choose a reason for hiding this comment

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

If these are only configurable via environment variables (not ideal!) then they should be documented in nautobot/docs/user-guide/administration/configuration/optional-settings.md under the "Environment-Variable-Only Settings" header.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

What is a better way to configure these? Note, we need to process these configuration settings into LOGGING Django settings attribute.

Copy link
Contributor

Choose a reason for hiding this comment

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

Ideally they'd be settable directly via Python in any nautobot_config.py as well without needing to manipulate os.environ.

changes/5687.housekeeping Outdated Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
if "test" in sys.argv:
django_logging["handlers"] = {
"null_handler": {
"level": "INFO",
Copy link
Contributor

Choose a reason for hiding this comment

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

Not log_level?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

level is the correct key here.

Copy link
Contributor

Choose a reason for hiding this comment

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

sorry, I meant instead of "INFO" being hard-coded. Same comment below.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

For testing, it was hardcoded to INFO in the original settings, so this keeps the same behavior.

As it is using "class": "logging.NullHandler", it disables log anyway.

}
for logger in django_logging["loggers"].values():
logger["handlers"] = ["null_handler"]
logger["level"] = "INFO"
Copy link
Contributor

Choose a reason for hiding this comment

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

Not log_level?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

level is the correct key here.

nautobot/core/settings_funcs.py Outdated Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
Comment on lines +148 to +151
if debug_db:
django_logging["loggers"]["django.db.backends"] = {"level": "DEBUG"}
Copy link
Contributor

Choose a reason for hiding this comment

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

Why is this specific logger handled specially?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is driven by NAUTOBOT_LOG_DEBUG_DB environment variable, inspired by management services configuration.

Added info about new environment variables to changes/5687.added.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

And the answer to why is to be able to selectively enable database queries logging.

@snaselj snaselj changed the base branch from develop to next May 9, 2024 08:06
@snaselj
Copy link
Contributor Author

snaselj commented May 9, 2024

Since this is a non-trivial feature, would you please target the PR to next (2.3.0) rather than develop (2.2.x)?

Changed base branch to next.

@snaselj snaselj marked this pull request as ready for review May 9, 2024 12:56
@snaselj
Copy link
Contributor Author

snaselj commented May 9, 2024

Can you provide some examples of the resulting Nautobot logs both with and without DEBUG enabled?

Log examples with:

NAUTOBOT_DEBUG=1
NAUTOBOT_LOG_PLAIN=1
nautobot-1  | 2024-05-09T12:40:58.089576Z [debug    ] Loading example_app!           [nautobot.extras.plugins.utils]
nautobot-1  | 2024-05-09T12:40:58.090570Z [info     ] Nautobot initialized!          [nautobot]
nautobot-1  | 2024-05-09T12:41:19.070546Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET /login/?next=/ request_id=1e0de46b-570e-4bc5-bcff-c7c9731bc53f user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=None
nautobot-1  | 2024-05-09T12:41:19.165370Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET /login/?next=/ request_id=1e0de46b-570e-4bc5-bcff-c7c9731bc53f user_id=None
nautobot-1  | 2024-05-09T12:41:19.347753Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET /template.css request_id=8832ce6f-ab1d-47b9-9169-dc2aae519438 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=None
nautobot-1  | 2024-05-09T12:41:19.348687Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET /template.css request_id=8832ce6f-ab1d-47b9-9169-dc2aae519438 user_id=None
nautobot-1  | 2024-05-09T12:43:50.138837Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=POST /login/ request_id=114b2ec7-5bc9-4d03-bca3-aef80d66371c user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=None
nautobot-1  | 2024-05-09T12:43:50.212636Z [debug    ] Login form validation was successful [nautobot.auth.login] ip=10.166.35.2 request_id=114b2ec7-5bc9-4d03-bca3-aef80d66371c user_id=None
nautobot-1  | 2024-05-09T12:43:50.229456Z [info     ] User admin successfully authenticated [nautobot.auth.login] ip=10.166.35.2 request_id=114b2ec7-5bc9-4d03-bca3-aef80d66371c user_id=None
nautobot-1  | 2024-05-09T12:43:50.236647Z [debug    ] Redirecting user to /          [nautobot.auth.login] ip=10.166.35.2 request_id=114b2ec7-5bc9-4d03-bca3-aef80d66371c user_id=None
nautobot-1  | 2024-05-09T12:43:50.236735Z [info     ] request_finished               [django_structlog.middlewares.request] code=302 ip=10.166.35.2 request=POST /login/ request_id=114b2ec7-5bc9-4d03-bca3-aef80d66371c user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:43:50.350696Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET / request_id=1fbd0806-d66c-41aa-b653-73a2d55a1e65 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:43:50.369314Z [debug    ] Skipping release check; RELEASE_CHECK_URL not defined [nautobot.core.releases] ip=10.166.35.2 request_id=1fbd0806-d66c-41aa-b653-73a2d55a1e65 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:43:50.564229Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET / request_id=1fbd0806-d66c-41aa-b653-73a2d55a1e65 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:43:51.020018Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET /template.css request_id=3415adf5-cecd-4a88-b5f6-9a27aecce293 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:43:51.021238Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET /template.css request_id=3415adf5-cecd-4a88-b5f6-9a27aecce293 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799

With:

NAUTOBOT_DEBUG=0
NAUTOBOT_LOG_PLAIN=1
nautobot-1  | 2024-05-09T12:49:40.638786Z [info     ] Nautobot initialized!          [nautobot]
nautobot-1  | 2024-05-09T12:49:43.592881Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET /login/?next=/ request_id=dcb6c36d-cc81-4ffe-a599-ae4da453c151 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=None
nautobot-1  | 2024-05-09T12:49:43.607732Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET /login/?next=/ request_id=dcb6c36d-cc81-4ffe-a599-ae4da453c151 user_id=None
nautobot-1  | 2024-05-09T12:49:43.723497Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET /template.css request_id=ba119d6d-1248-483f-86ff-38211cc029d6 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=None
nautobot-1  | 2024-05-09T12:49:43.724573Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET /template.css request_id=ba119d6d-1248-483f-86ff-38211cc029d6 user_id=None
nautobot-1  | 2024-05-09T12:49:46.811718Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=POST /login/ request_id=f5506374-2cd6-4e8f-b2a9-84c037e44e53 user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=None
nautobot-1  | 2024-05-09T12:49:46.897887Z [info     ] User admin successfully authenticated [nautobot.auth.login] ip=10.166.35.2 request_id=f5506374-2cd6-4e8f-b2a9-84c037e44e53 user_id=None
nautobot-1  | 2024-05-09T12:49:46.905343Z [info     ] request_finished               [django_structlog.middlewares.request] code=302 ip=10.166.35.2 request=POST /login/ request_id=f5506374-2cd6-4e8f-b2a9-84c037e44e53 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:49:47.025006Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET / request_id=4f66f8d9-ec7e-4dfc-a378-759b205789bb user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:49:47.079070Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET / request_id=4f66f8d9-ec7e-4dfc-a378-759b205789bb user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:49:47.195770Z [info     ] request_started                [django_structlog.middlewares.request] ip=10.166.35.2 request=GET /template.css request_id=5205c18e-a0f6-41a6-be2a-9cd663e50aba user_agent=Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36 user_id=99963881-7ce9-492b-8ec7-4c330ee1b799
nautobot-1  | 2024-05-09T12:49:47.196435Z [info     ] request_finished               [django_structlog.middlewares.request] code=200 ip=10.166.35.2 request=GET /template.css request_id=5205c18e-a0f6-41a6-be2a-9cd663e50aba user_id=99963881-7ce9-492b-8ec7-4c330ee1b799

With:

NAUTOBOT_DEBUG=0
NAUTOBOT_LOG_PLAIN=0
nautobot-1  | {"event": "Nautobot initialized!", "level": "info", "logger": "nautobot", "timestamp": "2024-05-09T12:51:43.677022Z"}
nautobot-1  | {"request": "GET /login/?next=/", "user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36", "event": "request_started", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": null, "ip": "10.166.35.2", "request_id": "9b9f00e7-7cbc-431f-a9cf-a484b9d1bc12", "timestamp": "2024-05-09T12:51:49.244073Z"}
nautobot-1  | {"code": 200, "request": "GET /login/?next=/", "event": "request_finished", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": null, "ip": "10.166.35.2", "request_id": "9b9f00e7-7cbc-431f-a9cf-a484b9d1bc12", "timestamp": "2024-05-09T12:51:49.258771Z"}
nautobot-1  | {"request": "GET /template.css", "user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36", "event": "request_started", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": null, "ip": "10.166.35.2", "request_id": "85946f20-f9a8-4fa6-a60b-0e60465cac04", "timestamp": "2024-05-09T12:51:49.402089Z"}
nautobot-1  | {"code": 200, "request": "GET /template.css", "event": "request_finished", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": null, "ip": "10.166.35.2", "request_id": "85946f20-f9a8-4fa6-a60b-0e60465cac04", "timestamp": "2024-05-09T12:51:49.402872Z"}
nautobot-1  | {"request": "POST /login/", "user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36", "event": "request_started", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": null, "ip": "10.166.35.2", "request_id": "ed57d881-cad4-4240-8492-1858cb6e5aca", "timestamp": "2024-05-09T12:51:53.628068Z"}
nautobot-1  | {"event": "User admin successfully authenticated", "level": "info", "logger": "nautobot.auth.login", "user_id": null, "ip": "10.166.35.2", "request_id": "ed57d881-cad4-4240-8492-1858cb6e5aca", "timestamp": "2024-05-09T12:51:53.714045Z"}
nautobot-1  | {"code": 302, "request": "POST /login/", "event": "request_finished", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": "99963881-7ce9-492b-8ec7-4c330ee1b799", "ip": "10.166.35.2", "request_id": "ed57d881-cad4-4240-8492-1858cb6e5aca", "timestamp": "2024-05-09T12:51:53.721586Z"}
nautobot-1  | {"request": "GET /", "user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36", "event": "request_started", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": "99963881-7ce9-492b-8ec7-4c330ee1b799", "ip": "10.166.35.2", "request_id": "50b8e78f-92f9-41d0-8c54-69948fa702e6", "timestamp": "2024-05-09T12:51:53.902784Z"}
nautobot-1  | {"code": 200, "request": "GET /", "event": "request_finished", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": "99963881-7ce9-492b-8ec7-4c330ee1b799", "ip": "10.166.35.2", "request_id": "50b8e78f-92f9-41d0-8c54-69948fa702e6", "timestamp": "2024-05-09T12:51:53.953947Z"}
nautobot-1  | {"request": "GET /template.css", "user_agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36", "event": "request_started", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": "99963881-7ce9-492b-8ec7-4c330ee1b799", "ip": "10.166.35.2", "request_id": "633c1ec3-b2ac-4bb2-bd95-447e2b6419c9", "timestamp": "2024-05-09T12:51:54.073128Z"}
nautobot-1  | {"code": 200, "request": "GET /template.css", "event": "request_finished", "level": "info", "logger": "django_structlog.middlewares.request", "user_id": "99963881-7ce9-492b-8ec7-4c330ee1b799", "ip": "10.166.35.2", "request_id": "633c1ec3-b2ac-4bb2-bd95-447e2b6419c9", "timestamp": "2024-05-09T12:51:54.073773Z"}

@snaselj snaselj requested a review from glennmatthews May 9, 2024 12:56
@jvanderaa
Copy link
Contributor

Is this a breaking change? Will the defaults have logs in the same output as before? I'm thinking about security organizations that may have parsers of logs set up...

@lampwins
Copy link
Member

I don’t feel comfortable with the size and scope of this for 2.3. When we spoke about this, my understanding was we were going to add structlog as a core dependency only. Any configuration can go in nautobot_config.py.

@snaselj
Copy link
Contributor Author

snaselj commented May 13, 2024

Is this a breaking change? Will the defaults have logs in the same output as before? I'm thinking about security organizations that may have parsers of logs set up...

By default, log output is different now, using structlog JSON formatting.

For instances rewriting LOGGING configuration key in a custom nautobot_config.py, nothing should change.

@snaselj
Copy link
Contributor Author

snaselj commented May 13, 2024

I don’t feel comfortable with the size and scope of this for 2.3. When we spoke about this, my understanding was we were going to add structlog as a core dependency only. Any configuration can go in nautobot_config.py.

@lampwins

structlog is a core dependency, not sure what should be changed here.

Separated structlog configuration to core/settings_funcs.py, to be reusable. Do you want to move everything to core/settings.py instead?

Added NAUTOBOT_LOG_PLAIN to allow switching to plaintext structlog logging. Do you want to remove this settings?

Added NAUTOBOT_LOG_DEBUG_DB to allow enabling SQL logs. Do you want to remove this settings?

@glennmatthews
Copy link
Contributor

As I understand it the approach we would prefer is to add structlog as a dependency, but not to enable it in 2.3 unless this can be done in such a way as to not introduce any behavior change in the logging output for any existing deployments that are using Nautobot's provided default logging configuration.

@snaselj
Copy link
Contributor Author

snaselj commented May 20, 2024

@glennmatthews

Updated based on the latest comments, ready for review now.

nautobot/core/settings_funcs.py Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
nautobot/docs/development/core/settings.md Outdated Show resolved Hide resolved
changes/5687.dependencies Outdated Show resolved Hide resolved
development/nautobot_config.py Outdated Show resolved Hide resolved
nautobot/core/settings_funcs.py Show resolved Hide resolved
@@ -85,3 +85,30 @@ Markdown rendering is supported for the `description`, `details`, and `default_l
### Technical Details of Settings Documentation

The `optional-settings.md` and `required-settings.md` files are rendered as Jinja2 templates via [`Mkdocs-Macros`](https://mkdocs-macros-plugin.readthedocs.io/en/latest/). The file `nautobot/docs/macros.py` is responsible for loading `settings.yaml` into the template context for rendering. `mkdocs.yml` instructs Mkdocs-Macros to run that file at documentation rendering time. The macros and templating are *not* enabled for all documentation by default - instead, only the files with `render_macros: true` in their headers will be templated.

## Structlog Configuration
Copy link
Contributor

Choose a reason for hiding this comment

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

This settings.md file is developer-facing not end-user-facing. Can you add this content to nautobot/core/settings.yaml under the LOGGING details section instead?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Moved as proposed.

@glennmatthews glennmatthews merged commit ded1ce7 into next May 23, 2024
17 checks passed
@glennmatthews glennmatthews deleted the u/snaselj-structlog branch May 23, 2024 17:23
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.

None yet

5 participants