Logging for custom connectors broken after upgrade - hanging/not logging after "Starting a new buffer for stream" #28830

luke-oa · 2023-07-28T15:49:51Z

luke-oa
Jul 28, 2023

We're recently upgraded our Airbyte deployment (via Kubernetes and Helm) from 0.40.29 to 0.50.6. After upgrade, I've noticed that our custom connectors stop logging if we start a new stream buffer. The pods still run in the background, and if left alone they still finish after awhile; however, after starting the new buffer, the source never logs again, and the normalization logs incorrectly (formatting is off - no green highlighting).

This appears to have come up in discussion (without resolution) here and as a GH issue (without resolution except the classic "upgrade" motto) here.

Here's an example log (note the jump from 20:45 to 04:06 - nearly 8 hours where things should have been logging but nothing came through):

2023-07-27 20:43:58 INFO i.a.a.c.AirbyteApiClient(retryWithJitterThrows):229 - Attempt 0 to get state
2023-07-27 20:44:12 destination > Running destination under deployment mode: OSS
2023-07-27 20:43:58 INFO i.a.w.h.NormalizationInDestinationHelper(shouldNormalizeInDestination):52 - Requires Normalization: true, Normalization Supported: false, Feature Flag Enabled: false
2023-07-27 20:43:58 INFO i.a.a.c.AirbyteApiClient(retryWithJitterThrows):229 - Attempt 0 to set attempt sync config
2023-07-27 20:43:59 INFO i.a.c.t.s.DefaultTaskQueueMapper(getTaskQueue):31 - Called DefaultTaskQueueMapper getTaskQueue for geography auto
2023-07-27 20:44:05 INFO i.a.w.t.TemporalAttemptExecution(get):138 - Cloud storage job log path: /workspace/24760/0/logs.log
2023-07-27 20:44:05 INFO i.a.w.t.TemporalAttemptExecution(get):141 - Executing worker wrapper. Airbyte version: 0.50.6
2023-07-27 20:44:05 INFO i.a.a.c.AirbyteApiClient(retryWithJitterThrows):229 - Attempt 0 to save workflow id for cancellation
2023-07-27 20:44:05 INFO i.a.a.c.AirbyteApiClient(retryWithJitterThrows):229 - Attempt 0 to get the source definition for feature flag checks
2023-07-27 20:44:05 INFO i.a.a.c.AirbyteApiClient(retryWithJitterThrows):229 - Attempt 0 to get the source definition
2023-07-27 20:44:05 INFO i.a.w.g.ReplicationWorkerFactory(maybeEnableConcurrentStreamReads):166 - Concurrent stream read enabled? false
2023-07-27 20:44:05 INFO i.a.w.g.ReplicationWorkerFactory(create):127 - Setting up source...
2023-07-27 20:44:05 INFO i.a.w.g.ReplicationWorkerFactory(create):134 - Setting up destination...
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable METRIC_CLIENT: ''
2023-07-27 20:44:05 WARN i.a.m.l.MetricClientFactory(initialize):60 - Metric client is already initialized to 
2023-07-27 20:44:05 INFO i.a.w.g.ReplicationWorkerFactory(create):146 - Setting up replication worker...
2023-07-27 20:44:05 INFO i.a.w.g.DefaultReplicationWorker(run):124 - start sync worker. job id: 24760 attempt id: 0
2023-07-27 20:44:05 INFO i.a.w.g.DefaultReplicationWorker(run):129 - configured sync modes: {null.associations__associationGlAccounts=full_refresh - overwrite, null.accounting__glTransactionsByDateAndAssocCode=incremental - append_dedup, null.accounting__glPreviousBalanceAsOfADate=incremental - append_dedup, null.associations=full_refresh - overwrite}
2023-07-27 20:44:05 INFO i.a.c.i.LineGobbler(voidCall):149 - 
2023-07-27 20:44:05 INFO i.a.c.i.LineGobbler(voidCall):149 - ----- START REPLICATION -----
2023-07-27 20:44:05 INFO i.a.w.i.DefaultAirbyteDestination(start):88 - Running destination...
2023-07-27 20:44:05 INFO i.a.c.i.LineGobbler(voidCall):149 - 
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SIDECAR_KUBE_CPU_LIMIT: '2.0'
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SOCAT_KUBE_CPU_LIMIT: '2.0'
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SIDECAR_KUBE_CPU_REQUEST: '0.1'
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SOCAT_KUBE_CPU_REQUEST: '0.1'
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable LAUNCHDARKLY_KEY: ''
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable FEATURE_FLAG_CLIENT: ''
2023-07-27 20:44:05 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable OTEL_COLLECTOR_ENDPOINT: ''
2023-07-27 20:44:05 INFO i.a.w.p.KubeProcessFactory(create):107 - Attempting to start pod = destination-snowflake-write-24760-0-ivalf for airbyte/destination-snowflake:0.4.44 with resources io.airbyte.config.ResourceRequirements@60e340a2[cpuRequest=,cpuLimit=,memoryRequest=4Gi,memoryLimit=8Gi,additionalProperties={}] and allowedHosts null
2023-07-27 20:44:05 INFO i.a.w.p.KubeProcessFactory(create):111 - destination-snowflake-write-24760-0-ivalf stdoutLocalPort = 9027
2023-07-27 20:44:05 INFO i.a.w.p.KubeProcessFactory(create):114 - destination-snowflake-write-24760-0-ivalf stderrLocalPort = 9030
2023-07-27 20:44:05 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$11):658 - Creating stdout socket server...
2023-07-27 20:44:05 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$12):676 - Creating stderr socket server...
2023-07-27 20:44:05 INFO i.a.w.p.KubePodProcess(<init>):584 - Creating pod destination-snowflake-write-24760-0-ivalf...
2023-07-27 20:44:05 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):362 - Waiting for init container to be ready before copying files...
2023-07-27 20:44:05 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):366 - Init container present..
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):369 - Init container ready..
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(<init>):615 - Copying files...
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: destination_config.json
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/1a7e4252-be47-46b5-97d3-d6cbfff3ba6d/destination_config.json default/destination-snowflake-write-24760-0-ivalf:/config/destination_config.json -c init
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: destination_catalog.json
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/b5c5cb73-aa8a-451e-a903-f212b3bc35b2/destination_catalog.json default/destination-snowflake-write-24760-0-ivalf:/config/destination_catalog.json -c init
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: FINISHED_UPLOADING
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/368665f0-ed37-4f70-8fda-26d2cbff5af1/FINISHED_UPLOADING default/destination-snowflake-write-24760-0-ivalf:/config/FINISHED_UPLOADING -c init
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-27 20:44:07 INFO i.a.w.p.KubePodProcess(<init>):618 - Waiting until pod is ready...
2023-07-27 20:44:08 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$11):667 - Setting stdout...
2023-07-27 20:44:08 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$12):679 - Setting stderr...
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(<init>):634 - Reading pod IP...
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(<init>):636 - Pod IP: 10.226.4.12
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(<init>):639 - Creating stdin socket...
2023-07-27 20:44:09 INFO i.a.w.i.VersionedAirbyteMessageBufferedWriterFactory(createWriter):41 - Writing messages to protocol version 0.2.0
2023-07-27 20:44:09 INFO i.a.w.i.VersionedAirbyteStreamFactory(create):177 - Reading messages from protocol version 0.2.0
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SIDECAR_KUBE_CPU_LIMIT: '2.0'
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SOCAT_KUBE_CPU_LIMIT: '2.0'
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SIDECAR_KUBE_CPU_REQUEST: '0.1'
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable SOCAT_KUBE_CPU_REQUEST: '0.1'
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable LAUNCHDARKLY_KEY: ''
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable FEATURE_FLAG_CLIENT: ''
2023-07-27 20:44:09 INFO i.a.c.EnvConfigs(getEnvOrDefault):1228 - Using default value for environment variable OTEL_COLLECTOR_ENDPOINT: ''
2023-07-27 20:44:09 INFO i.a.w.p.KubeProcessFactory(create):107 - Attempting to start pod = source-<source_name>-read-24760-0-zzitk for 904206145054.dkr.ecr.us-east-1.amazonaws.com/source-<source_name>:0.0.0-20230727185007-79b9d68 with resources io.airbyte.config.ResourceRequirements@5fab527f[cpuRequest=0.5,cpuLimit=,memoryRequest=4Gi,memoryLimit=8Gi,additionalProperties={}] and allowedHosts null
2023-07-27 20:44:09 INFO i.a.w.p.KubeProcessFactory(create):111 - source-<source_name>-read-24760-0-zzitk stdoutLocalPort = 9034
2023-07-27 20:44:09 INFO i.a.w.p.KubeProcessFactory(create):114 - source-<source_name>-read-24760-0-zzitk stderrLocalPort = 9035
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$11):658 - Creating stdout socket server...
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$12):676 - Creating stderr socket server...
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(<init>):584 - Creating pod source-<source_name>-read-24760-0-zzitk...
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):362 - Waiting for init container to be ready before copying files...
2023-07-27 20:44:09 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):366 - Init container present..
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):369 - Init container ready..
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(<init>):615 - Copying files...
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: source_config.json
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/1c66cb78-47bd-48a9-84a8-4746057572be/source_config.json default/source-<source_name>-read-24760-0-zzitk:/config/source_config.json -c init
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: source_catalog.json
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/12dac5fe-5241-442a-8cad-cf8cb66b107d/source_catalog.json default/source-<source_name>-read-24760-0-zzitk:/config/source_catalog.json -c init
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: FINISHED_UPLOADING
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/c1bde62d-9e11-4213-a04f-144e33550abc/FINISHED_UPLOADING default/source-<source_name>-read-24760-0-zzitk:/config/FINISHED_UPLOADING -c init
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-27 20:44:10 INFO i.a.w.p.KubePodProcess(<init>):618 - Waiting until pod is ready...
2023-07-27 20:44:11 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$11):667 - Setting stdout...
2023-07-27 20:44:11 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$12):679 - Setting stderr...
2023-07-27 20:44:12 INFO i.a.w.p.KubePodProcess(<init>):634 - Reading pod IP...
2023-07-27 20:44:12 INFO i.a.w.p.KubePodProcess(<init>):636 - Pod IP: 10.226.5.248
2023-07-27 20:44:12 INFO i.a.w.p.KubePodProcess(<init>):643 - Using null stdin output stream...
2023-07-27 20:44:12 INFO i.a.w.i.VersionedAirbyteStreamFactory(create):177 - Reading messages from protocol version 0.2.0
2023-07-27 20:44:12 INFO i.a.w.g.DefaultReplicationWorker(lambda$readFromDstRunnable$4):224 - Destination output thread started.
2023-07-27 20:44:12 INFO i.a.w.i.HeartbeatTimeoutChaperone(runWithHeartbeatThread):94 - Starting source heartbeat check. Will check every 1 minutes.
2023-07-27 20:44:12 INFO i.a.w.g.DefaultReplicationWorker(lambda$readFromSrcAndWriteToDstRunnable$5):268 - Replication thread started.
2023-07-27 20:44:12 destination > Starting destination: io.airbyte.integrations.destination.snowflake.SnowflakeDestination
2023-07-27 20:44:12 destination > integration args: {catalog=destination_catalog.json, write=null, config=destination_config.json}
2023-07-27 20:44:12 destination > Running integration: io.airbyte.integrations.destination.snowflake.SnowflakeDestination
2023-07-27 20:44:12 destination > Command: WRITE
2023-07-27 20:44:12 destination > Integration config: IntegrationConfig{command=WRITE, configPath='destination_config.json', catalogPath='destination_catalog.json', statePath='null'}
2023-07-27 20:44:12 destination > Unknown keyword order - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2023-07-27 20:44:12 destination > Unknown keyword airbyte_secret - you should define your own Meta Schema. If the keyword is irrelevant for validation, just use a NonValidationKeyword
2023-07-27 20:44:12 destination > Using destination type: INTERNAL_STAGING
2023-07-27 20:44:12 destination > Write config: WriteConfig{streamName=accounting__glPreviousBalanceAsOfADate, namespace=<client_name>_<source_name>, outputSchemaName=<client_name>_<source_name>, tmpTableName=_airbyte_tmp_myw_accounting__glPreviousBalanceAsOfADate, outputTableName=_airbyte_raw_accounting__glPreviousBalanceAsOfADate, syncMode=append_dedup}
2023-07-27 20:44:12 destination > Write config: WriteConfig{streamName=accounting__glTransactionsByDateAndAssocCode, namespace=<client_name>_<source_name>, outputSchemaName=<client_name>_<source_name>, tmpTableName=_airbyte_tmp_zqn_accounting__glTransactionsByDateAndAssocCode, outputTableName=_airbyte_raw_accounting__glTransactionsByDateAndAssocCode, syncMode=append_dedup}
2023-07-27 20:44:12 destination > Write config: WriteConfig{streamName=associations, namespace=<client_name>_<source_name>, outputSchemaName=<client_name>_<source_name>, tmpTableName=_airbyte_tmp_szg_associations, outputTableName=_airbyte_raw_associations, syncMode=overwrite}
2023-07-27 20:44:12 destination > Write config: WriteConfig{streamName=associations__associationGlAccounts, namespace=<client_name>_<source_name>, outputSchemaName=<client_name>_<source_name>, tmpTableName=_airbyte_tmp_bvl_associations__associationGlAccounts, outputTableName=_airbyte_raw_associations__associationGlAccounts, syncMode=overwrite}
2023-07-27 20:44:12 destination > class io.airbyte.integrations.destination.buffered_stream_consumer.BufferedStreamConsumer started.
2023-07-27 20:44:12 destination > Preparing tmp tables in destination started for 4 streams
2023-07-27 20:44:12 destination > Preparing staging area in destination started for schema <client_name>_<source_name> stream accounting__glPreviousBalanceAsOfADate: tmp table: _airbyte_tmp_myw_accounting__glPreviousBalanceAsOfADate, stage: 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/
2023-07-27 20:44:12 destination > HikariPool-1 - Starting...
2023-07-27 20:44:12 destination > HikariPool-1 - Added connection net.snowflake.client.jdbc.SnowflakeConnectionV1@6a0f2853
2023-07-27 20:44:12 destination > HikariPool-1 - Start completed.
2023-07-27 20:44:12 destination > closing connection
2023-07-27 20:44:12 destination > Preparing staging area in destination completed for schema <client_name>_<source_name> stream accounting__glPreviousBalanceAsOfADate
2023-07-27 20:44:12 destination > Preparing staging area in destination started for schema <client_name>_<source_name> stream accounting__glTransactionsByDateAndAssocCode: tmp table: _airbyte_tmp_zqn_accounting__glTransactionsByDateAndAssocCode, stage: 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/
2023-07-27 20:44:12 destination > closing connection
2023-07-27 20:44:12 destination > Preparing staging area in destination completed for schema <client_name>_<source_name> stream accounting__glTransactionsByDateAndAssocCode
2023-07-27 20:44:12 destination > Preparing staging area in destination started for schema <client_name>_<source_name> stream associations: tmp table: _airbyte_tmp_szg_associations, stage: 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/
2023-07-27 20:44:12 destination > closing connection
2023-07-27 20:44:12 destination > Preparing staging area in destination completed for schema <client_name>_<source_name> stream associations
2023-07-27 20:44:12 destination > Preparing staging area in destination started for schema <client_name>_<source_name> stream associations__associationGlAccounts: tmp table: _airbyte_tmp_bvl_associations__associationGlAccounts, stage: 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/
2023-07-27 20:44:12 destination > closing connection
2023-07-27 20:44:12 destination > Preparing staging area in destination completed for schema <client_name>_<source_name> stream associations__associationGlAccounts
2023-07-27 20:44:12 destination > Preparing tmp tables in destination completed.
2023-07-27 20:44:12 source > Starting syncing Source<source_name>
2023-07-27 20:44:12 source > Using user defined config for stream "accounting__glPreviousBalanceAsOfADate"
2023-07-27 20:44:12 source > Using user defined config for stream "accounting__glTransactionsByDateAndAssocCode"
2023-07-27 20:44:12 source > Using user defined config for stream "associations"
2023-07-27 20:44:12 source > Using user defined config for stream "associations__associationGlAccounts"
2023-07-27 20:44:12 source > Using user defined config for stream "accounting__glTransactionsByDateAndAssocCode"
2023-07-27 20:44:12 source > Using user defined config for stream "associations__associationGlAccounts"
2023-07-27 20:44:12 source > Using user defined config for stream "accounting__glPreviousBalanceAsOfADate"
2023-07-27 20:44:12 source > Marking stream accounting__glPreviousBalanceAsOfADate as STARTED
2023-07-27 20:45:28 destination > Starting a new buffer for stream accounting__glPreviousBalanceAsOfADate (current state: 0 bytes in 0 buffers)
2023-07-28 04:06:24 destination > Starting a new buffer for stream accounting__glTransactionsByDateAndAssocCode (current state: 1 MB in 1 buffers)
2023-07-28 04:08:18 destination > Starting a new buffer for stream associations (current state: 3 MB in 2 buffers)
2023-07-28 04:08:18 destination > Starting a new buffer for stream associations__associationGlAccounts (current state: 3 MB in 3 buffers)
2023-07-28 04:08:26 INFO i.a.w.i.HeartbeatTimeoutChaperone(runWithHeartbeatThread):111 - thread status... heartbeat thread: false , replication thread: true
2023-07-28 04:08:26 destination > Airbyte message consumer: succeeded.
2023-07-28 04:08:26 destination > executing on success close procedure.
2023-07-28 04:08:26 destination > Flushing all 4 current buffers (5 MB in total)
2023-07-28 04:08:26 destination > Flushing buffer of stream accounting__glTransactionsByDateAndAssocCode (2 MB)
2023-07-28 04:08:26 destination > Flushing buffer for stream accounting__glTransactionsByDateAndAssocCode (2 MB) to staging
2023-07-28 04:08:26 destination > Wrapping up compression and write GZIP trailer data.
2023-07-28 04:08:26 destination > Finished writing data to 88cca5f8-0ab8-4f6b-9869-69c4bf751d1b5873114889789443610.csv.gz (2 MB)
2023-07-28 04:08:27 destination > closing connection
2023-07-28 04:08:27 destination > Deleting tempFile data 88cca5f8-0ab8-4f6b-9869-69c4bf751d1b5873114889789443610.csv.gz
2023-07-28 04:08:27 destination > Flushing buffer of stream associations (39 KB)
2023-07-28 04:08:27 destination > Flushing buffer for stream associations (39 KB) to staging
2023-07-28 04:08:27 destination > Wrapping up compression and write GZIP trailer data.
2023-07-28 04:08:27 destination > Finished writing data to 1b05e293-87c5-4ecf-953b-31d2baedc5b13107643499949991273.csv.gz (46 KB)
2023-07-28 04:08:27 destination > closing connection
2023-07-28 04:08:27 destination > Deleting tempFile data 1b05e293-87c5-4ecf-953b-31d2baedc5b13107643499949991273.csv.gz
2023-07-28 04:08:27 destination > Flushing buffer of stream accounting__glPreviousBalanceAsOfADate (1 MB)
2023-07-28 04:08:27 destination > Flushing buffer for stream accounting__glPreviousBalanceAsOfADate (1 MB) to staging
2023-07-28 04:08:27 destination > Wrapping up compression and write GZIP trailer data.
2023-07-28 04:08:27 destination > Finished writing data to ea0294c1-4a1b-44ec-bb03-6624605d914b13639481700872765639.csv.gz (1 MB)
2023-07-28 04:08:28 destination > closing connection
2023-07-28 04:08:28 destination > Deleting tempFile data ea0294c1-4a1b-44ec-bb03-6624605d914b13639481700872765639.csv.gz
2023-07-28 04:08:28 destination > Flushing buffer of stream associations__associationGlAccounts (2 MB)
2023-07-28 04:08:28 destination > Flushing buffer for stream associations__associationGlAccounts (2 MB) to staging
2023-07-28 04:08:28 destination > Wrapping up compression and write GZIP trailer data.
2023-07-28 04:08:28 destination > Finished writing data to 092dba81-5496-4727-adce-cf419a05024114056699556199786783.csv.gz (2 MB)
2023-07-28 04:08:28 destination > closing connection
2023-07-28 04:08:28 destination > Deleting tempFile data 092dba81-5496-4727-adce-cf419a05024114056699556199786783.csv.gz
2023-07-28 04:08:28 destination > Closing buffer for stream accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:28 destination > Closing buffer for stream associations
2023-07-28 04:08:28 destination > Closing buffer for stream accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:28 destination > Closing buffer for stream associations__associationGlAccounts
2023-07-28 04:08:28 destination > Copying into tables in destination started for 4 streams
2023-07-28 04:08:28 destination > Copying stream accounting__glPreviousBalanceAsOfADate of schema <client_name>_<source_name> into tmp table _airbyte_tmp_myw_accounting__glPreviousBalanceAsOfADate to final table _airbyte_raw_accounting__glPreviousBalanceAsOfADate from stage path 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/ with 1 file(s) [ea0294c1-4a1b-44ec-bb03-6624605d914b13639481700872765639.csv.gz]
2023-07-28 04:08:29 destination > Copying stream accounting__glTransactionsByDateAndAssocCode of schema <client_name>_<source_name> into tmp table _airbyte_tmp_zqn_accounting__glTransactionsByDateAndAssocCode to final table _airbyte_raw_accounting__glTransactionsByDateAndAssocCode from stage path 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/ with 1 file(s) [88cca5f8-0ab8-4f6b-9869-69c4bf751d1b5873114889789443610.csv.gz]
2023-07-28 04:08:31 destination > Copying stream associations of schema <client_name>_<source_name> into tmp table _airbyte_tmp_szg_associations to final table _airbyte_raw_associations from stage path 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/ with 1 file(s) [1b05e293-87c5-4ecf-953b-31d2baedc5b13107643499949991273.csv.gz]
2023-07-28 04:08:32 destination > Copying stream associations__associationGlAccounts of schema <client_name>_<source_name> into tmp table _airbyte_tmp_bvl_associations__associationGlAccounts to final table _airbyte_raw_associations__associationGlAccounts from stage path 2023/07/27/20/0B7E2B94-8556-4DEE-895B-857A49755A4A/ with 1 file(s) [092dba81-5496-4727-adce-cf419a05024114056699556199786783.csv.gz]
2023-07-28 04:08:34 destination > No onDestinationCloseOperations required for this destination.
2023-07-28 04:08:34 destination > Executing finalization of tables.
2023-07-28 04:08:38 destination > Finalizing tables in destination completed.
2023-07-28 04:08:38 destination > Cleaning up destination started for 4 streams
2023-07-28 04:08:38 destination > Cleaning tmp table in destination started for stream accounting__glPreviousBalanceAsOfADate. schema <client_name>_<source_name>, tmp table name: _airbyte_tmp_myw_accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:38 destination > Cleaning stage in destination started for stream accounting__glPreviousBalanceAsOfADate. schema <client_name>_<source_name>, stage: <client_name>_<source_name>_ACCOUNTING__GLPREVIOUSBALANCEASOFADATE
2023-07-28 04:08:38 destination > Cleaning tmp table in destination started for stream accounting__glTransactionsByDateAndAssocCode. schema <client_name>_<source_name>, tmp table name: _airbyte_tmp_zqn_accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:38 destination > Cleaning stage in destination started for stream accounting__glTransactionsByDateAndAssocCode. schema <client_name>_<source_name>, stage: <client_name>_<source_name>_ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE
2023-07-28 04:08:38 destination > Cleaning tmp table in destination started for stream associations. schema <client_name>_<source_name>, tmp table name: _airbyte_tmp_szg_associations
2023-07-28 04:08:38 destination > Cleaning stage in destination started for stream associations. schema <client_name>_<source_name>, stage: <client_name>_<source_name>_ASSOCIATIONS
2023-07-28 04:08:38 destination > Cleaning tmp table in destination started for stream associations__associationGlAccounts. schema <client_name>_<source_name>, tmp table name: _airbyte_tmp_bvl_associations__associationGlAccounts
2023-07-28 04:08:38 destination > Cleaning stage in destination started for stream associations__associationGlAccounts. schema <client_name>_<source_name>, stage: <client_name>_<source_name>_ASSOCIATIONS__ASSOCIATIONGLACCOUNTS
2023-07-28 04:08:39 destination > Cleaning up destination completed.
2023-07-28 04:08:59 normalization > Running: transform-config --config destination_config.json --integration-type snowflake --out /config
2023-07-28 04:08:59 normalization > Namespace(config='destination_config.json', integration_type=<DestinationType.SNOWFLAKE: 'snowflake'>, out='/config')
2023-07-28 04:08:59 normalization > transform_snowflake
2023-07-28 04:08:59 normalization > Running: transform-catalog --integration-type snowflake --profile-config-dir /config --catalog destination_catalog.json --out /config/models/generated/ --json-column _airbyte_data
2023-07-28 04:08:59 normalization > Processing destination_catalog.json...
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_AB1.sql from accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_AB2.sql from accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:59 normalization >   Generating airbyte_views/<client_name>_<source_name>/ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_STG.sql from accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:59 normalization >   Generating airbyte_incremental/scd/<client_name>_<source_name>/ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_SCD.sql from accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:59 normalization >   Generating airbyte_incremental/<client_name>_<source_name>/ACCOUNTING__GLPREVIOUSBALANCEASOFADATE.sql from accounting__glPreviousBalanceAsOfADate
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_AB1.sql from accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_AB2.sql from accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:59 normalization >   Generating airbyte_views/<client_name>_<source_name>/ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_STG.sql from accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:59 normalization >   Generating airbyte_incremental/scd/<client_name>_<source_name>/ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_SCD.sql from accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:59 normalization >   Generating airbyte_incremental/<client_name>_<source_name>/ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE.sql from accounting__glTransactionsByDateAndAssocCode
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ASSOCIATIONS_AB1.sql from associations
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ASSOCIATIONS_AB2.sql from associations
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ASSOCIATIONS_AB3.sql from associations
2023-07-28 04:08:59 normalization >   Adding drop table hook for ASSOCIATIONS_SCD to ASSOCIATIONS
2023-07-28 04:08:59 normalization >   Generating airbyte_tables/<client_name>_<source_name>/ASSOCIATIONS.sql from associations
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ASSOCIATIONS__ASSOCIATIONGLACCOUNTS_AB1.sql from associations__associationGlAccounts
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ASSOCIATIONS__ASSOCIATIONGLACCOUNTS_AB2.sql from associations__associationGlAccounts
2023-07-28 04:08:59 normalization >   Generating airbyte_ctes/<client_name>_<source_name>/ASSOCIATIONS__ASSOCIATIONGLACCOUNTS_AB3.sql from associations__associationGlAccounts
2023-07-28 04:08:59 normalization >   Adding drop table hook for ASSOCIATIONS__ASSOCIATIONGLACCOUNTS_SCD to ASSOCIATIONS__ASSOCIATIONGLACCOUNTS
2023-07-28 04:08:59 normalization >   Generating airbyte_tables/<client_name>_<source_name>/ASSOCIATIONS__ASSOCIATIONGLACCOUNTS.sql from associations__associationGlAccounts
2023-07-28 04:08:59 normalization > detected no config file for ssh, assuming ssh is off.
2023-07-28 04:09:00 normalization >            [--event-buffer-size EVENT_BUFFER_SIZE]
2023-07-28 04:09:00 normalization >   --event-buffer-size EVENT_BUFFER_SIZE
2023-07-28 04:09:00 normalization > DBT >=1.0.0 detected; using 10K event buffer size
2023-07-28 04:09:02 normalization > Running with dbt=1.0.0
2023-07-28 04:09:02 normalization > Partial parse save file not found. Starting full parse.
2023-07-28 04:09:04 normalization > Found 18 models, 0 tests, 0 snapshots, 0 analyses, 593 macros, 0 operations, 0 seed files, 4 sources, 0 exposures, 0 metrics
2023-07-28 04:09:05 normalization > Concurrency: 5 threads (target='prod')
2023-07-28 04:09:05 normalization > 1 of 8 START view model _AIRBYTE_<client_name>_<source_name>.ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_STG.............................. [RUN]
2023-07-28 04:09:05 normalization > 2 of 8 START view model _AIRBYTE_<client_name>_<source_name>.ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_STG........................ [RUN]
2023-07-28 04:09:06 normalization > 3 of 8 START table model <client_name>_<source_name>.ASSOCIATIONS__ASSOCIATIONGLACCOUNTS............................................. [RUN]
2023-07-28 04:09:06 normalization > 4 of 8 START table model <client_name>_<source_name>.ASSOCIATIONS.................................................................... [RUN]
2023-07-28 04:09:07 normalization > 1 of 8 OK created view model _AIRBYTE_<client_name>_<source_name>.ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_STG......................... [SUCCESS 1 in 1.24s]
2023-07-28 04:09:07 normalization > 5 of 8 START incremental model <client_name>_<source_name>.ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_SCD................................ [RUN]
2023-07-28 04:09:07 normalization > 2 of 8 OK created view model _AIRBYTE_<client_name>_<source_name>.ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_STG................... [SUCCESS 1 in 1.28s]
2023-07-28 04:09:07 normalization > 6 of 8 START incremental model <client_name>_<source_name>.ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_SCD.......................... [RUN]
2023-07-28 04:09:07 normalization > 04:09:07 + "AIRBYTE".<client_name>_<source_name>."ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_SCD"._AIRBYTE_AB_ID does not exist yet. The table will be created or rebuilt with dbt.full_refresh
2023-07-28 04:09:07 normalization > 04:09:07 + "AIRBYTE".<client_name>_<source_name>."ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_SCD"._AIRBYTE_AB_ID does not exist yet. The table will be created or rebuilt with dbt.full_refresh
2023-07-28 04:09:08 normalization > 4 of 8 OK created table model <client_name>_<source_name>.ASSOCIATIONS............................................................... [SUCCESS 1 in 2.07s]
2023-07-28 04:09:08 normalization > 3 of 8 OK created table model <client_name>_<source_name>.ASSOCIATIONS__ASSOCIATIONGLACCOUNTS........................................ [SUCCESS 1 in 2.68s]
2023-07-28 04:09:09 normalization > 5 of 8 OK created incremental model <client_name>_<source_name>.ACCOUNTING__GLPREVIOUSBALANCEASOFADATE_SCD........................... [SUCCESS 1 in 2.78s]
2023-07-28 04:09:09 normalization > 7 of 8 START incremental model <client_name>_<source_name>.ACCOUNTING__GLPREVIOUSBALANCEASOFADATE.................................... [RUN]
2023-07-28 04:09:12 normalization > 6 of 8 OK created incremental model <client_name>_<source_name>.ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE_SCD..................... [SUCCESS 1 in 4.97s]
2023-07-28 04:09:12 normalization > 8 of 8 START incremental model <client_name>_<source_name>.ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE.............................. [RUN]
2023-07-28 04:09:12 normalization > 7 of 8 OK created incremental model <client_name>_<source_name>.ACCOUNTING__GLPREVIOUSBALANCEASOFADATE............................... [SUCCESS 1 in 2.93s]
2023-07-28 04:09:15 normalization > 8 of 8 OK created incremental model <client_name>_<source_name>.ACCOUNTING__GLTRANSACTIONSBYDATEANDASSOCCODE......................... [SUCCESS 1 in 3.72s]
2023-07-28 04:09:15 normalization > Finished running 2 view models, 2 table models, 4 incremental models in 11.86s.
2023-07-28 04:09:15 normalization > Completed successfully
2023-07-28 04:09:15 normalization > Done. PASS=8 WARN=0 ERROR=0 SKIP=0 TOTAL=8
2023-07-28 04:08:26 INFO i.a.w.g.DefaultReplicationWorker(replicate):195 - Waiting for source and destination threads to complete.
2023-07-28 04:08:26 INFO i.a.w.g.DefaultReplicationWorker(replicate):200 - One of source or destination thread complete. Waiting on the other.
2023-07-28 04:08:39 INFO i.a.w.g.ReplicationWorkerHelper(processMessageFromDestination):219 - State in DefaultReplicationWorker from destination: io.airbyte.protocol.models.AirbyteMessage@11ddb964[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@5ef84a5b[type=STREAM,stream=io.airbyte.protocol.models.AirbyteStreamState@2dfa6fdc[streamDescriptor=io.airbyte.protocol.models.StreamDescriptor@3e45089b[name=accounting__glPreviousBalanceAsOfADate,namespace=<null>,additionalProperties={}],streamState={"AsOfDate":"2020-01-06"},additionalProperties={}],global=<null>,data={"accounting__glPreviousBalanceAsOfADate":{"AsOfDate":"2020-01-06"}},additionalProperties={}],trace=<null>,control=<null>,additionalProperties={}]
2023-07-28 04:08:55 INFO i.a.w.i.s.SyncPersistenceImpl(startBackgroundFlushStateTask):180 - starting state flush thread for connectionId 7e6c3ea1-6a35-476e-a6a4-a26fd679ec7d
2023-07-28 04:08:55 INFO i.a.w.g.ReplicationWorkerHelper(processMessageFromDestination):219 - State in DefaultReplicationWorker from destination: io.airbyte.protocol.models.AirbyteMessage@1b6b00eb[type=STATE,log=<null>,spec=<null>,connectionStatus=<null>,catalog=<null>,record=<null>,state=io.airbyte.protocol.models.AirbyteStateMessage@26305514[type=STREAM,stream=io.airbyte.protocol.models.AirbyteStreamState@337e577a[streamDescriptor=io.airbyte.protocol.models.StreamDescriptor@3adcfb61[name=accounting__glTransactionsByDateAndAssocCode,namespace=<null>,additionalProperties={}],streamState={"TransactionDate":"2020-01-06"},additionalProperties={}],global=<null>,data={"accounting__glPreviousBalanceAsOfADate":{"AsOfDate":"2020-01-06"},"accounting__glTransactionsByDateAndAssocCode":{"TransactionDate":"2020-01-06"}},additionalProperties={}],trace=<null>,control=<null>,additionalProperties={}]
2023-07-28 04:08:55 INFO i.a.w.g.DefaultReplicationWorker(replicate):202 - Source and destination threads complete.
2023-07-28 04:08:55 INFO i.a.w.t.TemporalAttemptExecution(get):163 - Stopping cancellation check scheduling...
2023-07-28 04:08:55 INFO i.a.w.t.s.ReplicationActivityImpl(lambda$replicate$3):160 - sync summary: io.airbyte.config.StandardSyncOutput@58ff5cbe[standardSyncSummary=io.airbyte.config.StandardSyncSummary@4c91f8b2[status=completed,recordsSynced=148864,bytesSynced=32525934,startTime=1690490645431,endTime=1690517335894,totalStats=io.airbyte.config.SyncStats@6b2764fc[bytesCommitted=32525934,bytesEmitted=32525934,destinationStateMessagesEmitted=2,destinationWriteEndTime=1690517335870,destinationWriteStartTime=1690490645431,estimatedBytes=<null>,estimatedRecords=<null>,meanSecondsBeforeSourceStateMessageEmitted=0,maxSecondsBeforeSourceStateMessageEmitted=7,maxSecondsBetweenStateMessageEmittedandCommitted=26597,meanSecondsBetweenStateMessageEmittedandCommitted=13374,recordsEmitted=148864,recordsCommitted=148864,replicationEndTime=1690517335880,replicationStartTime=1690490645431,sourceReadEndTime=1690517306452,sourceReadStartTime=1690490649158,sourceStateMessagesEmitted=353754,additionalProperties={}],streamStats=[io.airbyte.config.StreamSyncStats@4c1728da[streamName=accounting__glTransactionsByDateAndAssocCode,streamNamespace=<client_name>_<source_name>,stats=io.airbyte.config.SyncStats@6eaf974a[bytesCommitted=16584103,bytesEmitted=16584103,destinationStateMessagesEmitted=<null>,destinationWriteEndTime=<null>,destinationWriteStartTime=<null>,estimatedBytes=<null>,estimatedRecords=<null>,meanSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBetweenStateMessageEmittedandCommitted=<null>,meanSecondsBetweenStateMessageEmittedandCommitted=<null>,recordsEmitted=51892,recordsCommitted=51892,replicationEndTime=<null>,replicationStartTime=<null>,sourceReadEndTime=<null>,sourceReadStartTime=<null>,sourceStateMessagesEmitted=<null>,additionalProperties={}],additionalProperties={}], io.airbyte.config.StreamSyncStats@2d38b645[streamName=associations,streamNamespace=<client_name>_<source_name>,stats=io.airbyte.config.SyncStats@7de8379a[bytesCommitted=357706,bytesEmitted=357706,destinationStateMessagesEmitted=<null>,destinationWriteEndTime=<null>,destinationWriteStartTime=<null>,estimatedBytes=<null>,estimatedRecords=<null>,meanSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBetweenStateMessageEmittedandCommitted=<null>,meanSecondsBetweenStateMessageEmittedandCommitted=<null>,recordsEmitted=605,recordsCommitted=605,replicationEndTime=<null>,replicationStartTime=<null>,sourceReadEndTime=<null>,sourceReadStartTime=<null>,sourceStateMessagesEmitted=<null>,additionalProperties={}],additionalProperties={}], io.airbyte.config.StreamSyncStats@84c8105[streamName=accounting__glPreviousBalanceAsOfADate,streamNamespace=<client_name>_<source_name>,stats=io.airbyte.config.SyncStats@1acb5281[bytesCommitted=4346629,bytesEmitted=4346629,destinationStateMessagesEmitted=<null>,destinationWriteEndTime=<null>,destinationWriteStartTime=<null>,estimatedBytes=<null>,estimatedRecords=<null>,meanSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBetweenStateMessageEmittedandCommitted=<null>,meanSecondsBetweenStateMessageEmittedandCommitted=<null>,recordsEmitted=37710,recordsCommitted=37710,replicationEndTime=<null>,replicationStartTime=<null>,sourceReadEndTime=<null>,sourceReadStartTime=<null>,sourceStateMessagesEmitted=<null>,additionalProperties={}],additionalProperties={}], io.airbyte.config.StreamSyncStats@72a95503[streamName=associations__associationGlAccounts,streamNamespace=<client_name>_<source_name>,stats=io.airbyte.config.SyncStats@4e41e82b[bytesCommitted=11237496,bytesEmitted=11237496,destinationStateMessagesEmitted=<null>,destinationWriteEndTime=<null>,destinationWriteStartTime=<null>,estimatedBytes=<null>,estimatedRecords=<null>,meanSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBeforeSourceStateMessageEmitted=<null>,maxSecondsBetweenStateMessageEmittedandCommitted=<null>,meanSecondsBetweenStateMessageEmittedandCommitted=<null>,recordsEmitted=58657,recordsCommitted=58657,replicationEndTime=<null>,replicationStartTime=<null>,sourceReadEndTime=<null>,sourceReadStartTime=<null>,sourceStateMessagesEmitted=<null>,additionalProperties={}],additionalProperties={}]],performanceMetrics=<null>,additionalProperties={}],normalizationSummary=<null>,webhookOperationSummary=<null>,state=<null>,outputCatalog=io.airbyte.protocol.models.ConfiguredAirbyteCatalog@22691c4f[streams=[io.airbyte.protocol.models.ConfiguredAirbyteStream@62f60dd9[stream=io.airbyte.protocol.models.AirbyteStream@5acf4dc9[name=accounting__glPreviousBalanceAsOfADate,jsonSchema={"path":"/management/{mgmtId}/accounting/glPreviousBalanceAsOfADate","description":"","type":"object","properties":{"AsOfDate":{"format":"date","type":"string"},"AssocCode":{"description":"The Association Code.","type":"string"},"PreviousBalance":{"description":"The previous balance before the given date.","type":"number"},"AssocId":{"description":"The unique identifier of the Association.","type":"integer"},"AccountNumber":{"description":"The GL Account Code.","type":"string"}}},supportedSyncModes=[full_refresh, incremental],sourceDefinedCursor=<null>,defaultCursorField=[AsOfDate],sourceDefinedPrimaryKey=[[AssocCode], [AccountNumber], [AsOfDate]],namespace=<client_name>_<source_name>,additionalProperties={}],syncMode=incremental,cursorField=[AsOfDate],destinationSyncMode=append_dedup,primaryKey=[[AssocCode], [AccountNumber], [AsOfDate]],additionalProperties={}], io.airbyte.protocol.models.ConfiguredAirbyteStream@1b0ef60b[stream=io.airbyte.protocol.models.AirbyteStream@716f0a41[name=accounting__glTransactionsByDateAndAssocCode,jsonSchema={"path":"/management/{mgmtId}/accounting/glTransactionsByDateAndAssocCode","description":"","type":"object","properties":{"AssocCode":{"description":"The Association Code","type":"string"},"Description":{"description":"Description of the transaction.","type":"string"},"CreatedDate":{"format":"date-time","airbyte_type":"timestamp_without_timezone","description":"The date the transaction was created.","type":"string"},"PostedDate":{"format":"date-time","airbyte_type":"timestamp_without_timezone","description":"The “Close Date” of the batch when the batch is posted.","type":"string"},"CreditAmount":{"description":"The amount of the transaction (if Credit).","type":"number"},"AssocId":{"description":"The unique identifier of the Association.","type":"integer"},"GLTransID":{"description":"The unique identifier of the GL Transaction","type":"integer"},"DebitAmount":{"description":"The amount of the transaction (if Debit).","type":"number"},"AccountNumber":{"description":"The GL Account Code","type":"string"},"TransactionDate":{"format":"date-time","airbyte_type":"timestamp_without_timezone","description":"The actual date of the transaction.","type":"string"},"ActualPostedDate":{"format":"date-time","airbyte_type":"timestamp_without_timezone","description":"The actual timestamp of the batch posting.","type":"string"}}},supportedSyncModes=[full_refresh, incremental],sourceDefinedCursor=<null>,defaultCursorField=[TransactionDate],sourceDefinedPrimaryKey=[[GLTransID]],namespace=<client_name>_<source_name>,additionalProperties={}],syncMode=incremental,cursorField=[TransactionDate],destinationSyncMode=append_dedup,primaryKey=[[GLTransID]],additionalProperties={}], io.airbyte.protocol.models.ConfiguredAirbyteStream@23255970[stream=io.airbyte.protocol.models.AirbyteStream@3a4e9d8[name=associations,jsonSchema={"path":"/management/{mgmtId}/associations","description":"Association model","type":"object","properties":{"Zip":{"description":"Association Zip","type":"string"},"AssociationIdLink":{"description":"Association Code","type":"string"},"ManagerName":{"description":"Association's manager name","type":"string"},"Website":{"description":"Association's website","type":"string"},"UserDefined1":{"description":"User defined field","type":"string"},"Numberofunits":{"description":"Number of units in an association","type":"integer"},"AssocId":{"description":"Association's id","type":"integer"},"ServicePackageId":{"description":"Association's service package id.","type":"integer"},"isActive":{"description":"Shows if Association is Active or not","type":"boolean"},"UserDefined4":{"description":"User defined field","type":"string"},"UserDefined2":{"description":"User defined field","type":"string"},"UserDefined3":{"description":"User defined field","type":"string"},"RegionName":{"description":"Association's region name","type":"string"},"AssistantManagerName":{"description":"Association's assistant manager name","type":"string"},"AssocTypeId":{"description":"Association's Type id","type":"integer"},"Address2":{"description":"Association's 2nd address","type":"string"},"City":{"description":"Association City","type":"string"},"TaxID":{"description":"Association's tax id","type":"string"},"Address1":{"description":"Association's address","type":"string"},"OfficeId":{"description":"Association's office id","type":"integer"},"State":{"description":"Association State","type":"string"},"Associationname":{"description":"Name of the Association","type":"string"},"AssistantManagerId":{"description":"Association's assistant manager id","type":"integer"},"RegionId":{"description":"Association's region id","type":"integer"},"ManagerId":{"description":"Association's manager id","type":"integer"},"OfficeName":{"description":"Association's office name","type":"string"}}},supportedSyncModes=[full_refresh],sourceDefinedCursor=<null>,defaultCursorField=[],sourceDefinedPrimaryKey=[],namespace=<client_name>_<source_name>,additionalProperties={}],syncMode=full_refresh,cursorField=[],destinationSyncMode=overwrite,primaryKey=[],additionalProperties={}], io.airbyte.protocol.models.ConfiguredAirbyteStream@6ff6e909[stream=io.airbyte.protocol.models.AirbyteStream@66c2dbb4[name=associations__associationGlAccounts,jsonSchema={"path":"/management/associations/{mgmtId}/associationGlAccounts","description":"","type":"object","properties":{"Reserve":{"description":"","type":"integer"},"GlAccountType":{"description":"Gl account type (Asset, Liability, Expense, or Revenue)","type":"string"},"AccountDescription":{"description":"","type":"string"},"TypicalBalance":{"description":"Typical balance type (Debit or Credit)","type":"string"},"AssocCode":{"type":"string"},"Report":{"description":"","type":"string"},"ChartID":{"description":"","type":"integer"},"AccountNumber":{"description":"","type":"string"}}},supportedSyncModes=[full_refresh],sourceDefinedCursor=<null>,defaultCursorField=[],sourceDefinedPrimaryKey=[],namespace=<client_name>_<source_name>,additionalProperties={}],syncMode=full_refresh,cursorField=[],destinationSyncMode=overwrite,primaryKey=[],additionalProperties={}]],additionalProperties={}],failures=[],additionalProperties={}]
2023-07-28 04:08:55 INFO i.a.w.t.s.ReplicationActivityImpl(lambda$replicate$3):165 - Sync summary length: 10683
2023-07-28 04:08:55 INFO i.a.c.t.TemporalUtils(withBackgroundHeartbeat):307 - Stopping temporal heartbeating...
2023-07-28 04:08:56 INFO i.a.w.t.s.NormalizationActivityImpl(lambda$normalize$3):132 - Using protocol v0
2023-07-28 04:08:56 INFO i.a.w.t.s.NormalizationActivityImpl(lambda$normalize$3):152 - Using normalization: airbyte/normalization-snowflake:0.2.25
2023-07-28 04:08:56 INFO i.a.w.t.TemporalAttemptExecution(get):138 - Cloud storage job log path: /workspace/24760/0/logs.log
2023-07-28 04:08:56 INFO i.a.w.t.TemporalAttemptExecution(get):141 - Executing worker wrapper. Airbyte version: 0.50.6
2023-07-28 04:08:56 INFO i.a.a.c.AirbyteApiClient(retryWithJitterThrows):229 - Attempt 0 to save workflow id for cancellation
2023-07-28 04:08:56 INFO i.a.c.i.LineGobbler(voidCall):149 - 
2023-07-28 04:08:56 INFO i.a.w.n.DefaultNormalizationRunner(runProcess):130 - Running with normalization version: airbyte/normalization-snowflake:0.2.25
2023-07-28 04:08:56 INFO i.a.c.i.LineGobbler(voidCall):149 - ----- START DEFAULT NORMALIZATION -----
2023-07-28 04:08:56 INFO i.a.c.i.LineGobbler(voidCall):149 - 
2023-07-28 04:08:56 INFO i.a.w.p.KubeProcessFactory(create):107 - Attempting to start pod = normalization-snowflake-normalize-24760-0-bpgbj for airbyte/normalization-snowflake:0.2.25 with resources io.airbyte.config.ResourceRequirements@526dc386[cpuRequest=,cpuLimit=,memoryRequest=4Gi,memoryLimit=8Gi,additionalProperties={}] and allowedHosts null
2023-07-28 04:08:56 INFO i.a.w.p.KubeProcessFactory(create):111 - normalization-snowflake-normalize-24760-0-bpgbj stdoutLocalPort = 9012
2023-07-28 04:08:56 INFO i.a.w.p.KubeProcessFactory(create):114 - normalization-snowflake-normalize-24760-0-bpgbj stderrLocalPort = 9013
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$11):658 - Creating stdout socket server...
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$12):676 - Creating stderr socket server...
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(<init>):584 - Creating pod normalization-snowflake-normalize-24760-0-bpgbj...
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):362 - Waiting for init container to be ready before copying files...
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):366 - Init container present..
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(waitForInitPodToRun):369 - Init container ready..
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(<init>):615 - Copying files...
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: destination_config.json
2023-07-28 04:08:56 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/a79aa5f5-b883-4495-b50d-e98f4dcd9273/destination_config.json default/normalization-snowflake-normalize-24760-0-bpgbj:/config/destination_config.json -c init
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: destination_catalog.json
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/9173e72b-5c5d-43d8-8276-0580f406bf6e/destination_catalog.json default/normalization-snowflake-normalize-24760-0-bpgbj:/config/destination_catalog.json -c init
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):311 - Uploading file: FINISHED_UPLOADING
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):319 - kubectl cp /tmp/407ab564-4862-4a90-90d1-56ecca057d06/FINISHED_UPLOADING default/normalization-snowflake-normalize-24760-0-bpgbj:/config/FINISHED_UPLOADING -c init
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):322 - Waiting for kubectl cp to complete
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):336 - kubectl cp complete, closing process
2023-07-28 04:08:57 INFO i.a.w.p.KubePodProcess(<init>):618 - Waiting until pod is ready...
2023-07-28 04:08:58 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$11):667 - Setting stdout...
2023-07-28 04:08:58 INFO i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$12):679 - Setting stderr...
2023-07-28 04:08:59 INFO i.a.w.p.KubePodProcess(<init>):634 - Reading pod IP...
2023-07-28 04:08:59 INFO i.a.w.p.KubePodProcess(<init>):636 - Pod IP: 10.226.5.235
2023-07-28 04:08:59 INFO i.a.w.p.KubePodProcess(<init>):643 - Using null stdin output stream...
2023-07-28 04:09:00 INFO i.a.w.n.NormalizationAirbyteStreamFactory(filterOutAndHandleNonAirbyteMessageLines):104 - 
2023-07-28 04:09:00 INFO i.a.w.n.NormalizationAirbyteStreamFactory(filterOutAndHandleNonAirbyteMessageLines):104 - 
2023-07-28 04:09:17 INFO i.a.w.p.KubePodProcess(close):799 - (pod: default / normalization-snowflake-normalize-24760-0-bpgbj) - Closed all resources for pod
2023-07-28 04:09:17 INFO i.a.w.n.DefaultNormalizationRunner(close):196 - Terminating normalization process...
2023-07-28 04:09:17 INFO i.a.w.n.DefaultNormalizationRunner(close):209 - Normalization process successfully terminated.
2023-07-28 04:09:17 INFO i.a.w.g.DefaultNormalizationWorker(run):97 - Normalization executed in 21 seconds for job 24760.
2023-07-28 04:09:17 INFO i.a.w.g.DefaultNormalizationWorker(run):109 - Normalization summary: io.airbyte.config.NormalizationSummary@3195871a[startTime=1690517336033,endTime=1690517357055,failures=[],additionalProperties={}]
2023-07-28 04:09:17 INFO i.a.c.i.LineGobbler(voidCall):149 - 
2023-07-28 04:09:17 INFO i.a.w.t.TemporalAttemptExecution(get):163 - Stopping cancellation check scheduling...
2023-07-28 04:09:17 INFO i.a.c.i.LineGobbler(voidCall):149 - ----- END DEFAULT NORMALIZATION -----
2023-07-28 04:09:17 INFO i.a.c.i.LineGobbler(voidCall):149 - 
2023-07-28 04:09:17 INFO i.a.c.t.TemporalUtils(withBackgroundHeartbeat):307 - Stopping temporal heartbeating...

luke-oa · 2023-07-28T17:36:10Z

luke-oa
Jul 28, 2023
Author

I also just confirmed that the extra logs aren't being written to S3, so the issue appears to be with writing, not reading via the API

0 replies

luke-oa · 2023-07-31T21:23:07Z

luke-oa
Jul 31, 2023
Author

Did confirm I can see the full source logging output if I stern the clusters in real time, so appears to be logging, just not writing the logging output to S3

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging for custom connectors broken after upgrade - hanging/not logging after "Starting a new buffer for stream" #28830

{{title}}

Replies: 2 comments

{{title}}

{{title}}

Select a reply

Logging for custom connectors broken after upgrade - hanging/not logging after "Starting a new buffer for stream" #28830

luke-oa Jul 28, 2023

Replies: 2 comments

luke-oa Jul 28, 2023 Author

luke-oa Jul 31, 2023 Author

luke-oa
Jul 28, 2023

luke-oa
Jul 28, 2023
Author

luke-oa
Jul 31, 2023
Author