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

[CT-2748] [Feature] A single Structured Logging JSON dictionary per Exception #7963

Closed
2 tasks done
moltar opened this issue Jun 27, 2023 · 4 comments · Fixed by #8210
Closed
2 tasks done

[CT-2748] [Feature] A single Structured Logging JSON dictionary per Exception #7963

moltar opened this issue Jun 27, 2023 · 4 comments · Fixed by #8210
Assignees
Labels
enhancement New feature or request logging

Comments

@moltar
Copy link

moltar commented Jun 27, 2023

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

I am not 100% sure if this can be considered a bug. I am filing it as a bug, as the end user and a system admin.

It appears that the structured logging (as JSON) feature is splitting error messages coming from the database into separate entries.

Here's an example of one database error being represented by 6 separate JSON events:

image

Expected Behavior

One database error should be packed into a single JSON event.

Steps To Reproduce

  1. Use dbt-postgres
  2. Set env DBT_LOG_FORMAT=json
  3. Create a model that produces a database error (e.g. select 1/0)
  4. Do a dbt run
  5. Observe the log output

Relevant log output

image

Environment

- OS: Linux
- Python: 3.11
- dbt: 1.5.2

Which database adapter are you using with dbt?

postgres

Additional Context

N/A

@moltar moltar added bug Something isn't working triage labels Jun 27, 2023
@github-actions github-actions bot changed the title [Bug] Structured Logging (for JSON) is splitting message into multiple lines [CT-2748] [Bug] Structured Logging (for JSON) is splitting message into multiple lines Jun 27, 2023
@peterallenwebb
Copy link
Contributor

I agree that this is not a desirable behavior. It is an artifact of the initial move to structured logging, which took the approach of converting each log line to its own independent message. We have since abandoned that approach, but it lingers in this issue. We should adopt the behavior @moltar suggests.

@dbeatty10
Copy link
Contributor

Thank you for raising this @moltar! And thanks for the insight @peterallenwebb 🧠

Per @gshank, here is the relevant section of code:

elif result.message is not None:
first = True
for line in result.message.split("\n"):
# TODO: why do we format like this? Is there a reason this needs to
# be split instead of sending it as a single log line?
if first:
fire_event(FirstRunResultError(msg=line))
first = False
else:
fire_event(AfterFirstRunResultError(msg=line))

I'm going to re-categorize this as a feature in the meantime.

@dbeatty10 dbeatty10 added enhancement New feature or request and removed bug Something isn't working triage labels Jun 27, 2023
@dbeatty10 dbeatty10 changed the title [CT-2748] [Bug] Structured Logging (for JSON) is splitting message into multiple lines [CT-2748] [Feature] A single Structured Logging JSON dictionary per Exception Jun 27, 2023
@graciegoheen
Copy link
Contributor

Note: This is a fix to improve Cloud's ingestion of the structured logging

@peterallenwebb
Copy link
Contributor

Noting that the Experience team has raised concerns about our plan to back-port this, and would like time to work with an RC first. That shouldn't stop us from merging to main, however.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request logging
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants