[SNOW-594195] Add correlationId to logging #487

sfc-gh-rcheng · 2022-09-14T22:08:22Z

Problem: multiple instances of kafka connect log to same spot causing confusion during debugging. Issue came up during a the Fidelity issue linked in the jira.

Changes:

LoggingHandler

is a layer between Kafka Connect and the logging framework
has a static correlationId that is updated on start()
logs when a new logger is returned

Logging.java -> EnableLogging.java

retains the original idea of Logging.java as an abstract class other classes can extend for easy logging methods

Logging.logMessage() -> Utils.formatLogMessage()

increases logging consistency: moved the format log message into LoggingHandler so consumers don't need to format the message themselves
name change: since logMessage doesn't log the message
moved to Utils.java since there are instances we use it to format strings for not just logging purposes

sfc-gh-rcheng · 2022-09-14T22:09:24Z

apologies, this really should have been multiple prs. I've highlighted the important parts

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkConnector.java

src/main/java/com/snowflake/kafka/connector/Utils.java

src/main/java/com/snowflake/kafka/connector/internal/EnableLogging.java

codecov-commenter · 2022-09-14T23:00:18Z

Codecov Report

Merging #487 (afefb11) into master (164632b) will increase coverage by 0.12%.
The diff coverage is 86.42%.

❗ Current head afefb11 differs from pull request most recent head e714da2. Consider uploading reports for the commit e714da2 to get more accurate results

@@            Coverage Diff             @@
##           master     #487      +/-   ##
==========================================
+ Coverage   87.07%   87.19%   +0.12%     
==========================================
  Files          46       47       +1     
  Lines        3946     3953       +7     
  Branches      416      419       +3     
==========================================
+ Hits         3436     3447      +11     
+ Misses        350      344       -6     
- Partials      160      162       +2

Impacted Files	Coverage Δ
...tor/internal/SnowflakeIngestionServiceFactory.java	`87.50% <ø> (ø)`
...al/telemetry/SnowflakeTelemetryServiceFactory.java	`90.00% <ø> (ø)`
...nternal/telemetry/SnowflakeTelemetryServiceV1.java	`92.39% <40.00%> (-1.02%)`	⬇️
...fka/connector/internal/SnowflakeInternalStage.java	`73.75% <50.00%> (ø)`
...tor/internal/streaming/SnowflakeSinkServiceV2.java	`74.85% <50.00%> (+0.58%)`	⬆️
...afka/connector/records/SnowflakeAvroConverter.java	`90.00% <66.66%> (-0.15%)`	⬇️
...nnector/internal/SnowflakeConnectionServiceV1.java	`80.47% <80.00%> (ø)`
...connector/internal/metrics/MetricsJmxReporter.java	`90.32% <80.00%> (-0.31%)`	⬇️
...wflake/kafka/connector/internal/EnableLogging.java	`81.81% <81.81%> (ø)`
...wflake/kafka/connector/internal/LoggerHandler.java	`81.81% <81.81%> (ø)`
... and 21 more

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

sfc-gh-rcheng · 2022-09-16T01:22:37Z

Confirmed that loggers created without a correlationId eventually log messages with a correlationId.

The static Utils logger was created without correlationId
[2022-09-16 01:15:26,500] INFO [SF_KAFKA_CONNECTOR] Created loggerHandler for class: 'com.snowflake.kafka.connector.Utils' without a correlationId. (com.snowflake.kafka.connector.internal.LoggerHandler)
Kafka connector starts with a correlationId
[2022-09-16 01:15:53,216] INFO [SF_KAFKA_CONNECTOR] [0f9b9a0e-34a9-4c16-92ae-ee3f3bd99d89]SnowflakeSinkConnector:start (com.snowflake.kafka.connector.SnowflakeSinkConnector)
All logs emitted from Utils after start have the correlationId
[2022-09-16 01:15:53,623] DEBUG [SF_KAFKA_CONNECTOR] [0f9b9a0e-34a9-4c16-92ae-ee3f3bd99d89]generated stage name: SNOWFLAKE_KAFKA_CONNECTOR_SnowflakeSinkConnector_revi_STAGE_SnowflakeSink_revi (com.snowflake.kafka.connector.Utils)

sfc-gh-tzhang

I'm not sure only adding the id at instance level would be sufficient, but this is a good start! We could add more things over time.

docker-setup/snowflake-kafka-docker/kafka-connect.yml

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkConnector.java

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkConnectorConfig.java

src/main/java/com/snowflake/kafka/connector/internal/EnableLogging.java

src/main/java/com/snowflake/kafka/connector/internal/LoggerHandler.java

sfc-gh-tzhang · 2022-09-16T17:33:50Z

Please also add a PR description about what we're trying to do here

src/test/java/com/snowflake/kafka/connector/internal/LoggerHandlerTest.java

sfc-gh-tzhang

LGTM, thanks! Regarding the testing, it would be good to use Mockito or Powermock, but I'm fine with some simple test cases.

src/test/java/com/snowflake/kafka/connector/internal/LoggerHandlerTest.java

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkTask.java

src/main/java/com/snowflake/kafka/connector/internal/EnableLogging.java

src/main/java/com/snowflake/kafka/connector/internal/LoggerHandler.java

sfc-gh-japatel · 2022-09-20T07:03:14Z

Confirmed that loggers created without a correlationId eventually log messages with a correlationId.

The static Utils logger was created without correlationId
[2022-09-16 01:15:26,500] INFO [SF_KAFKA_CONNECTOR] Created loggerHandler for class: 'com.snowflake.kafka.connector.Utils' without a correlationId. (com.snowflake.kafka.connector.internal.LoggerHandler)

Kafka connector starts with a correlationId
[2022-09-16 01:15:53,216] INFO [SF_KAFKA_CONNECTOR] [0f9b9a0e-34a9-4c16-92ae-ee3f3bd99d89]SnowflakeSinkConnector:start (com.snowflake.kafka.connector.SnowflakeSinkConnector)

All logs emitted from Utils after start have the correlationId
[2022-09-16 01:15:53,623] DEBUG [SF_KAFKA_CONNECTOR] [0f9b9a0e-34a9-4c16-92ae-ee3f3bd99d89]generated stage name: SNOWFLAKE_KAFKA_CONNECTOR_SnowflakeSinkConnector_revi_STAGE_SnowflakeSink_revi (com.snowflake.kafka.connector.Utils)

Should there be an extra space [corr_id] here instead of [corr_id]here ?

src/main/java/com/snowflake/kafka/connector/internal/LoggerHandler.java

sfc-gh-japatel

overall looks great. Thanks Revi! Will wait for your comments. [No major concerns]

sfc-gh-japatel · 2022-09-20T07:07:38Z

Can we somehow also get this correlation id in our telemetry so that we can check uuid in snowhouse? Dont need to do this in this PR but lets track it.
I just looked at the code, we dont send telemetry when we do encounter open() and close(). Would be good to send some data too, and there we can add correlation id

sfc-gh-japatel

lgtm, thanks for adding tests! Looks complete.
Lets make sure the gfmt passes before you merge.

* Add docker setup resources to the kafka connect repo (#483) * initial docker setup info * blank connectors and rename container folder * ignore connector example json files * more .gitignore setup maybe? * example files * template folder * clean up misc * remove volume bind, allow install sfkc 1.8.1 * yml changes * remove empty lines * Fix docker-setup yml files (#490) * docker wont pull from /usr/ * git ignore test * readme * test gitignore * remove yml files from gitignore * test force add * i think gitignore works now * need to add it back in for changes lol * add back jmx * SNOW-625820: multiple fixes for KC schematization schema mapping (#488) - Update the config key word from enable.schematization to snowflake.enable.schematization - Remove some duplicate constants - Fix a null pointer exception during channel closing - Update the column name format function to return the quoted column name * [SNOW-594195] Add correlationId to logging (#487) * smh static doesnt work * logginghandler with static cid, logging -> enablelogging * test gitignore * passes tests * corrid at beginning * remove yml files from git cache * add yml, copyright; change logger class name * ran formatter * remove wildcard imports * added logging handler tests * review changes * formatter * NO-SNOW: Put rows with JsonProcessingException into the DLQ instead of ignoring them (#491) Put rows with JsonProcessingException into the DLQ instead of ignoring them * [SNOW-643653] Fix Citi Blackduck vulnerabilities (#497) * avro 1.8.1 -> 1.11.0, kakfa-clients -> 2.8.2 * vulnerabilities fixed? * fixed all vuln * [SNOW-665920] Add warnings in build script to prevent a privately built jar from going to the customer (#492) * do as i say not as i do * change warn and mkdir docker jar folder * [SNOW-665898] Add log granularity instance id logging for Task (#495) * refactor to kcglobalinstanceid * parse instance id * ut pass - til final doesnt let injectmocks * tests pass, need cc * cc 100 * added logging to task * spacing issue in logs * formatter * formatter and rerun failed tests? * set task instance id in start * utils string format * task functionality * can someone say overengineer oops * no one likes overenegineering * 100 cc * added int test, maybe need to merge other branch? * remove fallbackid.. weird and not needed for task * working on int test * added it * stash * it done * formatter * formatter again * remove start count and fix it * format * add open count and some pr nits * formatting is a pain * change starttime and import * use uuid+time for instanceid * Modify Codeowners (#494) * SNOW-630885: Support schema evolution with schematization (#501) This PR adds support to do schema evolution through ALTER TABLE command when there is schema mismatch between the kafka message and the table schema * Bump protobuf-java from 3.19.4 to 3.19.6 in /test/test_data/protobuf (#499) Bumps [protobuf-java](https://github.com/protocolbuffers/protobuf) from 3.19.4 to 3.19.6. - [Release notes](https://github.com/protocolbuffers/protobuf/releases) - [Changelog](https://github.com/protocolbuffers/protobuf/blob/main/generate_changelog.py) - [Commits](protocolbuffers/protobuf@v3.19.4...v3.19.6) --- updated-dependencies: - dependency-name: com.google.protobuf:protobuf-java dependency-type: direct:production ... Signed-off-by: dependabot[bot] <support@github.com> Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * SNOW-686528: Check schema evolution table option (#509) - We always enable schema evolution for tables that are created by KC - Check for schema evolution table option before updating the schema * SNOW-506446: [Snyk] Security upgrade com.fasterxml.jackson.core:jackson-databind from 2.13.2.1 to 2.13.4.2 (#503) * fix: pom.xml to reduce vulnerabilities The following vulnerabilities are fixed with an upgrade: - https://snyk.io/vuln/SNYK-JAVA-COMFASTERXMLJACKSONCORE-3038426 * added to confluent pom as well Co-authored-by: snyk-bot <snyk-bot@snyk.io> Co-authored-by: revi cheng <revi.cheng@snowflake.com> Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: Toby Zhang <toby.zhang@snowflake.com> Co-authored-by: Jay Patel <jay.patel@snowflake.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: sfc-gh-snyk-sca-sa <95290361+sfc-gh-snyk-sca-sa@users.noreply.github.com> Co-authored-by: snyk-bot <snyk-bot@snyk.io>

sfc-gh-rcheng added 4 commits September 13, 2022 16:55

smh static doesnt work

bb3e22a

logginghandler with static cid, logging -> enablelogging

480cb79

test gitignore

74c9704

passes tests

d661c6c

sfc-gh-rcheng commented Sep 14, 2022

View reviewed changes

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkConnector.java Show resolved Hide resolved

sfc-gh-rcheng commented Sep 14, 2022

View reviewed changes

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkConnector.java Show resolved Hide resolved

sfc-gh-rcheng commented Sep 14, 2022

View reviewed changes

src/main/java/com/snowflake/kafka/connector/SnowflakeSinkConnector.java Show resolved Hide resolved

sfc-gh-rcheng commented Sep 14, 2022

View reviewed changes

src/main/java/com/snowflake/kafka/connector/Utils.java Show resolved Hide resolved

sfc-gh-rcheng commented Sep 14, 2022

View reviewed changes

src/main/java/com/snowflake/kafka/connector/internal/EnableLogging.java Show resolved Hide resolved

sfc-gh-rcheng changed the title ~~Add correlationId to logging~~ [draft] Add correlationId to logging Sep 14, 2022

sfc-gh-rcheng changed the title ~~[draft] Add correlationId to logging~~ [SNOW-594195] Add correlationId to logging Sep 15, 2022

sfc-gh-rcheng marked this pull request as ready for review September 15, 2022 22:44

sfc-gh-rcheng requested review from sfc-gh-japatel, sfc-gh-rramachandran, sfc-gh-mnaides, sfc-gh-tzhang and sfc-gh-tjones as code owners September 15, 2022 22:44

sfc-gh-rcheng added 3 commits September 15, 2022 18:05

corrid at beginning

37e4464

Merge branch 'master' into rcheng-corrid

6927708

remove yml files from git cache

8025240

sfc-gh-tzhang reviewed Sep 16, 2022

View reviewed changes

add yml, copyright; change logger class name

60baf2b

sfc-gh-rcheng force-pushed the rcheng-corrid branch from d248a11 to 60baf2b Compare September 16, 2022 20:36

sfc-gh-rcheng added 3 commits September 16, 2022 13:37

Merge branch 'master' into rcheng-corrid

49bfd90

ran formatter

adf9741

remove wildcard imports

d42a722

sfc-gh-rcheng commented Sep 16, 2022

View reviewed changes

src/test/java/com/snowflake/kafka/connector/internal/LoggerHandlerTest.java Outdated Show resolved Hide resolved

sfc-gh-rcheng requested a review from sfc-gh-tzhang September 19, 2022 23:32

sfc-gh-tzhang approved these changes Sep 19, 2022

View reviewed changes

src/test/java/com/snowflake/kafka/connector/internal/LoggerHandlerTest.java Outdated Show resolved Hide resolved