wave we are having difficulty understand the error log duri Airbyte #replication-troubleshooting

:wave: we are having difficulty understand the err...

Shangwei Wang

11/17/2022, 3:44 PM

👋 we are having difficulty understand the error log during the normalization process (partial log pasted in thread), maybe someone can help us decipher 🙏 ? more deployment info in thread too. This is for a large job where we are moving about 80GB (110 million rows) of data. The other smaller jobs of ours worked well.

Shangwei Wang

11/17/2022, 3:45 PM

Copy code

2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubeProcessFactory(create):103 - normalization-redshift-normalize-21321-0-wnzxp stdoutLocalPort = 9026
2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubeProcessFactory(create):106 - normalization-redshift-normalize-21321-0-wnzxp stderrLocalPort = 9027
2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$9):589 - Creating stdout socket server...
2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$10):607 - Creating stderr socket server...
2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubePodProcess(<init>):520 - Creating pod normalization-redshift-normalize-21321-0-wnzxp...
2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubePodProcess(waitForInitPodToRun):309 - Waiting for init container to be ready before copying files...
2022-11-17 02:37:51 [32mINFO[m i.a.w.p.KubePodProcess(waitForInitPodToRun):313 - Init container present..
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(waitForInitPodToRun):316 - Init container ready..
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(<init>):551 - Copying files...
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):258 - Uploading file: destination_config.json
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):266 - kubectl cp /tmp/c2420a0d-4939-4d64-9654-3dd1a2f8ca88/destination_config.json data-engineering/normalization-redshift-normalize-21321-0-wnzxp:/config/destination_config.json -c init
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):269 - Waiting for kubectl cp to complete
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):283 - kubectl cp complete, closing process
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):258 - Uploading file: destination_catalog.json
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):266 - kubectl cp /tmp/f2969057-f315-40aa-b342-59c78b5829a7/destination_catalog.json data-engineering/normalization-redshift-normalize-21321-0-wnzxp:/config/destination_catalog.json -c init
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):269 - Waiting for kubectl cp to complete
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):283 - kubectl cp complete, closing process
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):258 - Uploading file: FINISHED_UPLOADING
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):266 - kubectl cp /tmp/76b778b7-95ba-4735-a9c4-7cf0cc2e83df/FINISHED_UPLOADING data-engineering/normalization-redshift-normalize-21321-0-wnzxp:/config/FINISHED_UPLOADING -c init
2022-11-17 02:37:53 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):269 - Waiting for kubectl cp to complete
2022-11-17 02:37:54 [32mINFO[m i.a.w.p.KubePodProcess(waitForInitPodToTerminate):327 - Waiting for init container to terminate before checking exit value...
2022-11-17 02:37:55 [32mINFO[m i.a.w.p.KubePodProcess(waitForInitPodToTerminate):332 - Init container terminated with exit value 0.
2022-11-17 02:37:55 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):277 - Init was successful; ignoring non-zero kubectl cp exit code for success indicator file.
2022-11-17 02:37:55 [32mINFO[m i.a.w.p.KubePodProcess(copyFilesToKubeConfigVolume):283 - kubectl cp complete, closing process
2022-11-17 02:37:55 [32mINFO[m i.a.w.p.KubePodProcess(<init>):554 - Waiting until pod is ready...
2022-11-17 02:37:55 [32mINFO[m i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$9):598 - Setting stdout...
2022-11-17 02:37:55 [32mINFO[m i.a.w.p.KubePodProcess(lambda$setupStdOutAndStdErrListeners$10):610 - Setting stderr...
2022-11-17 02:37:56 [32mINFO[m i.a.w.p.KubePodProcess(<init>):570 - Reading pod IP...
2022-11-17 02:37:56 [32mINFO[m i.a.w.p.KubePodProcess(<init>):572 - Pod IP: 172.31.19.41
2022-11-17 02:37:56 [32mINFO[m i.a.w.p.KubePodProcess(<init>):579 - Using null stdin output stream...
2022-11-17 02:38:00 [32mINFO[m i.a.w.n.NormalizationAirbyteStreamFactory(filterOutAndHandleNonAirbyteMessageLines):104 - 
2022-11-17 02:38:00 [32mINFO[m i.a.w.n.NormalizationAirbyteStreamFactory(filterOutAndHandleNonAirbyteMessageLines):104 - 
2022-11-17 02:38:26 [42mnormalization[0m > 2 of 4 OK created view model _airbyte_airbyte.sales_channel_order_simple_stg............................................ [[32mCREATE VIEW[0m in 1.02s]
2022-11-17 02:38:26 [42mnormalization[0m > 3 of 4 START incremental model airbyte.sales_channel_order_simple_scd................................................... [RUN]
2022-11-17 02:38:27 [42mnormalization[0m > 02:38:27 + "parker".airbyte."sales_channel_order_simple_scd"._airbyte_ab_id does not exist yet. The table will be created or rebuilt with dbt.full_refresh
2022-11-17 04:09:38 [32mINFO[m i.a.w.p.KubePodProcess(close):737 - (pod: data-engineering / normalization-redshift-normalize-21321-0-wnzxp) - Closed all resources for pod
2022-11-17 04:09:38 [32mINFO[m i.a.w.g.DefaultNormalizationWorker(run):82 - Normalization executed in 1 hour 31 minutes 47 seconds.
2022-11-17 04:09:38 [32mINFO[m i.a.w.t.TemporalAttemptExecution(lambda$getWorkerThread$4):193 - Completing future exceptionally...
io.airbyte.workers.exception.WorkerException: Normalization Failed.
	at io.airbyte.workers.general.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:92) ~[io.airbyte-airbyte-commons-worker-0.40.17.jar:?]
	at io.airbyte.workers.general.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:27) ~[io.airbyte-airbyte-commons-worker-0.40.17.jar:?]
	at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$4(TemporalAttemptExecution.java:190) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	at java.lang.Thread.run(Thread.java:1589) ~[?:?]
2022-11-17 04:09:38 [32mINFO[m i.a.w.t.TemporalAttemptExecution(get):162 - Stopping cancellation check scheduling...
2022-11-17 04:09:38 [32mINFO[m i.a.c.t.TemporalUtils(withBackgroundHeartbeat):283 - Stopping temporal heartbeating...
2022-11-17 04:09:38 [33mWARN[m i.t.i.a.POJOActivityTaskHandler(activityFailureToResult):307 - Activity failure. ActivityId=4c1a4d1a-b752-3632-812e-ed0fb1f54bd5, activityType=Normalize, attempt=1
java.lang.RuntimeException: io.temporal.serviceclient.CheckedExceptionWrapper: java.util.concurrent.ExecutionException: io.airbyte.workers.exception.WorkerException: Normalization Failed.
	at io.airbyte.commons.temporal.TemporalUtils.withBackgroundHeartbeat(TemporalUtils.java:281) ~[io.airbyte-airbyte-commons-temporal-0.40.17.jar:?]
	at io.airbyte.workers.temporal.sync.NormalizationActivityImpl.normalize(NormalizationActivityImpl.java:104) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:578) ~[?:?]
	at io.temporal.internal.activity.POJOActivityTaskHandler$POJOActivityInboundCallsInterceptor.execute(POJOActivityTaskHandler.java:214) ~[temporal-sdk-1.8.1.jar:?]
	at io.temporal.internal.activity.POJOActivityTaskHandler$POJOActivityImplementation.execute(POJOActivityTaskHandler.java:180) ~[temporal-sdk-1.8.1.jar:?]
	at io.temporal.internal.activity.POJOActivityTaskHandler.handle(POJOActivityTaskHandler.java:120) ~[temporal-sdk-1.8.1.jar:?]
	at io.temporal.internal.worker.ActivityWorker$TaskHandlerImpl.handle(ActivityWorker.java:204) ~[temporal-sdk-1.8.1.jar:?]
	at io.temporal.internal.worker.ActivityWorker$TaskHandlerImpl.handle(ActivityWorker.java:164) ~[temporal-sdk-1.8.1.jar:?]
	at io.temporal.internal.worker.PollTaskExecutor.lambda$process$0(PollTaskExecutor.java:93) ~[temporal-sdk-1.8.1.jar:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
	at java.lang.Thread.run(Thread.java:1589) ~[?:?]
Caused by: io.temporal.serviceclient.CheckedExceptionWrapper: java.util.concurrent.ExecutionException: io.airbyte.workers.exception.WorkerException: Normalization Failed.
	at io.temporal.serviceclient.CheckedExceptionWrapper.wrap(CheckedExceptionWrapper.java:56) ~[temporal-serviceclient-1.8.1.jar:?]
	at io.temporal.internal.sync.WorkflowInternal.wrap(WorkflowInternal.java:448) ~[temporal-sdk-1.8.1.jar:?]
	at io.temporal.activity.Activity.wrap(Activity.java:51) ~[temporal-sdk-1.8.1.jar:?]
	at io.airbyte.workers.temporal.TemporalAttemptExecution.get(TemporalAttemptExecution.java:166) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	at io.airbyte.workers.temporal.sync.NormalizationActivityImpl.lambda$normalize$3(NormalizationActivityImpl.java:132) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	at io.airbyte.commons.temporal.TemporalUtils.withBackgroundHeartbeat(TemporalUtils.java:276) ~[io.airbyte-airbyte-commons-temporal-0.40.17.jar:?]
	... 12 more
Caused by: java.util.concurrent.ExecutionException: io.airbyte.workers.exception.WorkerException: Normalization Failed.
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073) ~[?:?]
	at io.airbyte.workers.temporal.TemporalAttemptExecution.get(TemporalAttemptExecution.java:160) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	at io.airbyte.workers.temporal.sync.NormalizationActivityImpl.lambda$normalize$3(NormalizationActivityImpl.java:132) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	at io.airbyte.commons.temporal.TemporalUtils.withBackgroundHeartbeat(TemporalUtils.java:276) ~[io.airbyte-airbyte-commons-temporal-0.40.17.jar:?]
	... 12 more
Caused by: io.airbyte.workers.exception.WorkerException: Normalization Failed.
	at io.airbyte.workers.general.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:92) ~[io.airbyte-airbyte-commons-worker-0.40.17.jar:?]
	at io.airbyte.workers.general.DefaultNormalizationWorker.run(DefaultNormalizationWorker.java:27) ~[io.airbyte-airbyte-commons-worker-0.40.17.jar:?]
	at io.airbyte.workers.temporal.TemporalAttemptExecution.lambda$getWorkerThread$4(TemporalAttemptExecution.java:190) ~[io.airbyte-airbyte-workers-0.40.17.jar:?]
	... 1 more
2022-11-17 04:09:39 [32mINFO[m i.a.v.j.JsonSchemaValidator(test):71 - JSON schema validation failed. 
errors: $.mode: must be a constant value disable, $.mode: does not have a value in the enumeration [disable]
2022-11-17 04:10:28 [43mdestination[0m > starting destination: class io.airbyte.integrations.destination.redshift.RedshiftDestination
2022-11-17 04:09:39 [32mINFO[m i.a.v.j.JsonSchemaValidator(test):71 - JSON schema validation failed. 
errors: $.method: must be a constant value Standard
2022-11-17 04:09:39 [32mINFO[m i.a.v.j.JsonSchemaValidator(test):71 - JSON schema validation failed. 
errors: $.access_key_id: object found, string expected, $.secret_access_key: object found, string expected
2022-11-17 04:09:39 [32mINFO[m i.a.w.t.TemporalAttemptExecution(get):138 - Cloud storage job log path: /workspace/21321/1/logs.log
2022-11-17 04:09:39 [32mINFO[m i.a.w.t.TemporalAttemptExecution(get):141 - Executing worker wrapper. Airbyte version: 0.40.18
2022-11-17 04:09:39 [32mINFO[m i.a.c.i.LineGobbler(voidCall):114 - 
2022-11-17 04:09:39 [32mINFO[m i.a.w.p.KubeProcessFactory(create):100 - Attempting to start pod = source-postgres-check-21321-1-xqkrd for airbyte/source-postgres:1.0.23 with resources io.airbyte.config.ResourceRequirements@15ab08b3[cpuRequest=,cpuLimit=,memoryRequest=,memoryLimit=]
2022-11-17 04:09:39 [32mINFO[m i.a.c.i.LineGobbler(voidCall):114 - ----- START CHECK -----
2022-11-17 04:09:39 [32mINFO[m i.a.c.i.LineGobbler(voidCall):114 -

Shangwei Wang

11/17/2022, 3:46 PM

Helm deployment 0.40.40 (airbyte 0.40.17) on EKS. Postgres (1.0.23) -> redshift (0.3.51) via S3 Copy.

Shangwei Wang

11/17/2022, 3:53 PM

much appreciated thanks!

Marcos Marx (Airbyte)

11/17/2022, 4:04 PM

Hello @Shangwei Wang can you upload the complete file here?

Shangwei Wang

11/17/2022, 4:28 PM

ya, i can but its 60MB, thats ok?

Shangwei Wang

11/17/2022, 7:06 PM

here it is, note that at the end of the log, we manually canceled the job

failed_normalization_log.txt.zip

Shangwei Wang

11/18/2022, 4:06 PM

👋 this happens again to another samll job, seems to de-stablize our pipeline. it just keeps retrying. help~ thanks!

Shangwei Wang

11/21/2022, 4:08 PM

happened again this morning, 🙏

Shangwei Wang

11/28/2022, 4:07 PM

Hi, this particular job has not ran successfully for the past 2 days, am wondering if someone can help take a look at the log and help? thanks!

Shangwei Wang

11/28/2022, 4:08 PM

we keep getting the stacktrace that says

Source cannot be stopped

, anything i should checked on my side?

Shangwei Wang

11/30/2022, 4:59 PM

@Marcos Marx (Airbyte) thoughts? i dont want to re-post this in the main channel if i dont have to, any update will be appreciated, thanks!

user

12/06/2022, 9:06 PM

Hello Shangwei Wang, it's been a while without an update from us. Are you still having problems or did you find a solution?

Shangwei Wang

12/06/2022, 9:17 PM

np, i dug deeper into the deployment, and i think it was a resource issue, so after giving it a bigger (bigger than i anticipated) instance type of the jobs, seems to be more stable

Marcos Marx (Airbyte)

12/06/2022, 9:23 PM

Do you mind sharing the size of the instance you’re using for a 80Gb table?

3 Views

Open in Slack

Previous Next