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-2259] Avoid serialization error of Undefined with JSON-formatted logs #7108

Closed
2 tasks
jtcohen6 opened this issue Mar 2, 2023 · 1 comment · Fixed by #7249
Closed
2 tasks

[CT-2259] Avoid serialization error of Undefined with JSON-formatted logs #7108

jtcohen6 opened this issue Mar 2, 2023 · 1 comment · Fixed by #7249
Assignees
Labels
bug Something isn't working logging

Comments

@jtcohen6
Copy link
Contributor

jtcohen6 commented Mar 2, 2023

Motivation: Commands should succeed or error consistently, regardless of the --log-format being used. This is a prerequisite for changing how dbt-core is deployed in dbt Cloud.

Let's say I, as a user, try to log a variable that I have not defined:

-- models/my_model.sql

{{ log("I am here", info=True) }}

{{ log(unknown_variable_name_here, info=True) }}

{{ log("I am now here", info=True) }}

select 1 as id

Rather than raising an exception, dbt renders unknown_variable_name_here to the Jinja type Undefined. This is fine on all versions with text-formatting logging. Unfortunately, on older versions, when run with JSON-formatted logging, it yields this error:

{
  "code": "Z028",
  "data": {
    "msg": "Object of type Undefined is not JSON serializable"
  },
  "invocation_id": "99db7ab4-cc63-4a0e-bb1f-30741bed654c",
  "level": "error",
  "log_version": 2,
  "msg": "\u001b[33mObject of type Undefined is not JSON serializable\u001b[0m",
  "pid": 41046,
  "thread_name": "MainThread",
  "ts": "2023-03-02T20:55:45.427322Z",
  "type": "log_line"
}

The good news is, this is handled gracefully in v1.4+, thanks to changes we made to log serialization:

{
  "data": {
    "msg": "",
    "node_info": {
      "materialized": "view",
      "meta": {},
      "node_finished_at": null,
      "node_name": "my_failing_model",
      "node_path": "my_failing_model.sql",
      "node_started_at": "2023-03-02T20:56:46.648597",
      "node_status": "compiling",
      "resource_type": "model",
      "unique_id": "model.test.my_failing_model"
    }
  },
  "info": {
    "category": "",
    "code": "M011",
    "extra": {},
    "invocation_id": "a2e17f17-5036-4b0a-848f-80fe2c1283dd",
    "level": "info",
    "msg": "",
    "name": "JinjaLogInfo",
    "pid": 41211,
    "thread": "Thread-1",
    "ts": "2023-03-02T20:56:46.653561Z"
  }
}

So we just need a fix for older versions under critical support (v1.1, v1.2, v1.3).

Proposed fix

It's a bit ugly, but it's also very very narrow in scope. Let's update the log context method to handle if the user has passed in an object that renders to type Undefined, and replace it with an empty string:

        import jinja2
        if isinstance(msg, jinja2.Undefined):
            msg = ""
        if info:
            fire_event(MacroEventInfo(msg=str(msg)))
        else:
            fire_event(MacroEventDebug(msg=str(msg)))
        return ""

The effect is identical for text-formatted logs, and avoids serialization errors for JSON-formatted logs.

(In general, we should really stringify whatever the user has passed us - this would also solve for #6568)

Acceptance criteria

  • Avoid serialization error for Undefined object being passed into {{ log() }} on v1.1, v1.2, v1.3
  • Add a test for this behavior, on affected versions and going forward
@jtcohen6 jtcohen6 added bug Something isn't working Team:Language logging labels Mar 2, 2023
@github-actions github-actions bot changed the title Avoid serialization error of Undefined with JSON-formatted logs [CT-2259] Avoid serialization error of Undefined with JSON-formatted logs Mar 2, 2023
@jtcohen6 jtcohen6 self-assigned this Mar 3, 2023
@gshank
Copy link
Contributor

gshank commented Mar 6, 2023

There is also an issue with errors being thrown by user invocation of the "tojson" method, so we should probably do a similar thing of catching all errors and issuing a warning.

@jtcohen6 jtcohen6 removed their assignment Mar 13, 2023
QMalcolm added a commit that referenced this issue Mar 31, 2023
[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3
QMalcolm added a commit that referenced this issue Apr 6, 2023
…ing (#7249)

* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Add tests ensuring failed event serialization is handled correctly

[CT-2264](#7113) states
that failed serialization should result in an exception handling path
which will fire another event instead of raising an exception. This is
hard to test perfectly because the exception handling path for
serialization depending on whether pytest is present. If pytest isn't
present, a new event documentation the failed serialization is fired.
If pytest is present, the failed serialization gets raised as an exception.
Thus this added test ensures that the expected exception is raised and
assumes that the correct event will be fired normally.

* Log warning when event serialization fails in `msg_to_dict`

This commit updates the `msg_to_dict` exception handling path to
fire a warning level event instead of raising an exception.
Truthfully, we're not sure if this exception handling path is even
possible to hit. That's because we recently switched from betterproto
to google's protobuf. However, exception path is the subject of
[CT-2264](#7113). Though we
don't think it's actually possible to hit it anymore, we still want
to handle the case if it is.

* Update serialization failure note to be a warn level event in `BaseEvent`

[CT-2264](#7113) wants
logging messages about event serialization failure to be `WARNING`
level events. This does that.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`
emmyoop pushed a commit that referenced this issue Apr 10, 2023
…ing (#7249)

* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Add tests ensuring failed event serialization is handled correctly

[CT-2264](#7113) states
that failed serialization should result in an exception handling path
which will fire another event instead of raising an exception. This is
hard to test perfectly because the exception handling path for
serialization depending on whether pytest is present. If pytest isn't
present, a new event documentation the failed serialization is fired.
If pytest is present, the failed serialization gets raised as an exception.
Thus this added test ensures that the expected exception is raised and
assumes that the correct event will be fired normally.

* Log warning when event serialization fails in `msg_to_dict`

This commit updates the `msg_to_dict` exception handling path to
fire a warning level event instead of raising an exception.
Truthfully, we're not sure if this exception handling path is even
possible to hit. That's because we recently switched from betterproto
to google's protobuf. However, exception path is the subject of
[CT-2264](#7113). Though we
don't think it's actually possible to hit it anymore, we still want
to handle the case if it is.

* Update serialization failure note to be a warn level event in `BaseEvent`

[CT-2264](#7113) wants
logging messages about event serialization failure to be `WARNING`
level events. This does that.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`
emmyoop pushed a commit that referenced this issue Apr 11, 2023
…ing (#7249)

* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Add tests ensuring failed event serialization is handled correctly

[CT-2264](#7113) states
that failed serialization should result in an exception handling path
which will fire another event instead of raising an exception. This is
hard to test perfectly because the exception handling path for
serialization depending on whether pytest is present. If pytest isn't
present, a new event documentation the failed serialization is fired.
If pytest is present, the failed serialization gets raised as an exception.
Thus this added test ensures that the expected exception is raised and
assumes that the correct event will be fired normally.

* Log warning when event serialization fails in `msg_to_dict`

This commit updates the `msg_to_dict` exception handling path to
fire a warning level event instead of raising an exception.
Truthfully, we're not sure if this exception handling path is even
possible to hit. That's because we recently switched from betterproto
to google's protobuf. However, exception path is the subject of
[CT-2264](#7113). Though we
don't think it's actually possible to hit it anymore, we still want
to handle the case if it is.

* Update serialization failure note to be a warn level event in `BaseEvent`

[CT-2264](#7113) wants
logging messages about event serialization failure to be `WARNING`
level events. This does that.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`
QMalcolm added a commit that referenced this issue Apr 11, 2023
…ing (#7249)

* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Log warning when event serialization fails in `msg_to_dict`

This commit updates the `msg_to_dict` exception handling path to
fire a warning level event instead of raising an exception.
Truthfully, we're not sure if this exception handling path is even
possible to hit. That's because we recently switched from betterproto
to google's protobuf. However, exception path is the subject of
[CT-2264](#7113). Though we
don't think it's actually possible to hit it anymore, we still want
to handle the case if it is.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`
QMalcolm added a commit that referenced this issue Apr 12, 2023
[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3
QMalcolm added a commit that referenced this issue Apr 12, 2023
[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3
QMalcolm added a commit that referenced this issue Apr 12, 2023
The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.
QMalcolm added a commit that referenced this issue Apr 12, 2023
[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3
QMalcolm added a commit that referenced this issue Apr 12, 2023
The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.
QMalcolm added a commit that referenced this issue Apr 12, 2023
[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3
QMalcolm added a commit that referenced this issue Apr 12, 2023
The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.
QMalcolm added a commit that referenced this issue Apr 12, 2023
[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3
QMalcolm added a commit that referenced this issue Apr 12, 2023
The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.
QMalcolm added a commit that referenced this issue Apr 18, 2023
* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Log warning when event serialization fails in `msg_to_dict`

This commit updates the `msg_to_dict` exception handling path to
fire a warning level event instead of raising an exception.

* Add changie info for changes

* Add test to check exception handling of `msg_to_dict`

* Ensure all events with self.msg stringify self.msg

---------

Co-authored-by: leahwicz <60146280+leahwicz@users.noreply.github.com>
QMalcolm added a commit that referenced this issue Apr 18, 2023
* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Add changie info for changes

* Ensure `log()` calls from jinja ensure the msg is stringified

The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.

---------

Co-authored-by: leahwicz <60146280+leahwicz@users.noreply.github.com>
QMalcolm added a commit that referenced this issue Apr 18, 2023
* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Add changie info for changes

* Ensure `log()` calls from jinja ensure the msg is stringified

The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.

---------

Co-authored-by: leahwicz <60146280+leahwicz@users.noreply.github.com>
QMalcolm added a commit that referenced this issue Apr 18, 2023
* Add tests for logging jinja2.Undefined objects

[CT-2259](#7108) identifies
an issue wherein dbt-core 1.0-1.3 raise errors if a jinja2.Undefined
object is attempted to be logged. This generally happened in the form
of `{{ log(undefined_variable, info=True) }}`. This commit adding this
test exists for two reasons
1. Ensure we don't have a regression in this going forward
2. Exist as a commit to be used for backport fixes for dbt-core 1.0-1.3

* Add tests for checking `DBT_ENV_SECRET_`s don't break logging

[CT-1783](#6568) describes
a bug in dbt-core 1.0-1.3 wherein when a `DBT_ENV_SECRET_` all
`{{ log("logging stuff", info=True) }}` invocations break. This commit
adds a test for this for two reasons:
1. Ensure we don't regress to this behavior going forward
2. Act as a base commit for making the backport fixes to dbt-core 1.0-1.3

* Add changie info for changes

* Ensure `log()` calls from jinja ensure the msg is stringified

The simplest way to resolve [CT-2259](#7108)
and [CT-1783](#6568) in backports
to dbt-core < 1.4 is to ensure `msg` in `BaseContext.log()` is stringified.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working logging
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants