2022-06-30 15:22:20 INFO i.a.v.j.JsonSchemaValidator(test):56 - JSON schema validation failed. 
errors: $.plugin: is not defined in the schema and the schema does not allow additional properties, $.publication: is not defined in the schema and the schema does not allow additional properties, $.replication_slot: is not defined in the schema and the schema does not allow additional properties, $.method: does not have a value in the enumeration [Standard], $.method: must be a constant value Standard
2022-06-30 15:22:20 INFO i.a.w.t.TemporalAttemptExecution(get):108 - Docker volume job log path: /tmp/workspace/1615/0/logs.log
2022-06-30 15:22:20 INFO i.a.w.t.TemporalAttemptExecution(get):113 - Executing worker wrapper. Airbyte version: 0.39.5-alpha
2022-06-30 15:22:20 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/source-postgres:0.4.29 exists...
2022-06-30 15:22:20 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/source-postgres:0.4.29 was found locally.
2022-06-30 15:22:20 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 1615
2022-06-30 15:22:20 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/1615/0 --log-driver none --name source-postgres-check-1615-0-fubwh --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_CONNECTOR_IMAGE=airbyte/source-postgres:0.4.29 -e WORKER_JOB_ATTEMPT=0 -e AIRBYTE_ROLE= -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_VERSION=0.39.5-alpha -e WORKER_JOB_ID=1615 airbyte/source-postgres:0.4.29 check --config source_config.json
2022-06-30 15:22:21 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:21 INFO i.a.i.b.a.AdaptiveSourceRunner$Runner(getSource):73 - Running source under deployment mode: null
2022-06-30 15:22:21 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:21 WARN i.a.i.b.a.AdaptiveSourceRunner$Runner(getSource):78 - Deployment mode is null, default to OSS mode
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO i.a.i.b.a.AdaptiveSourceRunner$Runner(run):85 - Starting source: io.airbyte.integrations.base.ssh.SshWrappedSource
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO i.a.i.b.IntegrationCliParser(parseOptions):118 - integration args: {check=null, config=source_config.json}
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO i.a.i.b.IntegrationRunner(runInternal):123 - Running integration: io.airbyte.integrations.base.ssh.SshWrappedSource
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO i.a.i.b.IntegrationRunner(runInternal):124 - Command: CHECK
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO i.a.i.b.IntegrationRunner(runInternal):125 - Integration config: IntegrationConfig{command=CHECK, configPath='source_config.json', catalogPath='null', statePath='null'}
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 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-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 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-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 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-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword multiline - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO i.a.i.b.s.SshTunnel(getInstance):170 - Starting connection with method: NO_TUNNEL
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO c.z.h.HikariDataSource(<init>):80 - HikariPool-1 - Starting...
2022-06-30 15:22:22 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:22 INFO c.z.h.HikariDataSource(<init>):82 - HikariPool-1 - Start completed.
2022-06-30 15:22:23 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:23 INFO i.a.i.s.p.PostgresSource(isCdc):277 - using CDC: true
2022-06-30 15:22:23 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:23 INFO i.a.i.s.j.AbstractJdbcSource(lambda$getCheckOperations$1):93 - Attempting to get metadata from the database to see if we can connect.
2022-06-30 15:22:24 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:24 INFO i.a.i.s.p.PostgresSource(lambda$getCheckOperations$1):185 - Attempting to find the named replication slot using the query: HikariProxyPreparedStatement@1637601612 wrapping SELECT * FROM pg_replication_slots WHERE slot_name = 'airbyte_slot_history' AND plugin = 'wal2json' AND database = 'airbyte_cdc_test_source_history'
2022-06-30 15:22:24 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:24 INFO i.a.d.j.s.AdaptiveStreamingQueryConfig(initialize):38 - Set initial fetch size: 10 rows
2022-06-30 15:22:24 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:24 INFO i.a.i.s.p.PostgresSource(lambda$getCheckOperations$3):203 - Attempting to find the publication using the query: HikariProxyPreparedStatement@2063786038 wrapping SELECT * FROM pg_publication WHERE pubname = 'airbyte_publication_history'
2022-06-30 15:22:24 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:24 INFO i.a.d.j.s.AdaptiveStreamingQueryConfig(initialize):38 - Set initial fetch size: 10 rows
2022-06-30 15:22:24 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:24 INFO c.z.h.HikariDataSource(close):350 - HikariPool-1 - Shutdown initiated...
2022-06-30 15:22:24 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:24 INFO c.z.h.HikariDataSource(close):352 - HikariPool-1 - Shutdown completed.
2022-06-30 15:22:24 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling...
2022-06-30 15:22:24 INFO i.a.w.t.TemporalAttemptExecution(get):108 - Docker volume job log path: /tmp/workspace/1615/0/logs.log
2022-06-30 15:22:24 INFO i.a.w.t.TemporalAttemptExecution(get):113 - Executing worker wrapper. Airbyte version: 0.39.5-alpha
2022-06-30 15:22:25 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/destination-postgres:0.3.20 exists...
2022-06-30 15:22:25 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/destination-postgres:0.3.20 was found locally.
2022-06-30 15:22:25 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 1615
2022-06-30 15:22:25 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/1615/0 --log-driver none --name destination-postgres-check-1615-0-hvbqd --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_CONNECTOR_IMAGE=airbyte/destination-postgres:0.3.20 -e WORKER_JOB_ATTEMPT=0 -e AIRBYTE_ROLE= -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_VERSION=0.39.5-alpha -e WORKER_JOB_ID=1615 airbyte/destination-postgres:0.3.20 check --config source_config.json
2022-06-30 15:22:25 ERROR i.a.c.i.LineGobbler(voidCall):82 - SLF4J: Class path contains multiple SLF4J bindings.
2022-06-30 15:22:25 ERROR i.a.c.i.LineGobbler(voidCall):82 - SLF4J: Found binding in [jar:file:/airbyte/lib/log4j-slf4j-impl-2.17.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-06-30 15:22:25 ERROR i.a.c.i.LineGobbler(voidCall):82 - SLF4J: Found binding in [jar:file:/airbyte/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-06-30 15:22:25 ERROR i.a.c.i.LineGobbler(voidCall):82 - SLF4J: Found binding in [jar:file:/airbyte/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-06-30 15:22:25 ERROR i.a.c.i.LineGobbler(voidCall):82 - SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
2022-06-30 15:22:25 ERROR i.a.c.i.LineGobbler(voidCall):82 - SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
2022-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 INFO i.a.i.d.p.PostgresDestination(main):90 - starting destination: class io.airbyte.integrations.destination.postgres.PostgresDestination
2022-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 INFO i.a.i.b.IntegrationCliParser(parseOptions):118 - integration args: {check=null, config=source_config.json}
2022-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 INFO i.a.i.b.IntegrationRunner(runInternal):123 - Running integration: io.airbyte.integrations.base.ssh.SshWrappedDestination
2022-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 INFO i.a.i.b.IntegrationRunner(runInternal):124 - Command: CHECK
2022-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 INFO i.a.i.b.IntegrationRunner(runInternal):125 - Integration config: IntegrationConfig{command=CHECK, configPath='source_config.json', catalogPath='null', statePath='null'}
2022-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 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-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 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-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 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-06-30 15:22:26 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:26 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword multiline - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-06-30 15:22:27 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:27 INFO i.a.i.b.s.SshTunnel(getInstance):170 - Starting connection with method: NO_TUNNEL
2022-06-30 15:22:27 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:27 INFO c.z.h.HikariDataSource(<init>):80 - HikariPool-1 - Starting...
2022-06-30 15:22:27 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:27 INFO c.z.h.HikariDataSource(<init>):82 - HikariPool-1 - Start completed.
2022-06-30 15:22:28 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:28 INFO c.z.h.HikariDataSource(close):350 - HikariPool-1 - Shutdown initiated...
2022-06-30 15:22:28 INFO i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$0):61 - 2022-06-30 15:22:28 INFO c.z.h.HikariDataSource(close):352 - HikariPool-1 - Shutdown completed.
2022-06-30 15:22:28 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling...
2022-06-30 15:22:29 INFO i.a.w.t.TemporalAttemptExecution(get):108 - Docker volume job log path: /tmp/workspace/1615/0/logs.log
2022-06-30 15:22:29 INFO i.a.w.t.TemporalAttemptExecution(get):113 - Executing worker wrapper. Airbyte version: 0.39.5-alpha
2022-06-30 15:22:29 INFO i.a.w.g.DefaultReplicationWorker(run):112 - start sync worker. job id: 1615 attempt id: 0
2022-06-30 15:22:29 INFO i.a.w.g.DefaultReplicationWorker(run):124 - configured sync modes: {history.hist_table1=incremental - append}
2022-06-30 15:22:29 INFO i.a.w.i.DefaultAirbyteDestination(start):69 - Running destination...
2022-06-30 15:22:29 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/destination-postgres:0.3.20 exists...
2022-06-30 15:22:29 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/destination-postgres:0.3.20 was found locally.
2022-06-30 15:22:29 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 1615
2022-06-30 15:22:29 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/1615/0 --log-driver none --name destination-postgres-write-1615-0-wyfeh --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_CONNECTOR_IMAGE=airbyte/destination-postgres:0.3.20 -e WORKER_JOB_ATTEMPT=0 -e AIRBYTE_ROLE= -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_VERSION=0.39.5-alpha -e WORKER_JOB_ID=1615 airbyte/destination-postgres:0.3.20 write --config destination_config.json --catalog destination_catalog.json
2022-06-30 15:22:29 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/source-postgres:0.4.29 exists...
2022-06-30 15:22:29 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/source-postgres:0.4.29 was found locally.
2022-06-30 15:22:29 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 1615
2022-06-30 15:22:29 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/1615/0 --log-driver none --name source-postgres-read-1615-0-orcwt --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e WORKER_CONNECTOR_IMAGE=airbyte/source-postgres:0.4.29 -e WORKER_JOB_ATTEMPT=0 -e AIRBYTE_ROLE= -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_VERSION=0.39.5-alpha -e WORKER_JOB_ID=1615 airbyte/source-postgres:0.4.29 read --config source_config.json --catalog source_catalog.json --state input_state.json
2022-06-30 15:22:29 INFO i.a.w.g.DefaultReplicationWorker(run):166 - Waiting for source and destination threads to complete.
2022-06-30 15:22:29 INFO i.a.w.g.DefaultReplicationWorker(lambda$getDestinationOutputRunnable$7):385 - Destination output thread started.
2022-06-30 15:22:29 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):295 - Replication thread started.
2022-06-30 15:22:29 destination > SLF4J: Class path contains multiple SLF4J bindings.
2022-06-30 15:22:29 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/log4j-slf4j-impl-2.17.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-06-30 15:22:29 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-06-30 15:22:29 destination > SLF4J: Found binding in [jar:file:/airbyte/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
2022-06-30 15:22:29 destination > SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
2022-06-30 15:22:29 destination > SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
2022-06-30 15:22:30 destination > 2022-06-30 15:22:30 INFO i.a.i.d.p.PostgresDestination(main):90 - starting destination: class io.airbyte.integrations.destination.postgres.PostgresDestination
2022-06-30 15:22:30 source > 2022-06-30 15:22:30 INFO i.a.i.b.a.AdaptiveSourceRunner$Runner(getSource):73 - Running source under deployment mode: null
2022-06-30 15:22:30 source > 2022-06-30 15:22:30 WARN i.a.i.b.a.AdaptiveSourceRunner$Runner(getSource):78 - Deployment mode is null, default to OSS mode
2022-06-30 15:22:30 destination > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationCliParser(parseOptions):118 - integration args: {catalog=destination_catalog.json, write=null, config=destination_config.json}
2022-06-30 15:22:30 destination > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationRunner(runInternal):123 - Running integration: io.airbyte.integrations.base.ssh.SshWrappedDestination
2022-06-30 15:22:30 destination > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationRunner(runInternal):124 - Command: WRITE
2022-06-30 15:22:30 destination > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationRunner(runInternal):125 - Integration config: IntegrationConfig{command=WRITE, configPath='destination_config.json', catalogPath='destination_catalog.json', statePath='null'}
2022-06-30 15:22:30 source > 2022-06-30 15:22:30 INFO i.a.i.b.a.AdaptiveSourceRunner$Runner(run):85 - Starting source: io.airbyte.integrations.base.ssh.SshWrappedSource
2022-06-30 15:22:30 source > 2022-06-30 15:22:30 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-06-30 15:22:30 source > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationRunner(runInternal):123 - Running integration: io.airbyte.integrations.base.ssh.SshWrappedSource
2022-06-30 15:22:30 source > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationRunner(runInternal):124 - Command: READ
2022-06-30 15:22:30 source > 2022-06-30 15:22:30 INFO i.a.i.b.IntegrationRunner(runInternal):125 - Integration config: IntegrationConfig{command=READ, configPath='source_config.json', catalogPath='source_catalog.json', statePath='input_state.json'}
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 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-06-30 15:22:31 destination > 2022-06-30 15:22:31 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-06-30 15:22:31 destination > 2022-06-30 15:22:31 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-06-30 15:22:31 destination > 2022-06-30 15:22:31 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword multiline - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-06-30 15:22:31 source > 2022-06-30 15:22:31 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-06-30 15:22:31 source > 2022-06-30 15:22:31 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-06-30 15:22:31 source > 2022-06-30 15:22:31 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-06-30 15:22:31 source > 2022-06-30 15:22:31 WARN c.n.s.JsonMetaSchema(newValidator):338 - Unknown keyword multiline - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO i.a.i.b.s.SshTunnel(getInstance):170 - Starting connection with method: NO_TUNNEL
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO c.z.h.HikariDataSource(<init>):80 - HikariPool-1 - Starting...
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO c.z.h.HikariDataSource(<init>):82 - HikariPool-1 - Start completed.
2022-06-30 15:22:31 source > 2022-06-30 15:22:31 INFO i.a.i.b.s.SshTunnel(getInstance):170 - Starting connection with method: NO_TUNNEL
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$toWriteConfig$0):98 - Write config: WriteConfig{streamName=hist_table1, namespace=history, outputSchemaName=history, tmpTableName=_airbyte_tmp_hpv_hist_table1, outputTableName=_airbyte_raw_hist_table1, syncMode=append}
2022-06-30 15:22:31 source > 2022-06-30 15:22:31 INFO c.z.h.HikariDataSource(<init>):80 - HikariPool-1 - Starting...
2022-06-30 15:22:31 source > 2022-06-30 15:22:31 INFO c.z.h.HikariDataSource(<init>):82 - HikariPool-1 - Start completed.
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO i.a.i.d.b.BufferedStreamConsumer(startTracked):116 - class io.airbyte.integrations.destination.buffered_stream_consumer.BufferedStreamConsumer started.
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onStartFunction$1):123 - Preparing tmp tables in destination started for 1 streams
2022-06-30 15:22:31 destination > 2022-06-30 15:22:31 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onStartFunction$1):127 - Preparing tmp table in destination started for stream hist_table1. schema: history, tmp table name: _airbyte_tmp_hpv_hist_table1
2022-06-30 15:22:32 source > 2022-06-30 15:22:32 INFO i.a.i.s.p.PostgresSource(isCdc):277 - using CDC: true
2022-06-30 15:22:32 source > 2022-06-30 15:22:32 INFO i.a.i.s.j.AbstractJdbcSource(lambda$getCheckOperations$1):93 - Attempting to get metadata from the database to see if we can connect.
2022-06-30 15:22:32 source > 2022-06-30 15:22:32 INFO i.a.i.s.p.PostgresSource(lambda$getCheckOperations$1):185 - Attempting to find the named replication slot using the query: HikariProxyPreparedStatement@615853374 wrapping SELECT * FROM pg_replication_slots WHERE slot_name = 'airbyte_slot_history' AND plugin = 'wal2json' AND database = 'airbyte_cdc_test_source_history'
2022-06-30 15:22:32 source > 2022-06-30 15:22:32 INFO i.a.d.j.s.AdaptiveStreamingQueryConfig(initialize):38 - Set initial fetch size: 10 rows
2022-06-30 15:22:33 destination > 2022-06-30 15:22:33 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onStartFunction$1):133 - Preparing tables in destination completed.
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.p.PostgresSource(lambda$getCheckOperations$3):203 - Attempting to find the publication using the query: HikariProxyPreparedStatement@465152579 wrapping SELECT * FROM pg_publication WHERE pubname = 'airbyte_publication_history'
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.d.j.s.AdaptiveStreamingQueryConfig(initialize):38 - Set initial fetch size: 10 rows
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO c.z.h.HikariDataSource(close):350 - HikariPool-1 - Shutdown initiated...
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO c.z.h.HikariDataSource(close):352 - HikariPool-1 - Shutdown completed.
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.p.PostgresSource(isCdc):277 - using CDC: true
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.c.f.EnvVariableFeatureFlags(getEnvOrDefault):43 - Using default value for environment variable USE_STREAM_CAPABLE_STATE: 'false'
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.p.PostgresSource(isCdc):277 - using CDC: true
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.r.s.StateManagerFactory(createStateManager):51 - Global state manager selected to manage state object with type LEGACY.
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.r.s.StateManagerFactory(generateGlobalState):84 - Legacy state converted to global state.
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.r.s.CursorManager(createCursorInfoForStream):161 - No cursor field set in catalog but not present in state. Stream: AirbyteStreamNameNamespacePair{name='hist_table1', namespace='history'}, New Cursor Field: null. Resetting cursor value
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.r.CdcStateManager(<init>):24 - Initialized CDC state with: null
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO c.z.h.HikariDataSource(<init>):80 - HikariPool-2 - Starting...
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO c.z.h.HikariDataSource(<init>):82 - HikariPool-2 - Start completed.
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.p.PostgresSource(discoverInternal):156 - Checking schema: history
2022-06-30 15:22:33 source > 2022-06-30 15:22:33 INFO i.a.i.s.j.AbstractJdbcSource(discoverInternal):121 - Internal schemas to exclude: [catalog_history, information_schema, pg_catalog, pg_internal]
2022-06-30 15:22:34 source > 2022-06-30 15:22:34 INFO i.a.d.j.s.AdaptiveStreamingQueryConfig(initialize):38 - Set initial fetch size: 10 rows
2022-06-30 15:22:34 source > 2022-06-30 15:22:34 INFO i.a.i.s.j.AbstractJdbcSource(lambda$discoverInternal$5):143 - Table hist_table1 column id (type int4[10]) -> JsonSchemaType({type=number})
2022-06-30 15:22:34 source > 2022-06-30 15:22:34 INFO i.a.i.s.j.AbstractJdbcSource(lambda$discoverInternal$5):143 - Table hist_table1 column column1 (type varchar[2147483647]) -> JsonSchemaType({type=string})
2022-06-30 15:22:34 source > 2022-06-30 15:22:34 INFO i.a.i.s.p.PostgresSource(discoverInternal):160 - Found table: history.hist_table1
2022-06-30 15:22:34 source > 2022-06-30 15:22:34 INFO i.a.i.s.p.PostgresSource(isCdc):277 - using CDC: true
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.a.i.s.p.PostgresCdcTargetPosition(targetPosition):45 - identified target lsn: PgLsn{lsn=12856744976384}
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.a.i.d.AirbyteDebeziumHandler(getIncrementalIterators):96 - using CDC: true
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO o.a.k.c.c.AbstractConfig(logAll):376 - EmbeddedConfig values: 
2022-06-30 15:22:35 source > 	access.control.allow.methods = 
2022-06-30 15:22:35 source > 	access.control.allow.origin = 
2022-06-30 15:22:35 source > 	admin.listeners = null
2022-06-30 15:22:35 source > 	bootstrap.servers = [localhost:9092]
2022-06-30 15:22:35 source > 	client.dns.lookup = use_all_dns_ips
2022-06-30 15:22:35 source > 	config.providers = []
2022-06-30 15:22:35 source > 	connector.client.config.override.policy = All
2022-06-30 15:22:35 source > 	header.converter = class org.apache.kafka.connect.storage.SimpleHeaderConverter
2022-06-30 15:22:35 source > 	key.converter = class org.apache.kafka.connect.json.JsonConverter
2022-06-30 15:22:35 source > 	listeners = [http://:8083]
2022-06-30 15:22:35 source > 	metric.reporters = []
2022-06-30 15:22:35 source > 	metrics.num.samples = 2
2022-06-30 15:22:35 source > 	metrics.recording.level = INFO
2022-06-30 15:22:35 source > 	metrics.sample.window.ms = 30000
2022-06-30 15:22:35 source > 	offset.flush.interval.ms = 1000
2022-06-30 15:22:35 source > 	offset.flush.timeout.ms = 5000
2022-06-30 15:22:35 source > 	offset.storage.file.filename = /tmp/cdc-state-offset14994011218380743363/offset.dat
2022-06-30 15:22:35 source > 	offset.storage.partitions = null
2022-06-30 15:22:35 source > 	offset.storage.replication.factor = null
2022-06-30 15:22:35 source > 	offset.storage.topic = 
2022-06-30 15:22:35 source > 	plugin.path = null
2022-06-30 15:22:35 source > 	response.http.headers.config = 
2022-06-30 15:22:35 source > 	rest.advertised.host.name = null
2022-06-30 15:22:35 source > 	rest.advertised.listener = null
2022-06-30 15:22:35 source > 	rest.advertised.port = null
2022-06-30 15:22:35 source > 	rest.extension.classes = []
2022-06-30 15:22:35 source > 	ssl.cipher.suites = null
2022-06-30 15:22:35 source > 	ssl.client.auth = none
2022-06-30 15:22:35 source > 	ssl.enabled.protocols = [TLSv1.2, TLSv1.3]
2022-06-30 15:22:35 source > 	ssl.endpoint.identification.algorithm = https
2022-06-30 15:22:35 source > 	ssl.engine.factory.class = null
2022-06-30 15:22:35 source > 	ssl.key.password = null
2022-06-30 15:22:35 source > 	ssl.keymanager.algorithm = SunX509
2022-06-30 15:22:35 source > 	ssl.keystore.certificate.chain = null
2022-06-30 15:22:35 source > 	ssl.keystore.key = null
2022-06-30 15:22:35 source > 	ssl.keystore.location = null
2022-06-30 15:22:35 source > 	ssl.keystore.password = null
2022-06-30 15:22:35 source > 	ssl.keystore.type = JKS
2022-06-30 15:22:35 source > 	ssl.protocol = TLSv1.3
2022-06-30 15:22:35 source > 	ssl.provider = null
2022-06-30 15:22:35 source > 	ssl.secure.random.implementation = null
2022-06-30 15:22:35 source > 	ssl.trustmanager.algorithm = PKIX
2022-06-30 15:22:35 source > 	ssl.truststore.certificates = null
2022-06-30 15:22:35 source > 	ssl.truststore.location = null
2022-06-30 15:22:35 source > 	ssl.truststore.password = null
2022-06-30 15:22:35 source > 	ssl.truststore.type = JKS
2022-06-30 15:22:35 source > 	task.shutdown.graceful.timeout.ms = 5000
2022-06-30 15:22:35 source > 	topic.creation.enable = true
2022-06-30 15:22:35 source > 	topic.tracking.allow.reset = true
2022-06-30 15:22:35 source > 	topic.tracking.enable = true
2022-06-30 15:22:35 source > 	value.converter = class org.apache.kafka.connect.json.JsonConverter
2022-06-30 15:22:35 INFO i.a.v.j.JsonSchemaValidator(test):56 - JSON schema validation failed. 
errors: $: unknown found, object expected
2022-06-30 15:22:35 ERROR i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$1):70 - Validation failed: null
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 WARN o.a.k.c.r.WorkerConfig(logInternalConverterRemovalWarnings):316 - The worker has been configured with one or more internal converter properties ([internal.key.converter, internal.value.converter]). Support for these properties was deprecated in version 2.0 and removed in version 3.0, and specifying them will have no effect. Instead, an instance of the JsonConverter with schemas.enable set to false will be used. For more information, please visit http://kafka.apache.org/documentation/#upgrade and consult the upgrade notesfor the 3.0 release.
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 WARN o.a.k.c.r.WorkerConfig(logPluginPathConfigProviderWarning):334 - Variables cannot be used in the 'plugin.path' property, since the property is used by plugin scanning before the config providers that replace the variables are initialized. The raw value 'null' was used for plugin scanning, as opposed to the transformed value 'null', and this may cause unexpected results.
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 WARN i.d.c.p.PostgresConnectorConfig(validatePluginName):1394 - Logical decoder 'wal2json' is deprecated and will be removed in future versions
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 WARN i.d.c.p.PostgresConnectorConfig(validateTruncateHandlingMode):1333 - Configuration property 'truncate.handling.mode' is deprecated and will be removed in future versions. Please use 'skipped.operations' instead.
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 WARN i.d.c.p.PostgresConnectorConfig(validateToastedValuePlaceholder):1384 - Configuration property 'toasted.value.placeholder' is deprecated and will be removed in future versions. Please use 'unavailable.value.placeholder' instead.
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(start):124 - Starting PostgresConnectorTask with configuration:
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    connector.class = io.debezium.connector.postgresql.PostgresConnector
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    max.queue.size = 8192
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    slot.name = airbyte_slot_history
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    publication.name = airbyte_publication_history
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    offset.storage.file.filename = /tmp/cdc-state-offset14994011218380743363/offset.dat
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    decimal.handling.mode = string
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    converters = datetime
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    datetime.type = io.airbyte.integrations.debezium.internals.PostgresConverter
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    value.converter = org.apache.kafka.connect.json.JsonConverter
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    key.converter = org.apache.kafka.connect.json.JsonConverter
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    publication.autocreate.mode = disabled
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    database.user = airbyte_cdc_user
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    database.dbname = airbyte_cdc_test_source_history
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    offset.storage = org.apache.kafka.connect.storage.FileOffsetBackingStore
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    database.server.name = airbyte_cdc_test_source_history
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    offset.flush.timeout.ms = 5000
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    plugin.name = wal2json
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    database.port = 5432
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    offset.flush.interval.ms = 1000
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    key.converter.schemas.enable = false
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    internal.key.converter = org.apache.kafka.connect.json.JsonConverter
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    database.hostname = dataplatform-development-marketplace-ml-db.cm34s0a3cqfi.eu-west-1.rds.amazonaws.com
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    database.password = ********
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    name = airbyte_cdc_test_source_history
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    value.converter.schemas.enable = false
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    internal.value.converter = org.apache.kafka.connect.json.JsonConverter
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    max.batch.size = 2048
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    table.include.list = history.hist_table1
2022-06-30 15:22:35 source > 2022-06-30 15:22:35 INFO i.d.c.c.BaseSourceTask(lambda$start$0):126 -    snapshot.mode = initial
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.c.BaseSourceTask(getPreviousOffsets):318 - No previous offsets found
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.p.PostgresConnectorTask(start):108 - user 'airbyte_cdc_user' connected to database 'airbyte_cdc_test_source_history' on PostgreSQL 13.4 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red Hat 7.3.1-12), 64-bit with roles:
2022-06-30 15:22:37 source > 	role 'rds_replication' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
2022-06-30 15:22:37 source > 	role 'airbyte_cdc_user' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: true]
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.p.c.PostgresConnection(readReplicationSlotInfo):251 - Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=LSN{B4D/60EEA8C0}, catalogXmin=239486]
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.p.PostgresConnectorTask(start):117 - No previous offset found
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.p.s.InitialSnapshotter(shouldSnapshot):34 - Taking initial snapshot for new datasource
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.u.Threads(threadFactory):270 - Requested thread factory for connector PostgresConnector, id = airbyte_cdc_test_source_history named = change-event-source-coordinator
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.u.Threads$3(newThread):287 - Creating thread debezium-postgresconnector-airbyte_cdc_test_source_history-change-event-source-coordinator
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.p.ChangeEventSourceCoordinator(lambda$start$0):103 - Metrics registered
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.p.ChangeEventSourceCoordinator(lambda$start$0):106 - Context created
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.p.s.InitialSnapshotter(shouldSnapshot):34 - Taking initial snapshot for new datasource
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.c.p.PostgresSnapshotChangeEventSource(getSnapshottingTask):64 - According to the connector configuration data will be snapshotted
2022-06-30 15:22:37 source > 2022-06-30 15:22:37 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):87 - Snapshot step 1 - Preparing
2022-06-30 15:22:40 source > 2022-06-30 15:22:40 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):96 - Snapshot step 2 - Determining captured tables
2022-06-30 15:22:40 source > 2022-06-30 15:22:40 INFO i.d.r.RelationalSnapshotChangeEventSource(determineCapturedTables):189 - Adding table history.hist_table1 to the list of capture schema tables
2022-06-30 15:22:40 source > 2022-06-30 15:22:40 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):103 - Snapshot step 3 - Locking captured tables [history.hist_table1]
2022-06-30 15:22:40 source > 2022-06-30 15:22:40 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):109 - Snapshot step 4 - Determining snapshot offset
2022-06-30 15:22:40 source > 2022-06-30 15:22:40 INFO i.d.c.p.PostgresOffsetContext(initialContext):231 - Creating initial offset context
2022-06-30 15:22:40 source > 2022-06-30 15:22:40 INFO i.d.c.p.PostgresOffsetContext(initialContext):234 - Read xlogStart at 'LSN{BB1/73688000}' from transaction '429223'
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.c.p.PostgresSnapshotChangeEventSource(updateOffsetForSnapshot):146 - Read xlogStart at 'LSN{BB1/73768000}' from transaction '429223'
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):112 - Snapshot step 5 - Reading structure of captured tables
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.c.p.PostgresSnapshotChangeEventSource(readTableStructure):192 - Reading structure of schema 'history' of catalog 'airbyte_cdc_test_source_history'
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):116 - Snapshot step 6 - Persisting schema history
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(doExecute):128 - Snapshot step 7 - Snapshotting data
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(createDataEvents):302 - Snapshotting contents of 1 tables while still in transaction
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(createDataEventsForTable):338 - Exporting data from table 'history.hist_table1' (1 of 1 tables)
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(createDataEventsForTable):346 - 	 For table 'history.hist_table1' using select statement: 'SELECT "id", "column1" FROM "history"."hist_table1"'
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.r.RelationalSnapshotChangeEventSource(createDataEventsForTable):392 - 	 Finished exporting 4 records for table 'history.hist_table1'; total duration '00:00:00.171'
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.p.s.AbstractSnapshotChangeEventSource(execute):88 - Snapshot - Final stage
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.p.ChangeEventSourceCoordinator(doSnapshot):156 - Snapshot ended with SnapshotResult [status=COMPLETED, offset=PostgresOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.postgresql.Source:STRUCT}, sourceInfo=source_info[server='airbyte_cdc_test_source_history'db='airbyte_cdc_test_source_history', lsn=LSN{BB1/73768000}, txId=429223, timestamp=2022-06-30T15:22:41.804Z, snapshot=FALSE, schema=history, table=hist_table1], lastSnapshotRecord=true, lastCompletelyProcessedLsn=null, lastCommitLsn=null, streamingStoppingLsn=null, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], incrementalSnapshotContext=IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]]]
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.p.ChangeEventSourceCoordinator(streamingConnected):234 - Connected metrics set to 'true'
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.c.c.BaseSourceTask(logStatistics):182 - 4 records sent during previous 00:00:06.637, last recorded offset: {last_snapshot_record=true, lsn=12856774262784, txId=429223, ts_usec=1656602561804000, snapshot=true}
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.e.EmbeddedEngine(stop):1047 - Stopping the embedded engine
2022-06-30 15:22:41 source > 2022-06-30 15:22:41 INFO i.d.e.EmbeddedEngine(stop):1055 - Waiting for PT5M for connector to stop
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.c.p.PostgresSchema(printReplicaIdentityInfo):103 - REPLICA IDENTITY for 'history.hist_table1' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.p.ChangeEventSourceCoordinator(streamEvents):173 - Starting streaming
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.c.p.PostgresStreamingChangeEventSource(execute):127 - Retrieved latest position from stored offset 'LSN{BB1/73768000}'
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.c.p.c.WalPositionLocator(<init>):40 - Looking for WAL restart position for last commit LSN 'null' and last change LSN 'LSN{BB1/73768000}'
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.e.EmbeddedEngine(run):846 - Stopping the task and engine
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.c.c.BaseSourceTask(stop):238 - Stopping down connector
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.c.p.c.PostgresConnection(readReplicationSlotInfo):251 - Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=LSN{B4D/60EEA8C0}, catalogXmin=239486]
2022-06-30 15:22:42 source > 2022-06-30 15:22:42 INFO i.d.j.JdbcConnection(lambda$doClose$3):956 - Connection gracefully closed
2022-06-30 15:22:43 source > 2022-06-30 15:22:43 INFO i.d.u.Threads(threadFactory):270 - Requested thread factory for connector PostgresConnector, id = airbyte_cdc_test_source_history named = keep-alive
2022-06-30 15:22:43 source > 2022-06-30 15:22:43 INFO i.d.u.Threads$3(newThread):287 - Creating thread debezium-postgresconnector-airbyte_cdc_test_source_history-keep-alive
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.c.p.PostgresSchema(printReplicaIdentityInfo):103 - REPLICA IDENTITY for 'history.hist_table1' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.c.p.PostgresStreamingChangeEventSource(searchWalPosition):314 - Searching for WAL resume position
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.c.p.PostgresStreamingChangeEventSource(searchWalPosition):335 - WAL resume position 'null' discovered
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.j.JdbcConnection(lambda$doClose$3):956 - Connection gracefully closed
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.u.Threads(threadFactory):270 - Requested thread factory for connector PostgresConnector, id = airbyte_cdc_test_source_history named = keep-alive
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.u.Threads$3(newThread):287 - Creating thread debezium-postgresconnector-airbyte_cdc_test_source_history-keep-alive
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.c.p.PostgresStreamingChangeEventSource(processMessages):202 - Processing messages
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.j.JdbcConnection(lambda$doClose$3):956 - Connection gracefully closed
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.p.ChangeEventSourceCoordinator(streamEvents):175 - Finished streaming
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.p.ChangeEventSourceCoordinator(streamingConnected):234 - Connected metrics set to 'false'
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.j.JdbcConnection(lambda$doClose$3):956 - Connection gracefully closed
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.d.j.JdbcConnection(lambda$doClose$3):956 - Connection gracefully closed
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.a.i.d.i.DebeziumRecordPublisher(lambda$start$1):85 - Debezium engine shutdown.
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.a.i.s.p.PostgresCdcStateHandler(saveState):32 - debezium state: {"{\"schema\":null,\"payload\":[\"airbyte_cdc_test_source_history\",{\"server\":\"airbyte_cdc_test_source_history\"}]}":"{\"last_snapshot_record\":true,\"lsn\":12856774262784,\"txId\":429223,\"ts_usec\":1656602561804000,\"snapshot\":true}"}
2022-06-30 15:22:44 INFO i.a.v.j.JsonSchemaValidator(test):56 - JSON schema validation failed. 
errors: $.state.global.shared_state: is not defined in the schema and the schema does not allow additional properties, $.state.global.stream_states: is not defined in the schema and the schema does not allow additional properties
2022-06-30 15:22:44 ERROR i.a.w.i.DefaultAirbyteStreamFactory(lambda$create$1):70 - Validation failed: {"type":"STATE","state":{"type":"GLOBAL","global":{"shared_state":{"state":{"{\"schema\":null,\"payload\":[\"airbyte_cdc_test_source_history\",{\"server\":\"airbyte_cdc_test_source_history\"}]}":"{\"last_snapshot_record\":true,\"lsn\":12856774262784,\"txId\":429223,\"ts_usec\":1656602561804000,\"snapshot\":true}"}},"stream_states":[{"stream_descriptor":{"name":"hist_table1","namespace":"history"},"stream_state":{"stream_name":"hist_table1","stream_namespace":"history","cursor_field":[]}}]},"data":{"cdc":true,"cdc_state":{"state":{"{\"schema\":null,\"payload\":[\"airbyte_cdc_test_source_history\",{\"server\":\"airbyte_cdc_test_source_history\"}]}":"{\"last_snapshot_record\":true,\"lsn\":12856774262784,\"txId\":429223,\"ts_usec\":1656602561804000,\"snapshot\":true}"}},"streams":[{"stream_name":"hist_table1","stream_namespace":"history","cursor_field":[]}]}}}
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.a.i.s.r.AbstractDbSource(lambda$read$2):139 - Closing database connection pool.
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO c.z.h.HikariDataSource(close):350 - HikariPool-2 - Shutdown initiated...
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO c.z.h.HikariDataSource(close):352 - HikariPool-2 - Shutdown completed.
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.a.i.s.r.AbstractDbSource(lambda$read$2):141 - Closed database connection pool.
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.a.i.b.IntegrationRunner(runInternal):171 - Completed integration: io.airbyte.integrations.base.ssh.SshWrappedSource
2022-06-30 15:22:44 source > 2022-06-30 15:22:44 INFO i.a.i.b.a.AdaptiveSourceRunner$Runner(run):87 - Completed source: io.airbyte.integrations.base.ssh.SshWrappedSource
2022-06-30 15:22:44 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):337 - Source has no more messages, closing connection.
2022-06-30 15:22:44 INFO i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$6):345 - Total records read: 4 (512 bytes)
2022-06-30 15:22:44 WARN i.a.w.g.DefaultReplicationWorker(lambda$getReplicationRunnable$5):348 - 4 schema validation errors found for stream history-hist_table1. Error message: Record schema validation failed for history-hist_table1. Expected schema: {"type":"object","properties":{"id":{"type":"number"},"column1":{"type":"string"},"_ab_cdc_lsn":{"type":"number"},"_ab_cdc_deleted_at":{"type":"string"},"_ab_cdc_updated_at":{"type":"string"}},"$schema":"http://json-schema.org/draft-07/schema#"}
2022-06-30 15:22:44 INFO i.a.w.g.DefaultReplicationWorker(run):171 - One of source or destination thread complete. Waiting on the other.
2022-06-30 15:22:44 destination > 2022-06-30 15:22:44 INFO i.a.i.b.FailureTrackingAirbyteMessageConsumer(close):65 - Airbyte message consumer: succeeded.
2022-06-30 15:22:44 destination > 2022-06-30 15:22:44 INFO i.a.i.d.b.BufferedStreamConsumer(close):170 - executing on success close procedure.
2022-06-30 15:22:44 destination > 2022-06-30 15:22:44 INFO i.a.i.d.r.InMemoryRecordBufferingStrategy(lambda$flushAll$1):84 - Flushing hist_table1: 4 records (2 KB)
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.SqlOperations(onDestinationCloseOperations):138 - No onDestinationCloseOperations required for this destination.
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):163 - Finalizing tables in destination started for 1 streams
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):168 - Finalizing stream hist_table1. schema history, tmp table _airbyte_tmp_hpv_hist_table1, final table _airbyte_raw_hist_table1
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):181 - Executing finalization of tables.
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):183 - Finalizing tables in destination completed.
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):186 - Cleaning tmp tables in destination started for 1 streams
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):190 - Cleaning tmp table in destination started for stream hist_table1. schema history, tmp table name: _airbyte_tmp_hpv_hist_table1
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.j.JdbcBufferedConsumerFactory(lambda$onCloseFunction$3):195 - Cleaning tmp tables in destination completed.
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.b.IntegrationRunner(runInternal):171 - Completed integration: io.airbyte.integrations.base.ssh.SshWrappedDestination
2022-06-30 15:22:45 destination > 2022-06-30 15:22:45 INFO i.a.i.d.p.PostgresDestination(main):92 - completed destination: class io.airbyte.integrations.destination.postgres.PostgresDestination
2022-06-30 15:22:45 INFO i.a.w.g.DefaultReplicationWorker(run):173 - Source and destination threads complete.
2022-06-30 15:22:45 INFO i.a.w.g.DefaultReplicationWorker(run):236 - sync summary: io.airbyte.config.ReplicationAttemptSummary@4c42001c[status=completed,recordsSynced=4,bytesSynced=512,startTime=1656602549119,endTime=1656602565455,totalStats=io.airbyte.config.SyncStats@2727c329[recordsEmitted=4,bytesEmitted=512,stateMessagesEmitted=0,recordsCommitted=4],streamStats=[io.airbyte.config.StreamSyncStats@6ad5c435[streamName=hist_table1,stats=io.airbyte.config.SyncStats@653b1665[recordsEmitted=4,bytesEmitted=512,stateMessagesEmitted=<null>,recordsCommitted=4]]]]
2022-06-30 15:22:45 INFO i.a.w.g.DefaultReplicationWorker(run):265 - Source did not output any state messages
2022-06-30 15:22:45 WARN i.a.w.g.DefaultReplicationWorker(run):273 - State capture: No new state, falling back on input state: io.airbyte.config.State@39a5a83e[state={}]
2022-06-30 15:22:45 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling...
2022-06-30 15:22:45 INFO i.a.w.t.s.ReplicationActivityImpl(lambda$replicate$3):157 - sync summary: io.airbyte.config.StandardSyncOutput@528bb2e4[standardSyncSummary=io.airbyte.config.StandardSyncSummary@178926d1[status=completed,recordsSynced=4,bytesSynced=512,startTime=1656602549119,endTime=1656602565455,totalStats=io.airbyte.config.SyncStats@2727c329[recordsEmitted=4,bytesEmitted=512,stateMessagesEmitted=0,recordsCommitted=4],streamStats=[io.airbyte.config.StreamSyncStats@6ad5c435[streamName=hist_table1,stats=io.airbyte.config.SyncStats@653b1665[recordsEmitted=4,bytesEmitted=512,stateMessagesEmitted=<null>,recordsCommitted=4]]]],normalizationSummary=<null>,state=io.airbyte.config.State@39a5a83e[state={}],outputCatalog=io.airbyte.protocol.models.ConfiguredAirbyteCatalog@51f0f2cd[streams=[io.airbyte.protocol.models.ConfiguredAirbyteStream@26545765[stream=io.airbyte.protocol.models.AirbyteStream@29c7ddd9[name=hist_table1,jsonSchema={"type":"object","properties":{"id":{"type":"number"},"column1":{"type":"string"},"_ab_cdc_lsn":{"type":"number"},"_ab_cdc_deleted_at":{"type":"string"},"_ab_cdc_updated_at":{"type":"string"}}},supportedSyncModes=[full_refresh, incremental],sourceDefinedCursor=true,defaultCursorField=[],sourceDefinedPrimaryKey=[[id]],namespace=history,additionalProperties={}],syncMode=incremental,cursorField=[],destinationSyncMode=append,primaryKey=[[id]],additionalProperties={}]],additionalProperties={}],failures=[]]
2022-06-30 15:22:45 INFO i.a.w.t.TemporalUtils(withBackgroundHeartbeat):236 - Stopping temporal heartbeating...
2022-06-30 15:22:45 INFO i.a.c.p.ConfigRepository(updateConnectionState):775 - Updating connection ff907196-c23e-45d3-8de5-ac9365f693cf state: io.airbyte.config.State@257daf05[state={}]
2022-06-30 15:22:45 INFO i.a.w.t.TemporalAttemptExecution(get):108 - Docker volume job log path: /tmp/workspace/1615/0/logs.log
2022-06-30 15:22:45 INFO i.a.w.t.TemporalAttemptExecution(get):113 - Executing worker wrapper. Airbyte version: 0.39.5-alpha
2022-06-30 15:22:45 INFO i.a.w.g.DefaultNormalizationWorker(run):49 - Running normalization.
2022-06-30 15:22:45 INFO i.a.w.n.DefaultNormalizationRunner(runProcess):122 - Running with normalization version: airbyte/normalization:0.2.1
2022-06-30 15:22:45 INFO i.a.c.i.LineGobbler(voidCall):82 - Checking if airbyte/normalization:0.2.1 exists...
2022-06-30 15:22:45 INFO i.a.c.i.LineGobbler(voidCall):82 - airbyte/normalization:0.2.1 was found locally.
2022-06-30 15:22:45 INFO i.a.w.p.DockerProcessFactory(create):108 - Creating docker job ID: 1615
2022-06-30 15:22:45 INFO i.a.w.p.DockerProcessFactory(create):163 - Preparing command: docker run --rm --init -i -w /data/1615/0/normalize --log-driver none --name normalization-normalize-1615-0-fkzrp --network host -v airbyte_workspace:/data -v /tmp/airbyte_local:/local -e AIRBYTE_ROLE= -e WORKER_ENVIRONMENT=DOCKER -e AIRBYTE_VERSION=0.39.5-alpha airbyte/normalization:0.2.1 run --integration-type postgres --config destination_config.json --catalog destination_catalog.json
2022-06-30 15:22:46 normalization > Running: transform-config --config destination_config.json --integration-type postgres --out /data/1615/0/normalize
2022-06-30 15:22:46 normalization > Namespace(config='destination_config.json', integration_type=<DestinationType.POSTGRES: 'postgres'>, out='/data/1615/0/normalize')
2022-06-30 15:22:46 normalization > transform_postgres
2022-06-30 15:22:46 normalization > Running: transform-catalog --integration-type postgres --profile-config-dir /data/1615/0/normalize --catalog destination_catalog.json --out /data/1615/0/normalize/models/generated/ --json-column _airbyte_data
2022-06-30 15:22:47 normalization > Processing destination_catalog.json...
2022-06-30 15:22:47 normalization >   Generating airbyte_ctes/history/hist_table1_ab1.sql from hist_table1
2022-06-30 15:22:47 normalization >   Generating airbyte_ctes/history/hist_table1_ab2.sql from hist_table1
2022-06-30 15:22:47 normalization >   Generating airbyte_ctes/history/hist_table1_ab3.sql from hist_table1
2022-06-30 15:22:47 normalization >   Generating airbyte_incremental/history/hist_table1.sql from hist_table1
2022-06-30 15:22:47 normalization > detected no config file for ssh, assuming ssh is off.
2022-06-30 15:22:50 normalization >            [--event-buffer-size EVENT_BUFFER_SIZE]
2022-06-30 15:22:50 normalization >   --event-buffer-size EVENT_BUFFER_SIZE
2022-06-30 15:22:50 normalization > 
2022-06-30 15:22:50 normalization > DBT >=1.0.0 detected; using 10K event buffer size
2022-06-30 15:22:50 normalization > 
2022-06-30 15:22:53 normalization > 15:22:53  Running with dbt=1.0.0
2022-06-30 15:22:53 normalization > 15:22:53  Partial parse save file not found. Starting full parse.
2022-06-30 15:22:54 normalization > 15:22:54  [WARNING]: Configuration paths exist in your dbt_project.yml file which do not apply to any resources.
2022-06-30 15:22:54 normalization > There are 2 unused configuration paths:
2022-06-30 15:22:54 normalization > - models.airbyte_utils.generated.airbyte_tables
2022-06-30 15:22:54 normalization > - models.airbyte_utils.generated.airbyte_views
2022-06-30 15:22:54 normalization > 
2022-06-30 15:22:54 normalization > 15:22:54  Found 4 models, 0 tests, 0 snapshots, 0 analyses, 521 macros, 0 operations, 0 seed files, 1 source, 0 exposures, 0 metrics
2022-06-30 15:22:54 normalization > 15:22:54  
2022-06-30 15:22:57 normalization > 15:22:57  Concurrency: 8 threads (target='prod')
2022-06-30 15:22:57 normalization > 15:22:57  
2022-06-30 15:22:59 normalization > 15:22:59  1 of 1 START incremental model history.hist_table1...................................................................... [RUN]
2022-06-30 15:23:01 normalization > 15:23:01  1 of 1 OK created incremental model history.hist_table1................................................................. [INSERT 0 4 in 1.76s]
2022-06-30 15:23:02 normalization > 15:23:02  
2022-06-30 15:23:02 normalization > 15:23:02  Finished running 1 incremental model in 7.46s.
2022-06-30 15:23:02 normalization > 15:23:02  
2022-06-30 15:23:02 normalization > 15:23:02  Completed successfully
2022-06-30 15:23:02 normalization > 15:23:02  
2022-06-30 15:23:02 normalization > 15:23:02  Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
2022-06-30 15:23:02 INFO i.a.w.g.DefaultNormalizationWorker(run):73 - Normalization executed in 16 seconds.
2022-06-30 15:23:02 INFO i.a.w.g.DefaultNormalizationWorker(run):79 - Normalization summary: io.airbyte.config.NormalizationSummary@38159424[startTime=1656602565551,endTime=1656602582430]
2022-06-30 15:23:02 INFO i.a.w.t.TemporalAttemptExecution(get):134 - Stopping cancellation check scheduling...
2022-06-30 15:23:02 INFO i.a.w.t.TemporalUtils(withBackgroundHeartbeat):236 - Stopping temporal heartbeating...