`AirbyteLogMessage.stack_trace` for logging messages with related (non-fatal) errors #16479

evantahler · 2022-09-08T19:52:16Z

This PR is inspired by the conversation in #15668 (comment). Please read this thread first. The goal of this PR is to allow connectors to pass non-fatal stack traces along with an AirbyteLogMessage to be logged by the worker. This is helpful when the connector catches an exception and handles it, e.g. log("caught HTTP exception, trying again in 10 seconds", exception);. The message and exception will be logged together for debugging.

For example:

{
  TYPE: "LOG", 
  log: {
    level: "INFO", 
    message: "The connector had a problem, but we are retrying in 10 seconds...",
    stack_trace: "OH NO on line 1\r\n\tBECAUSE OF foo on line 2"
}}

Will be rendered in the logs like:

2022-09-08 20:38:54 source > The connector had a problem, but we are retrying in 10 seconds...
Stack Trace: OH NO on line 1
	BECAUSE OF foo on line 2

This PR replaces #16317.

Rationale

We are ok with adding this one additional property to AirbyteLogMessage because this one additional named property's use-case is very clear and unlikely to be misinterpreted.
We shouldn’t add wildcard objects to the protocol (e.g. AirbyeteLogMessage.data) because people will do silly with things that we can’t guarantee - e.g. data.foo could be used for triggering other operations which we can’t promise will work in the future.
Loggers in general seem to understand stack_trace as a first class object. This elevates this concept above a wildcard .data object
Google says "stack trace" is 2 words, and that’s what we already use for AirbyteErrorTraceMessage so we will use the underscore
This allows AirbyteNotificaitonTraceMessage to remain reserved for notifying UI consumers of connector behavior.

Notes

As this is a change to the Airbyte Protocol, do not merge this PR until the Protocol Change Process has been completed.

To test this PR, source-faker has also been modified to emit additional LOG messages.

We use stack_trace (underscore) in the protocol.

evantahler · 2022-09-08T20:58:24Z

/test connector=connectors/source-faker

🕑 connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3018237976
✅ connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3018237976
Python tests coverage:

Name                       Stmts   Miss  Cover
----------------------------------------------
source_faker/__init__.py       2      0   100%
source_faker/source.py       130      2    98%
----------------------------------------------
TOTAL                        132      2    98%
	 Name                                                 Stmts   Miss  Cover   Missing
	 ----------------------------------------------------------------------------------
	 source_acceptance_test/base.py                          10      4    60%   15-18
	 source_acceptance_test/config.py                        83      6    93%   78-80, 84-86
	 source_acceptance_test/conftest.py                     164    164     0%   6-282
	 source_acceptance_test/plugin.py                        48     48     0%   6-104
	 source_acceptance_test/tests/test_core.py              329    111    66%   39, 50-58, 63-70, 74-75, 79-80, 164, 202-219, 228-236, 240-245, 251, 284-289, 327-334, 374-376, 379, 439-448, 477-478, 484, 487, 520-530, 543-568, 573-577
	 source_acceptance_test/tests/test_full_refresh.py       52      2    96%   34, 65
	 source_acceptance_test/tests/test_incremental.py       121     25    79%   21-23, 29-31, 36-43, 48-61, 208-216
	 source_acceptance_test/utils/asserts.py                 37      2    95%   57-58
	 source_acceptance_test/utils/common.py                  77     17    78%   15-16, 24-30, 47-54, 64, 67
	 source_acceptance_test/utils/compare.py                 62     23    63%   21-51, 68, 97-99
	 source_acceptance_test/utils/connector_runner.py       110     48    56%   23-26, 32, 36, 39-64, 67-69, 72-74, 77-79, 82-84, 87-89, 92-110, 144-146
	 source_acceptance_test/utils/json_schema_helper.py     105     13    88%   30-31, 38, 41, 65-68, 96, 120, 190-192
	 ----------------------------------------------------------------------------------
	 TOTAL                                                 1322    463    65%

Build Passed

Test summary info:

=========================== short test summary info ============================
SKIPPED [1] ../usr/local/lib/python3.9/site-packages/source_acceptance_test/plugin.py:60: Skipping TestIncremental.test_two_sequential_reads because not found in the config
======================== 26 passed, 1 skipped in 25.77s ========================

