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

[Bug] Enhance Log Formatting Documentation #5577

Closed
2 tasks done
iamtodor opened this issue May 29, 2024 · 3 comments · Fixed by #5578
Closed
2 tasks done

[Bug] Enhance Log Formatting Documentation #5577

iamtodor opened this issue May 29, 2024 · 3 comments · Fixed by #5578
Labels
content Improvements or additions to content improvement Use this when an area of the docs needs improvement as it's currently unclear

Comments

@iamtodor
Copy link
Contributor

iamtodor commented May 29, 2024

Is this a new bug in dbt-core?

  • I believe this is a new bug in dbt-core
  • I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

Per documentation from https://docs.getdbt.com/reference/global-configs/logs#log-formatting

If the value of this config is json, dbt will output fully structured logs in JSON format; otherwise, it will output text-formatted logs that are sparser for the CLI and more detailed in logs/dbt.log.

I propose to add all allowed values as well as specifying the default one.

Similar to https://docs.getdbt.com/reference/global-configs/logs#log-level

This is a more flexible alternative to the --debug flag. The available options for the log levels are debug, info, warn, error, or none.

Expected Behavior

Unambiguous and clear documentation

Steps To Reproduce

Not applicable

Relevant log output

Not applicable

Environment

Not applicable

Which database adapter are you using with dbt?

No response

Additional Context

Documentation only

@iamtodor iamtodor added the bug Something isn't working label May 29, 2024
@iamtodor
Copy link
Contributor Author

iamtodor commented May 29, 2024

On the new issue template page https://github.com/dbt-labs/dbt-core/issues/new/choose, there is no documentation category, so I did my best to select the most appropriate one

image

@iamtodor
Copy link
Contributor Author

Also, from my perspective, it would be nice to add the possibility of adding a documentation issue, similar to Airflow templates https://github.com/apache/airflow/issues/new/choose

image

@dbeatty10 dbeatty10 self-assigned this May 29, 2024
@dbeatty10 dbeatty10 transferred this issue from dbt-labs/dbt-core May 29, 2024
@dbeatty10
Copy link
Contributor

Thanks for reaching out @iamtodor !

https://github.com/dbt-labs/docs.getdbt.com is our repository for our documentation website, so I've transferred this issue accordingly.

We haven't had much other feedback about adding an "Open" button that links to our documentation issue templates, but that would be easy to do without much downside.

It would be just adding a snippet like the following in github/ISSUE_TEMPLATE/config.yml:

  - name: Documentation
    url: https://github.com/dbt-labs/docs.getdbt.com/issues/new/choose
    about: Problems and issues with dbt documentation

I opened dbt-labs/dbt-core#10239 within the dbt-core repo to add this to the issue types.

@dbeatty10 dbeatty10 removed their assignment May 29, 2024
@dbeatty10 dbeatty10 added content Improvements or additions to content improvement Use this when an area of the docs needs improvement as it's currently unclear and removed bug Something isn't working labels May 29, 2024
matthewshaver added a commit that referenced this issue May 30, 2024
)

[Preview](https://docs-getdbt-com-git-dbeatty10-patch-1-dbt-labs.vercel.app/reference/global-configs/logs#log-formatting)

## What are you changing in this pull request and why?

resolves #5577

Allowed and default values are in the source code
[here](https://github.com/dbt-labs/dbt-core/blob/3e37d77780492499b5fcf72a99078f7843f0bd28/core/dbt/cli/params.py#L179-L180).

### TLDR

The `LOG_FORMAT` and `LOG_FORMAT_FILE` global config flags in dbt
control the format of log outputs. There are three formats:

1. **`text`**
- Outputs unstructured text with minimal metadata and second-precision
timestamps in UTC.
   - Default format for console output.

   Example:
    ```
    23:30:16  Running with dbt=1.8.0
    23:30:17  Registered adapter: postgres=1.8.0
    ```

2. **`debug`**
- Outputs unstructured text with detailed metadata including log level,
thread ID, and microsecond-precision timestamps in the system's local
time zone.
   - Default format for the `logs/dbt.log` file.

   Example:
    ```
============================== 16:12:08.555032 |
9089bafa-4010-4f38-9b42-564ec9106e07 ==============================
    16:12:08.555032 [info ] [MainThread]: Running with dbt=1.8.0
16:12:08.751069 [info ] [MainThread]: Registered adapter: postgres=1.8.0
    ```

3. **`json`**
   - Outputs structured JSON-L format logs.


   Example:
    ```json
{"data": {"log_version": 3, "version": "=1.8.0"}, "info": {"category":
"", "code": "A001", "extra": {}, "invocation_id":
"82131fa0-d2b4-4a77-9436-019834e22746", "level": "info", "msg": "Running
with dbt=1.8.0", "name": "MainReportVersion", "pid": 7875, "thread":
"MainThread", "ts": "2024-05-29T23:32:54.993336Z"}}
{"data": {"adapter_name": "postgres", "adapter_version": "=1.8.0"},
"info": {"category": "", "code": "E034", "extra": {}, "invocation_id":
"82131fa0-d2b4-4a77-9436-019834e22746", "level": "info", "msg":
"Registered adapter: postgres=1.8.0", "name": "AdapterRegistered",
"pid": 7875, "thread": "MainThread", "ts":
"2024-05-29T23:32:56.437986Z"}}

    ```

**Note:** The `debug` log format should not be confused with the `debug`
log level. The `log level` determines the number of log messages, while
the `log format` determines the detail in each log message.

### More info

There are two different sub-classes of
[`_Logger`](https://github.com/dbt-labs/dbt-common/blob/50072e70b01c988bfc7dcd777d603f8a7d7738bd/dbt_common/events/logger.py#L93):
1.
[`_TextLogger`](https://github.com/dbt-labs/dbt-common/blob/50072e70b01c988bfc7dcd777d603f8a7d7738bd/dbt_common/events/logger.py#L145)
(default)
2.
[`_JsonLogger`](https://github.com/dbt-labs/dbt-common/blob/50072e70b01c988bfc7dcd777d603f8a7d7738bd/dbt_common/events/logger.py#L190)

`_TextLogger` has two different line formats:
1.
[`DebugText`](https://github.com/dbt-labs/dbt-common/blob/50072e70b01c988bfc7dcd777d603f8a7d7738bd/dbt_common/events/logger.py#L44)
(default)
- Same as `PlainText` below except it includes a header at the beginning
of each invocation (which has a timestamp and the [invocation
ID](https://docs.getdbt.com/reference/dbt-jinja-functions/invocation_id))
and each message includes the [log
level](https://docs.getdbt.com/reference/global-configs/logs#log-level)
of the message, [thread
ID](https://docs.getdbt.com/reference/dbt-jinja-functions/thread_id),
and the timestamp has a microsecond precision using the Python system
time zone
1.
[`PlainText`](https://github.com/dbt-labs/dbt-common/blob/50072e70b01c988bfc7dcd777d603f8a7d7738bd/dbt_common/events/logger.py#L43)
- Same as `DebugText` above except it does not include a header at the
beginning of each invocation and each message does not include the [log
level](https://docs.getdbt.com/reference/global-configs/logs#log-level)
of the message or the [thread
ID](https://docs.getdbt.com/reference/dbt-jinja-functions/thread_id).
The timestamp for each message has a second precision represented in
UTC.

`_JsonLogger` has a single line format:
1.
[`Json`](https://github.com/dbt-labs/dbt-common/blob/50072e70b01c988bfc7dcd777d603f8a7d7738bd/dbt_common/events/logger.py#L45)

Those (3) line formats correspond to the options for the [`LOG_FORMAT`
and
`LOG_FORMAT_FILE`](https://docs.getdbt.com/reference/global-configs/logs#log-formatting)
global config flags:
1. `debug` -> `DebugText` line format (default for the `logs/dbt.log`
file) outputs unstructured text with more metadata at the beginning of
each log line and upon each dbt invocation
1. `text` -> `PlainText` line format (default for console output)
outputs unstructured text with minimal metadata at the beginning of each
log line and none upon each dbt invocation
1. `json` -> `Json` line format outputs structured
[JSON-L](https://www.ncbi.nlm.nih.gov/datasets/docs/v2/reference-docs/file-formats/metadata-files/why-jsonl/#why-use-the-json-lines-format-for-various-data-reports)

> [!WARNING]
> The `debug`
[`log_level`](https://docs.getdbt.com/reference/global-configs/logs#log-level)
can easily be confused with the `debug`
[`log_format`](https://docs.getdbt.com/reference/global-configs/logs#log-formatting)
since they have the same name. But the `log_level` and `log_format` are
independent configurations whose options can be mixed'n'matched.
> 
> Think of **log levels** as affecting the total number of log messages
and the **log format** as affecting the length of each log message: the
`debug` log level includes the **maximal number** of log messages
whereas the `debug` log format includes more detailed information **per
log message**
> 
> e.g. The `debug` log level filters out the least number of potential
log messages -- none! And the `debug` log format has longer lines
because it includes the most detailed debugging metadata per log
message.
> 
> To avoid confusion, we would have been better off giving the `debug`
log format a unique name instead (like `detailed`). A better name for
the `text` log format would have been `basic`, `simple`, or `brief`.

> [!NOTE]  
> I don't know the precision reasons why the `PlainText` line format is
in UTC with low-resolution while the `DebugText` with a local time zone
and high resolution

## Checklist
- [x] Review the [Content style
guide](https://github.com/dbt-labs/docs.getdbt.com/blob/current/contributing/content-style-guide.md)
so my content adheres to these guidelines.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
content Improvements or additions to content improvement Use this when an area of the docs needs improvement as it's currently unclear
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants