[#3078] [CDK] Add support for enabling debug from command line and some basic general debug logs #14521

brianjlai · 2022-07-08T00:53:15Z

Addresses: #3078

What

Adds the ability for custom debug statements to be emitted to stdout (same as airbyte messages and logs) when running a connector locally using the --debug command. An example would look like:
python main.py read --config secrets/config_oauth.json --catalog sample_files/basic_read_oauth_catalog.json --debug | jq

There are some general debug statements added to the CDK that provide helpful context out of the box, but custom debug statements at the CDK or connector level can also be added. It also allows for custom fields to be passed via extra instead of just crammed into the string message:

logger.debug(
    f"general debug message here",
    extra={
        "a_field": path.to.field,
        "custom": self.something,
    },
)

It would then be presented as a debug in the output:

{
    "type": "DEBUG",
    "message": "general debug message here",
    "data": {
        "a_field": "a value",
        "custom": "Some attribute"
    }
}

How

We primarily leverage the existing debugger to handle filtering and formatting of logs according to the set log level. Using the --debug flag to determine whether the log level is set to INFO or DEBUG accordingly. There are a few little tricks that needed to be done to propagate the log level since streams and the source emit using different logger names.

There's also some custom formatting to make writing new logs a little nicer and make them easier to read in stdout.

🚨 User Impact 🚨

Are there any breaking changes? What is the end result perceived by the user? If yes, please merge this PR with the 🚨🚨 emoji so changelog authors can further highlight this if needed.

Pre-merge Checklist

Expand the relevant checklist and delete the others.

New Connector

Community member or Airbyter

Airbyter

If this is a community PR, the Airbyte engineer reviewing this PR is responsible for the below items.

Create a non-forked branch based on this PR and test the below items on it
Build is successful
If new credentials are required for use in CI, add them to GSM. Instructions.
/test connector=connectors/<name> command is passing
New Connector version released on Dockerhub by running the /publish command described here
After the connector is published, connector added to connector index as described here
Seed specs have been re-generated by building the platform and committing the changes to the seed spec files, as described here

Updating a connector

Community member or Airbyter

Grant edit access to maintainers (instructions)
Secrets in the connector's spec are annotated with airbyte_secret
Unit & integration tests added and passing. Community members, please provide proof of success locally e.g: screenshot or copy-paste unit, integration, and acceptance test output. To run acceptance tests for a Python connector, follow instructions in the README. For java connectors run ./gradlew :airbyte-integrations:connectors:<name>:integrationTest.
Code reviews completed
Documentation updated
- Connector's README.md
- Connector's bootstrap.md. See description and examples
- Changelog updated in docs/integrations/<source or destination>/<name>.md including changelog. See changelog example
PR name follows PR naming conventions

Airbyter

If this is a community PR, the Airbyte engineer reviewing this PR is responsible for the below items.

Create a non-forked branch based on this PR and test the below items on it
Build is successful
If new credentials are required for use in CI, add them to GSM. Instructions.
/test connector=connectors/<name> command is passing
New Connector version released on Dockerhub and connector version bumped by running the /publish command described here

Connector Generator

Issue acceptance criteria met
PR name follows PR naming conventions
If adding a new generator, add it to the list of scaffold modules being tested
The generator test modules (all connectors with -scaffold in their name) have been updated with the latest scaffold by running ./gradlew :airbyte-integrations:connector-templates:generator:testScaffoldTemplates then checking in your changes
Documentation which references the generator is updated as needed

Tests

Unit

Put your unit tests output here.

Integration

Put your integration tests output here.

Acceptance

Put your acceptance tests output here.

…arative

brianjlai · 2022-07-08T00:57:10Z

airbyte-cdk/python/airbyte_cdk/logger.py

+        if airbyte_level == "DEBUG":
+            extras = self.extract_extra_args_from_record(record)
+            debug_dict = {"type": "DEBUG", "message": record.getMessage(), "data": extras}
+            return filter_secrets(json.dumps(debug_dict))


An alternative is to create an entirely new AirbyteDebugMessage that supplies the same flexibility to log variables. I didn't really envision the --debug command ever being invoked at prod level, but if it is, its definitely worth investing in a new type of message into the protocol. Otherwise I'm not married to either. Updating json creation to use a new message type isn't too massive a change here

does this produce messages that are accepted by the platform? While we probably won't use --debug in production, I would imagine us using it on a dev machine or locally so we should make sure we can still run syncs with --debug

100% fine if the platform just ends up ignoring them

https://github.com/airbytehq/airbyte/blob/master/docs/10-understanding-airbyte/02-airbyte-protocol.md#airbytelogmessage

Based on this it should treat any non message JSON as a defacto log message, might lose some prettification on the platform, but also saves us from committing Debug messages to being a first class citizen in the protocol right at this moment.

brianjlai · 2022-07-08T16:42:10Z

airbyte-cdk/python/airbyte_cdk/entrypoint.py

@@ -67,6 +68,12 @@ def run(self, parsed_args: argparse.Namespace) -> Iterable[str]:
        if not cmd:
            raise Exception("No command passed")

+        if parsed_args.debug:
+            self.logger.setLevel(logging.DEBUG)


note: This does actually override the TRACE debug level, but going through the code, I don't see it used anywhere and it appears to be legacy code from the deprecated custom built AirbyteDebugger that was removed in favor of pythons default logger. Also occasionally introduces bugs:
https://airbytehq-team.slack.com/archives/C02TL38U5L7/p1649731849925669

Given the lack of usage, I'm partial yanking the entire TRACE message from the logger entirely

should we check the log level with self.logger.getEffectiveLevel() and fail if it's TRACE (and add a comment for future reference)

I think the issue is that by default we used to always set the logger to TRACE in logger.__init__ which has a value of 5. So it was inclusive of all logs higher than it. So at this moment, it will always be TRACE and it would fail.

Something I just thought of is changing the TRACE log to 15. And if --debug is not present, then set level to TRACE. That way debug is exclusive by default, but we still capture TRACE at all levels. A little hacky, but TRACE is already a hack haha

I'm like 99% confident we can just remove the TRACE level (as long as it's not backwards breaking) -- do you know if that's an easy removal?

Yep should be straightforward in the logger, it just the reference to the leveling and we'll use the remaining presets

girarda

a bit of nitpicking, but this is

girarda · 2022-07-08T18:15:03Z

airbyte-cdk/python/airbyte_cdk/entrypoint.py

@@ -67,6 +68,12 @@ def run(self, parsed_args: argparse.Namespace) -> Iterable[str]:
        if not cmd:
            raise Exception("No command passed")

+        if parsed_args.debug:
+            self.logger.setLevel(logging.DEBUG)


should we check the log level with self.logger.getEffectiveLevel() and fail if it's TRACE (and add a comment for future reference)

girarda · 2022-07-08T18:17:26Z

airbyte-cdk/python/airbyte_cdk/logger.py

+        if airbyte_level == "DEBUG":
+            extras = self.extract_extra_args_from_record(record)
+            debug_dict = {"type": "DEBUG", "message": record.getMessage(), "data": extras}
+            return filter_secrets(json.dumps(debug_dict))


does this produce messages that are accepted by the platform? While we probably won't use --debug in production, I would imagine us using it on a dev machine or locally so we should make sure we can still run syncs with --debug

100% fine if the platform just ends up ignoring them

girarda · 2022-07-08T18:21:40Z

airbyte-cdk/python/airbyte_cdk/sources/abstract_source.py

@@ -142,7 +150,7 @@ def _read_stream(
        connector_state: MutableMapping[str, Any],
        internal_config: InternalConfig,
    ) -> Iterator[AirbyteMessage]:
-
+        self._apply_log_level_to_stream_logger(logger, stream_instance)


should this be applied on line https://github.com/airbytehq/airbyte/pull/14521/files#diff-51c861828e0a614ef6ee21390f3ba17d7138549f0575051fdb24868ee05eabbbR106 just in case?

I think we should be in the clear because the logger passed into the read() method is always coming from entrypoint() which is the source level logger and is already set.

Although I'm gonna move the debug statement you mentioned down a level to the stream level since it makes more sense for it to be logged by the stream logger instead of source logger

girarda · 2022-07-08T18:24:42Z

airbyte-cdk/python/airbyte_cdk/sources/declarative/yaml_declarative_source.py

@@ -14,6 +14,7 @@ class YamlDeclarativeSource(DeclarativeSource):
    def __init__(self, path_to_yaml):
        self._factory = DeclarativeComponentFactory()
        self._source_config = self._read_and_parse_yaml_file(path_to_yaml)
+        self.logger = logging.getLogger(f"airbyte.{self.name or ''}")


what would cause self.name to be None?

Probably me just being overly cautious, will remove.

girarda · 2022-07-08T18:24:59Z

airbyte-cdk/python/airbyte_cdk/sources/declarative/yaml_declarative_source.py

+            parsed_config = YamlParser().parse(config_content)
+            self.logger.debug(
+                "parsed YAML into declarative source",
+                extra={"path_to_yaml_file": path_to_yaml_file, "source_name": self.name, "parsed_config": parsed_config},


sherifnada

This looks great! One requested addition: can you add a note in the docs which tells a developer they can use the --debug flag when developing their own connector or when contributing to the CDK itself?

sherifnada · 2022-07-12T01:15:32Z

airbyte-cdk/python/airbyte_cdk/entrypoint.py

@@ -67,6 +68,12 @@ def run(self, parsed_args: argparse.Namespace) -> Iterable[str]:
        if not cmd:
            raise Exception("No command passed")

+        if parsed_args.debug:
+            self.logger.setLevel(logging.DEBUG)


I'm like 99% confident we can just remove the TRACE level (as long as it's not backwards breaking) -- do you know if that's an easy removal?

sherifnada · 2022-07-12T01:17:49Z

airbyte-cdk/python/airbyte_cdk/sources/abstract_source.py

+        logger.debug(
+            f"Syncing stream: {configured_stream.stream.name}",
+            extra={
+                "stream_name": configured_stream.stream.name,


nit: extraneous since stream name is already in the above formatted string

Suggested change

"stream_name": configured_stream.stream.name,

sherifnada · 2022-07-12T01:20:21Z

airbyte-cdk/python/airbyte_cdk/sources/streams/http/http.py

@@ -286,8 +286,11 @@ def _send(self, request: requests.PreparedRequest, request_kwargs: Mapping[str,
        Unexpected transient exceptions use the default backoff parameters.
        Unexpected persistent exceptions are not handled and will cause the sync to fail.
        """
+        self.logger.debug(
+            "Making outbound API request", extra={"headers": request.headers, "url": request.url, "request_body": request.body}


url includes qparams right?

girarda

…ug configuration

sherifnada

allow for command line debug option and basic debug statements + decl…

147f34f

…arative

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

brianjlai commented Jul 8, 2022

View reviewed changes

Merge branch 'master' into brian/cdk_debug_command

23c1f17

brianjlai marked this pull request as ready for review July 8, 2022 17:06

brianjlai requested a review from a team as a code owner July 8, 2022 17:06

brianjlai requested review from girarda and sherifnada July 8, 2022 17:06

girarda reviewed Jul 8, 2022

View reviewed changes

brianjlai changed the title ~~[CDK] Add support for enabling debug from command line and some basic general debug logs~~ [3078= [CDK] Add support for enabling debug from command line and some basic general debug logs Jul 8, 2022

brianjlai changed the title ~~[3078= [CDK] Add support for enabling debug from command line and some basic general debug logs~~ [#3078] [CDK] Add support for enabling debug from command line and some basic general debug logs Jul 8, 2022

brianjlai added 3 commits July 8, 2022 14:10

feedback from pr comments

bbd8ccd

fix some tests w/ req/res mixed up and fixing logging tests

a6b438b

formatting

5324b90

sherifnada reviewed Jul 12, 2022

View reviewed changes

girarda approved these changes Jul 12, 2022

View reviewed changes

pr feedback: cleaning up traces in logger.py and update docs with deb…

ccf0e19

…ug configuration

github-actions bot added the area/documentation Improvements or additions to documentation label Jul 12, 2022

remove unneeded trace logger test

f7bddc4

sherifnada approved these changes Jul 13, 2022

View reviewed changes

remove extra print statement

fd3328e

brianjlai merged commit 7bff12a into master Jul 13, 2022

brianjlai deleted the brian/cdk_debug_command branch July 13, 2022 22:01

brianjlai mentioned this pull request Jul 13, 2022

forgot to publish a new version of airbyte-cdk to PyPi #14696

Merged

octavia-squidington-iii mentioned this pull request Jul 14, 2022

Bump Airbyte version from 0.39.36-alpha to 0.39.37-alpha #14719

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[#3078] [CDK] Add support for enabling debug from command line and some basic general debug logs #14521

[#3078] [CDK] Add support for enabling debug from command line and some basic general debug logs #14521

brianjlai commented Jul 8, 2022 •

edited

Loading

brianjlai Jul 8, 2022 •

edited

Loading

girarda Jul 8, 2022

brianjlai Jul 8, 2022 •

edited

Loading

brianjlai Jul 8, 2022 •

edited

Loading

girarda Jul 8, 2022

brianjlai Jul 8, 2022 •

edited

Loading

sherifnada Jul 12, 2022

brianjlai Jul 12, 2022

girarda left a comment

girarda Jul 8, 2022

girarda Jul 8, 2022

girarda Jul 8, 2022

brianjlai Jul 8, 2022

girarda Jul 8, 2022

brianjlai Jul 8, 2022

girarda Jul 8, 2022

sherifnada left a comment

sherifnada Jul 12, 2022

sherifnada Jul 12, 2022

sherifnada Jul 12, 2022

brianjlai Jul 12, 2022

girarda left a comment

sherifnada left a comment

[#3078] [CDK] Add support for enabling debug from command line and some basic general debug logs #14521

[#3078] [CDK] Add support for enabling debug from command line and some basic general debug logs #14521

Conversation

brianjlai commented Jul 8, 2022 • edited Loading

What

How

Recommended reading order

🚨 User Impact 🚨

Pre-merge Checklist

Community member or Airbyter

Airbyter

Community member or Airbyter

Airbyter

Tests

brianjlai Jul 8, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brianjlai Jul 8, 2022 • edited Loading

Choose a reason for hiding this comment

brianjlai Jul 8, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brianjlai Jul 8, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

girarda left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sherifnada left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

girarda left a comment

Choose a reason for hiding this comment

sherifnada left a comment

Choose a reason for hiding this comment

brianjlai commented Jul 8, 2022 •

edited

Loading

brianjlai Jul 8, 2022 •

edited

Loading

brianjlai Jul 8, 2022 •

edited

Loading

brianjlai Jul 8, 2022 •

edited

Loading

brianjlai Jul 8, 2022 •

edited

Loading