evantahler · 2022-09-08T20:59:56Z

Here's what it looks like in the UI:

sherifnada

My understanding from our IRL convo @evantahler was we wanted to a way to do structured logging, and that adding a generic data field would allow us to do that. Why has this goal changed? It seemed like a worthwhile target. It seems the main reason was to prevent consumers from making assumptions about the structure of the logs, but I guess I don't see why that is any more true than it is today? (people can make assumptions about the content of the message field)

I thought the previous direction made sense, so I'm just trying to better understand the change

evantahler · 2022-09-08T22:52:47Z

@sherifnada yeah, this is a reversal. We ended up deciding that the right path forward was to be a strictly typed as possible with the protocol in order to discourage un-expected use cases. A single "stack_trace" property we can guarantee, and because it's a known term, expect people will use it only for this purpose. The "data" blob appeared to be to enticing for others to put structured data into it what would be used downstream (e.g. parse the logs for {next_step:go} and use that to power dagster or something similar).

edgao

nice

no comments about the protocol change itself, looks like it aligns with the slack discussions over the last few days. Minor comment about the implementation but I wouldn't block on it.

airbyte-workers/src/main/java/io/airbyte/workers/internal/DefaultAirbyteStreamFactory.java

sherifnada

The rationale seems fair enough

Is there a protocol change log that needs to be updated or something?

evantahler · 2022-09-09T20:49:25Z

Is there a protocol change log that needs to be updated or something?

There isn't! I'll add one in a separate PR. There might be some conversation about the version numbers.

Edit: That PR is here - #16560

jdpgrailsdev

evantahler · 2022-09-09T22:53:21Z

/publish connector=connectors/source-faker

🕑 Publishing the following connectors:
connectors/source-faker
https://github.com/airbytehq/airbyte/actions/runs/3025790475

Connector	Did it publish?	Were definitions generated?
connectors/source-faker	❌	❌

if you have connectors that successfully published but failed definition generation, follow step 4 here ▶️

pedroslopez · 2022-09-09T23:16:46Z

/test connector=connectors/source-faker

🕑 connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3025874097
❌ connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3025874097
🐛 https://gradle.com/s/x4ihuuje3mnqy

Build Failed

Test summary info:

=========================== short test summary info ============================
FAILED test_core.py::TestBasicRead::test_read[inputs0] - docker.errors.Contai...
FAILED test_full_refresh.py::TestFullRefresh::test_sequential_reads[inputs0]
SKIPPED [1] ../usr/local/lib/python3.9/site-packages/source_acceptance_test/plugin.py:60: Skipping TestIncremental.test_two_sequential_reads because not found in the config
=================== 2 failed, 24 passed, 1 skipped in 24.40s ===================

evantahler · 2022-09-10T01:10:50Z

/test connector=connectors/source-faker

🕑 connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3026231967
❌ connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3026231967
🐛 https://gradle.com/s/3wujjd2zs7toc

Build Failed

Test summary info:

=========================== short test summary info ============================
FAILED test_core.py::TestBasicRead::test_read[inputs0] - docker.errors.Contai...
FAILED test_full_refresh.py::TestFullRefresh::test_sequential_reads[inputs0]
SKIPPED [1] ../usr/local/lib/python3.9/site-packages/source_acceptance_test/plugin.py:60: Skipping TestIncremental.test_two_sequential_reads because not found in the config
=================== 2 failed, 24 passed, 1 skipped in 23.89s ===================

evantahler · 2022-09-12T21:59:22Z

/test connector=connectors/source-faker

🕑 connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3040851106
✅ connectors/source-faker https://github.com/airbytehq/airbyte/actions/runs/3040851106
Python tests coverage:

Name                       Stmts   Miss  Cover
----------------------------------------------
source_faker/__init__.py       2      0   100%
source_faker/source.py       130      2    98%
----------------------------------------------
TOTAL                        132      2    98%
	 Name                                                 Stmts   Miss  Cover   Missing
	 ----------------------------------------------------------------------------------
	 source_acceptance_test/base.py                          10      4    60%   15-18
	 source_acceptance_test/config.py                        83      6    93%   78-80, 84-86
	 source_acceptance_test/conftest.py                     164    164     0%   6-282
	 source_acceptance_test/plugin.py                        48     48     0%   6-104
	 source_acceptance_test/tests/test_core.py              329    111    66%   39, 50-58, 63-70, 74-75, 79-80, 164, 202-219, 228-236, 240-245, 251, 284-289, 327-334, 374-376, 379, 439-448, 477-478, 484, 487, 520-530, 543-568, 573-577
	 source_acceptance_test/tests/test_full_refresh.py       52      2    96%   34, 65
	 source_acceptance_test/tests/test_incremental.py       121     25    79%   21-23, 29-31, 36-43, 48-61, 208-216
	 source_acceptance_test/utils/asserts.py                 37      2    95%   57-58
	 source_acceptance_test/utils/common.py                  77     17    78%   15-16, 24-30, 47-54, 64, 67
	 source_acceptance_test/utils/compare.py                 62     23    63%   21-51, 68, 97-99
	 source_acceptance_test/utils/connector_runner.py       110     48    56%   23-26, 32, 36, 39-64, 67-69, 72-74, 77-79, 82-84, 87-89, 92-110, 144-146
	 source_acceptance_test/utils/json_schema_helper.py     105     13    88%   30-31, 38, 41, 65-68, 96, 120, 190-192
	 ----------------------------------------------------------------------------------
	 TOTAL                                                 1325    463    65%

Build Passed

Test summary info:

=========================== short test summary info ============================
SKIPPED [1] ../usr/local/lib/python3.9/site-packages/source_acceptance_test/plugin.py:60: Skipping TestIncremental.test_two_sequential_reads because not found in the config
======================== 26 passed, 1 skipped in 25.80s ========================

evantahler · 2022-09-12T22:32:35Z

/publish connector=connectors/source-faker

🕑 Publishing the following connectors:
connectors/source-faker
https://github.com/airbytehq/airbyte/actions/runs/3041012392

Connector	Did it publish?	Were definitions generated?
connectors/source-faker	✅	✅

if you have connectors that successfully published but failed definition generation, follow step 4 here ▶️

…n-fatal) errors (airbytehq#16479) * Test log message from faker * AirbyteLogMessage gains stack_trace * Fixup spacing * bump python protocol * fixup additionalProperties in faker spec * bump faker version * update docs * use lineSeparator vs \r\n * auto-bump connector version [ci skip] Co-authored-by: Octavia Squidington III <octavia-squidington-iii@users.noreply.github.com>

evantahler added 2 commits September 8, 2022 12:47

Test log message from faker

d46f218

AirbyteLogMessage gains stack_trace

d5eab3c

github-actions bot added area/connectors Connector related issues area/documentation Improvements or additions to documentation area/platform issues related to the platform area/protocol area/worker Related to worker labels Sep 8, 2022

octavia-squidington-iii added the connectors/source/faker label Sep 8, 2022

Merge branch 'master' into evan/AirbyteLogMessage-with-stacktrace

50ec77f

evantahler temporarily deployed to more-secrets September 8, 2022 19:55 Inactive

evantahler mentioned this pull request Sep 8, 2022

Use LOG4J2 to wrap connectors logs to JSON format #15668

Merged

37 tasks

evantahler added 2 commits September 8, 2022 13:40

Fixup spacing

d1a01e8

bump python protocol

8869810

github-actions bot added the CDK Connector Development Kit label Sep 8, 2022

evantahler temporarily deployed to more-secrets September 8, 2022 20:50 Inactive

fixup additionalProperties in faker spec

43a81b1

evantahler requested review from cgardens, edgao and grishick September 8, 2022 20:58

evantahler temporarily deployed to more-secrets September 8, 2022 21:00 Inactive

evantahler marked this pull request as ready for review September 8, 2022 21:00

evantahler requested review from a team as code owners September 8, 2022 21:00

bump faker version

a01aaff

evantahler temporarily deployed to more-secrets September 8, 2022 21:26 Inactive

update docs

fad2fa9

evantahler temporarily deployed to more-secrets September 8, 2022 21:46 Inactive

sherifnada reviewed Sep 8, 2022

View reviewed changes

edgao approved these changes Sep 9, 2022

View reviewed changes

airbyte-workers/src/main/java/io/airbyte/workers/internal/DefaultAirbyteStreamFactory.java Outdated Show resolved Hide resolved

use lineSeparator vs \r\n

3805018

evantahler temporarily deployed to more-secrets September 9, 2022 16:05 Inactive

sherifnada approved these changes Sep 9, 2022

View reviewed changes

evantahler mentioned this pull request Sep 9, 2022

Add changelog for Airbyte Protocol #16560

Merged

jdpgrailsdev approved these changes Sep 9, 2022

View reviewed changes

evantahler temporarily deployed to more-secrets September 9, 2022 22:55 Inactive

Merge branch 'master' into evan/AirbyteLogMessage-with-stacktrace

096ebb2

evantahler temporarily deployed to more-secrets September 10, 2022 01:12 Inactive

Merge branch 'master' into evan/AirbyteLogMessage-with-stacktrace

0e01993

evantahler temporarily deployed to more-secrets September 12, 2022 22:00 Inactive

auto-bump connector version [ci skip]

c926ae8

evantahler merged commit dcfcb75 into master Sep 12, 2022

evantahler deleted the evan/AirbyteLogMessage-with-stacktrace branch September 12, 2022 23:01

octavia-squidington-iii mentioned this pull request Sep 13, 2022

Bump Airbyte version from 0.40.5 to 0.40.6 #16656

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`AirbyteLogMessage.stack_trace` for logging messages with related (non-fatal) errors #16479

`AirbyteLogMessage.stack_trace` for logging messages with related (non-fatal) errors #16479

evantahler commented Sep 8, 2022 •

edited

Loading

evantahler commented Sep 8, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 8, 2022 •

edited

Loading

sherifnada left a comment

evantahler commented Sep 8, 2022

edgao left a comment

sherifnada left a comment

evantahler commented Sep 9, 2022 •

edited

Loading

jdpgrailsdev left a comment

evantahler commented Sep 9, 2022 •

edited by github-actions bot

Loading

pedroslopez commented Sep 9, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 10, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 12, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 12, 2022 •

edited by github-actions bot

Loading

AirbyteLogMessage.stack_trace for logging messages with related (non-fatal) errors #16479

AirbyteLogMessage.stack_trace for logging messages with related (non-fatal) errors #16479

Conversation

evantahler commented Sep 8, 2022 • edited Loading

Rationale

Notes

evantahler commented Sep 8, 2022 • edited by github-actions bot Loading

Build Passed

evantahler commented Sep 8, 2022 • edited Loading

sherifnada left a comment

Choose a reason for hiding this comment

evantahler commented Sep 8, 2022

edgao left a comment

Choose a reason for hiding this comment

sherifnada left a comment

Choose a reason for hiding this comment

evantahler commented Sep 9, 2022 • edited Loading

jdpgrailsdev left a comment

Choose a reason for hiding this comment

evantahler commented Sep 9, 2022 • edited by github-actions bot Loading

pedroslopez commented Sep 9, 2022 • edited by github-actions bot Loading

Build Failed

evantahler commented Sep 10, 2022 • edited by github-actions bot Loading

Build Failed

evantahler commented Sep 12, 2022 • edited by github-actions bot Loading

Build Passed

evantahler commented Sep 12, 2022 • edited by github-actions bot Loading

`AirbyteLogMessage.stack_trace` for logging messages with related (non-fatal) errors #16479

`AirbyteLogMessage.stack_trace` for logging messages with related (non-fatal) errors #16479

evantahler commented Sep 8, 2022 •

edited

Loading

evantahler commented Sep 8, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 8, 2022 •

edited

Loading

evantahler commented Sep 9, 2022 •

edited

Loading

evantahler commented Sep 9, 2022 •

edited by github-actions bot

Loading

pedroslopez commented Sep 9, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 10, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 12, 2022 •

edited by github-actions bot

Loading

evantahler commented Sep 12, 2022 •

edited by github-actions bot

Loading