2022-01-31 09:30:41 INFO i.a.w.w.WorkerRun(call):49 - Executing worker wrapper. Airbyte version: 0.35.5-alpha
2022-01-31 09:30:42 INFO i.a.w.t.TemporalAttemptExecution(get):118 - Docker volume job log path: /tmp/workspace/60/0/logs.log
2022-01-31 09:30:42 INFO i.a.w.t.TemporalAttemptExecution(get):123 - Executing worker wrapper. Airbyte version: version not set
2022-01-31 09:30:42 WARN i.a.d.Databases(createPostgresDatabaseWithRetryTimeout):65 - Waiting for database to become available...
2022-01-31 09:30:42 INFO i.a.d.i.j.JobsDatabaseInstance(lambda$static$2):25 - Testing if jobs database is ready...
2022-01-31 09:30:42 INFO i.a.d.Databases(createPostgresDatabaseWithRetryTimeout):90 - Database available!
2022-01-31 09:30:42 INFO i.a.d.Databases(createPostgresDatabaseWithRetry):48 - Database available!
2022-01-31 09:30:42 INFO i.a.w.DefaultReplicationWorker(run):99 - start sync worker. job id: 60 attempt id: 0
2022-01-31 09:30:42 INFO i.a.w.DefaultReplicationWorker(run):108 - configured sync modes: {PUBLIC.TEST_TIMESTAMP=incremental - append}
2022-01-31 09:30:42 INFO i.a.w.p.a.DefaultAirbyteDestination(start):69 - Running destination...
2022-01-31 09:30:42 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/destination-s3:0.2.5 exists...
2022-01-31 09:30:42 INFO i.a.w.p.DockerProcessFactory(create):177 - Preparing command: docker run --rm --init -i -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -w /data/60/0 --network host --log-driver none airbyte/destination-s3:0.2.5 write --config destination_config.json --catalog destination_catalog.json
2022-01-31 09:30:42 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/destination-s3:0.2.5 was found locally.
2022-01-31 09:30:42 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/source-snowflake:0.1.5 exists...
2022-01-31 09:30:42 INFO i.a.w.p.DockerProcessFactory(create):177 - Preparing command: docker run --rm --init -i -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -w /data/60/0 --network host --log-driver none airbyte/source-snowflake:0.1.5 read --config source_config.json --catalog source_catalog.json --state input_state.json
2022-01-31 09:30:42 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/source-snowflake:0.1.5 was found locally.
2022-01-31 09:30:42 INFO i.a.w.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$4):277 - Destination output thread started.
2022-01-31 09:30:42 INFO i.a.w.DefaultReplicationWorker(run):130 - Waiting for source and destination threads to complete.
2022-01-31 09:30:42 INFO i.a.w.DefaultReplicationWorker(lambda$getReplicationRunnable$3):238 - Replication thread started.
2022-01-31 09:30:43 destination > SLF4J: Class path contains multiple SLF4J bindings.
2022-01-31 09:30:43 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/log4j-slf4j-impl-2.16.0.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-01-31 09:30:43 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-01-31 09:30:43 destination > SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
2022-01-31 09:30:43 destination > SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.s.s.SnowflakeSource(main):29 - starting source: class io.airbyte.integrations.source.snowflake.SnowflakeSource
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationRunner(run):76 - Running integration: io.airbyte.integrations.source.snowflake.SnowflakeSource
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationCliParser(parseOptions):118 - integration args: {read=null, catalog=source_catalog.json, state=input_state.json, config=source_config.json}
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationRunner(run):80 - Command: READ
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationRunner(run):81 - Integration config: IntegrationConfig{command=READ, configPath='source_config.json', catalogPath='source_catalog.json', statePath='input_state.json'}
2022-01-31 09:30:45 destination > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationRunner(run):76 - Running integration: io.airbyte.integrations.destination.s3.S3Destination
2022-01-31 09:30:45 destination > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationCliParser(parseOptions):118 - integration args: {catalog=destination_catalog.json, write=null, config=destination_config.json}
2022-01-31 09:30:45 destination > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationRunner(run):80 - Command: WRITE
2022-01-31 09:30:45 destination > 2022-01-31 09:30:45 INFO i.a.i.b.IntegrationRunner(run):81 - Integration config: IntegrationConfig{command=WRITE, configPath='destination_config.json', catalogPath='destination_catalog.json', statePath='null'}
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword examples - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword order - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword airbyte_secret - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.s.r.CdcStateManager(<init>):26 - Initialized CDC state with: null
2022-01-31 09:30:45 source > 2022-01-31 09:30:45 INFO i.a.i.s.r.StateManager(createCursorInfoForStream):108 - Found matching cursor in state. Stream: AirbyteStreamNameNamespacePair{name='TEST_TIMESTAMP', namespace='PUBLIC'}. Cursor Field: REQUEST_TIMESTAMP_FORMATTED Value: 2022-01-31T01:27:08Z
2022-01-31 09:30:46 destination > 2022-01-31 09:30:46 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword examples - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-01-31 09:30:46 destination > 2022-01-31 09:30:46 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword airbyte_secret - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-01-31 09:30:46 destination > 2022-01-31 09:30:46 INFO i.a.i.d.s.S3FormatConfigs(getS3FormatConfig):22 - S3 format config: {"flattening":"Root level flattening","format_type":"CSV","part_size_mb":15}
2022-01-31 09:30:47 destination > 2022-01-31 09:30:47 INFO i.a.i.d.s.c.S3CsvWriter(<init>):56 - Full S3 path for stream 'TEST_TIMESTAMP': s3://bsft-de-airbyte-testing/snowflake/bsft/PUBLIC/TEST_TIMESTAMP/2022_01_31_1643621447379_58d77e8c-c40e-4ce7-bfb9-b4d9d86dd97f.csv
2022-01-31 09:30:47 destination > 2022-01-31 09:30:47 INFO i.a.i.d.s.u.S3StreamTransferManagerHelper(getDefault):55 - PartSize arg is set to 15 MB
2022-01-31 09:30:48 destination > 2022-01-31 09:30:48 INFO a.m.s.StreamTransferManager(getMultiPartOutputStreams):329 - Initiated multipart upload to bsft-de-airbyte-testing/snowflake/bsft/PUBLIC/TEST_TIMESTAMP/2022_01_31_1643621447379_58d77e8c-c40e-4ce7-bfb9-b4d9d86dd97f.csv with full ID 1vrKRma6OCBa9RbHYyb6MEyvr754mSavHVGLCxwl3SbFp1BcneGM.WYLjCuvsTMxlct5CqCQE1b.0Ql8oqEq60oGLGnAFUp3OOogAquB0h8Q9XVmwD02HOfrl5cEM5Jq
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.j.AbstractJdbcSource(lambda$discoverInternal$5):136 - Table TEST_TIMESTAMP column ID (type NUMBER[38]) -> Json type NUMBER
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.j.AbstractJdbcSource(lambda$discoverInternal$5):136 - Table TEST_TIMESTAMP column REQUEST_TIMESTAMP_FORMATTED (type TIMESTAMPNTZ[0]) -> Json type STRING
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.j.AbstractJdbcSource(queryTableIncremental):255 - Queueing query for table: TEST_TIMESTAMP
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.j.AbstractJdbcSource(lambda$queryTableIncremental$16):260 - Preparing query for table: TEST_TIMESTAMP
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.j.AbstractJdbcSource(lambda$queryTableIncremental$16):269 - Executing query for table: TEST_TIMESTAMP
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.r.StateDecoratingIterator(computeNext):60 - State Report: stream name: AirbyteStreamNameNamespacePair{name='TEST_TIMESTAMP', namespace='PUBLIC'}, original cursor field: REQUEST_TIMESTAMP_FORMATTED, original cursor 2022-01-31T01:27:08Z, cursor field: REQUEST_TIMESTAMP_FORMATTED, new cursor: 2022-01-31T01:27:08Z
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.r.AbstractDbSource(lambda$read$2):123 - Closing database connection pool.
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.r.AbstractDbSource(lambda$read$2):125 - Closed database connection pool.
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.b.IntegrationRunner(run):133 - Completed integration: io.airbyte.integrations.source.snowflake.SnowflakeSource
2022-01-31 09:30:49 source > 2022-01-31 09:30:49 INFO i.a.i.s.s.SnowflakeSource(main):31 - completed source: class io.airbyte.integrations.source.snowflake.SnowflakeSource
2022-01-31 09:30:51 INFO i.a.w.DefaultReplicationWorker(run):135 - One of source or destination thread complete. Waiting on the other.
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO i.a.i.b.FailureTrackingAirbyteMessageConsumer(close):60 - Airbyte message consumer: succeeded.
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO i.a.i.d.s.w.BaseS3Writer(close):107 - Uploading remaining data for stream 'TEST_TIMESTAMP'.
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO a.m.s.MultiPartOutputStream(close):158 - Called close() on [MultipartOutputStream for parts 1 - 10000]
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO a.m.s.MultiPartOutputStream(close):158 - Called close() on [MultipartOutputStream for parts 1 - 10000]
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 WARN a.m.s.MultiPartOutputStream(close):160 - [MultipartOutputStream for parts 1 - 10000] is already closed
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO a.m.s.StreamTransferManager(complete):367 - [Manager uploading to bsft-de-airbyte-testing/snowflake/bsft/PUBLIC/TEST_TIMESTAMP/2022_01_31_1643621447379_58d77e8c-c40e-4ce7-bfb9-b4d9d86dd97f.csv with id 1vrKRma6O...rl5cEM5Jq]: Uploading leftover stream [Part number 1 containing 0.01 MB]
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO a.m.s.StreamTransferManager(uploadStreamPart):558 - [Manager uploading to bsft-de-airbyte-testing/snowflake/bsft/PUBLIC/TEST_TIMESTAMP/2022_01_31_1643621447379_58d77e8c-c40e-4ce7-bfb9-b4d9d86dd97f.csv with id 1vrKRma6O...rl5cEM5Jq]: Finished uploading [Part number 1 containing 0.01 MB]
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO a.m.s.StreamTransferManager(complete):395 - [Manager uploading to bsft-de-airbyte-testing/snowflake/bsft/PUBLIC/TEST_TIMESTAMP/2022_01_31_1643621447379_58d77e8c-c40e-4ce7-bfb9-b4d9d86dd97f.csv with id 1vrKRma6O...rl5cEM5Jq]: Completed
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO i.a.i.d.s.w.BaseS3Writer(close):109 - Upload completed for stream 'TEST_TIMESTAMP'.
2022-01-31 09:30:51 INFO i.a.w.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$4):282 - state in DefaultReplicationWorker from Destination: io.airbyte.protocol.models.AirbyteMessage@ac9b8a1[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@40e4788[data={"cdc":false,"streams":[{"stream_name":"TEST_TIMESTAMP","stream_namespace":"PUBLIC","cursor_field":["REQUEST_TIMESTAMP_FORMATTED"],"cursor":"2022-01-31T01:27:08Z"}]},additionalProperties={}],additionalProperties={}]
2022-01-31 09:30:51 destination > 2022-01-31 09:30:51 INFO i.a.i.b.IntegrationRunner(run):133 - Completed integration: io.airbyte.integrations.destination.s3.S3Destination
2022-01-31 09:30:51 INFO i.a.w.DefaultReplicationWorker(run):137 - Source and destination threads complete.
2022-01-31 09:30:51 INFO i.a.w.DefaultReplicationWorker(run):200 - sync summary: io.airbyte.config.ReplicationAttemptSummary@586bdb9e[status=completed,recordsSynced=100,bytesSynced=6208,startTime=1643621442220,endTime=1643621451346,totalStats=io.airbyte.config.SyncStats@4bbc904c[recordsEmitted=100,bytesEmitted=6208,stateMessagesEmitted=1,recordsCommitted=100],streamStats=[io.airbyte.config.StreamSyncStats@51975363[streamName=TEST_TIMESTAMP,stats=io.airbyte.config.SyncStats@4baa3cb2[recordsEmitted=100,bytesEmitted=6208,stateMessagesEmitted=<null>,recordsCommitted=100]]]]
2022-01-31 09:30:51 INFO i.a.w.DefaultReplicationWorker(run):207 - Source output at least one state message
2022-01-31 09:30:51 INFO i.a.w.DefaultReplicationWorker(run):213 - State capture: Updated state to: Optional[io.airbyte.config.State@4d1bb972[state={"cdc":false,"streams":[{"stream_name":"TEST_TIMESTAMP","stream_namespace":"PUBLIC","cursor_field":["REQUEST_TIMESTAMP_FORMATTED"],"cursor":"2022-01-31T01:27:08Z"}]}]]
2022-01-31 09:30:51 INFO i.a.w.t.TemporalAttemptExecution(get):144 - Stopping cancellation check scheduling...
2022-01-31 09:30:51 INFO i.a.w.t.s.ReplicationActivityImpl(replicate):144 - sync summary: io.airbyte.config.StandardSyncOutput@54bc63a4[standardSyncSummary=io.airbyte.config.StandardSyncSummary@3f5b5c86[status=completed,recordsSynced=100,bytesSynced=6208,startTime=1643621442220,endTime=1643621451346,totalStats=io.airbyte.config.SyncStats@4bbc904c[recordsEmitted=100,bytesEmitted=6208,stateMessagesEmitted=1,recordsCommitted=100],streamStats=[io.airbyte.config.StreamSyncStats@51975363[streamName=TEST_TIMESTAMP,stats=io.airbyte.config.SyncStats@4baa3cb2[recordsEmitted=100,bytesEmitted=6208,stateMessagesEmitted=<null>,recordsCommitted=100]]]],state=io.airbyte.config.State@4d1bb972[state={"cdc":false,"streams":[{"stream_name":"TEST_TIMESTAMP","stream_namespace":"PUBLIC","cursor_field":["REQUEST_TIMESTAMP_FORMATTED"],"cursor":"2022-01-31T01:27:08Z"}]}],outputCatalog=io.airbyte.protocol.models.ConfiguredAirbyteCatalog@6e40a813[streams=[io.airbyte.protocol.models.ConfiguredAirbyteStream@18932763[stream=io.airbyte.protocol.models.AirbyteStream@2f85d696[name=TEST_TIMESTAMP,jsonSchema={"type":"object","properties":{"ID":{"type":"number"},"REQUEST_TIMESTAMP_FORMATTED":{"type":"string"}}},supportedSyncModes=[full_refresh, incremental],sourceDefinedCursor=<null>,defaultCursorField=[],sourceDefinedPrimaryKey=[],namespace=PUBLIC,additionalProperties={}],syncMode=incremental,cursorField=[REQUEST_TIMESTAMP_FORMATTED],destinationSyncMode=append,primaryKey=[],additionalProperties={}]],additionalProperties={}]]
2022-01-31 09:30:51 INFO i.a.c.p.ConfigRepository(updateConnectionState):545 - Updating connection 0d17c944-7c8d-4538-8e99-f241e75c10be state: io.airbyte.config.State@212de96d[state={"cdc":false,"streams":[{"stream_name":"TEST_TIMESTAMP","stream_namespace":"PUBLIC","cursor_field":["REQUEST_TIMESTAMP_FORMATTED"],"cursor":"2022-01-31T01:27:08Z"}]}]