SnowflakeFileTransferAgent - Exception encountered during file upload

[berl-a]

Hello,

We have the following exception in our app: SnowflakeFileTransferAgent - Exception encountered during file upload. It's usually preceded by the following 2 issues:

• ERROR: value ***** is out of range for type integer
• ERROR: cannot execute INSERT in a read-only transaction

Is this a known issue? What should we do about it?

[sfc-gh-lsembera]

Hi, here we would need more information to debug this issue. Could you please contact the Snowflake support and provide your client logs around the time of the issue?

[sliwamichal]

From the debug logs it looks like a token is expired. Based on the configuration the upload is retried and the first retry is successful. So the only thing to be changed here - as I assume that's the expected scenario - is to change log level from ERROR to DEBUG for this specific situation with token expiration (as it's pretty regular)

` {"log":"03:00:39.126 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.SnowflakeFileTransferAgent\u001b[0;39m - Begin upload data for 2024/5/7/3/0/sd3hp3_yGwIGLbycrwGKHxj0EQs2otKYyhBFI6FTVHAhbIDO28CC_1016_509_1246.bdec","stream":"stdout","timestamp":1715050839126}

{"log":"03:00:39.127 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.c.storage.SnowflakeS3Client\u001b[0;39m - s3 client configuration: maxConnection=2, connectionTimeout=10,000, socketTimeout=50,000, maxErrorRetry=3","stream":"stdout","timestamp":1715050839127}

{"log":"03:00:39.186 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.c.storage.SnowflakeS3Client\u001b[0;39m - Stack trace: net.snowflake.client.jdbc.internal.amazonaws.services.s3.model.AmazonS3Exception: The provided token has expired. (Service: Amazon S3; Status Code: 400; Error Code: ExpiredToken; Request ID: 98S6BY512RCSCFSM; S3 Extended Request ID: x35zA9POzezS+rt4L9BKrj423kB2mTkMzQMUhXPQUrxX/ofBUhmyPJJ8Ae/3MBYgDd1/X+fz6rg=; Proxy: null) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.handleErrorResponse(AmazonHttpClient.java:1879) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.handleServiceErrorResponse(AmazonHttpClient.java:1418) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(AmazonHttpClient.java:1387) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1157) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:814) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:781) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:755) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:715) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:697) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:561) at net.snowflake.client.jdbc.internal.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:541) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:5456) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:5403) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.AmazonS3Client.access$300(AmazonS3Client.java:421) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.AmazonS3Client$PutObjectStrategy.invokeServiceCall(AmazonS3Client.java:6532) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.AmazonS3Client.uploadObject(AmazonS3Client.java:1861) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1821) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.transfer.internal.UploadCallable.uploadInOneChunk(UploadCallable.java:169) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.transfer.internal.UploadCallable.call(UploadCallable.java:149) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.transfer.internal.UploadMonitor.call(UploadMonitor.java:115) at net.snowflake.client.jdbc.internal.amazonaws.services.s3.transfer.internal.UploadMonitor.call(UploadMonitor.java:45) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) at java.base/java.lang.Thread.run(Thread.java:1583)","stream":"stdout","timestamp":1715050839187}

{"log":"03:00:39.186 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.c.storage.SnowflakeS3Client\u001b[0;39m - Encountered exception (The provided token has expired. (Service: Amazon S3; Status Code: 400; Error Code: ExpiredToken; Request ID: 98S6BY512RCSCFSM; S3 Extended Request ID: x35zA9POzezS+rt4L9BKrj423kB2mTkMzQMUhXPQUrxX/ofBUhmyPJJ8Ae/3MBYgDd1/X+fz6rg=; Proxy: null)) during upload, retry count: 1","stream":"stdout","timestamp":1715050839186}

{"log":"03:00:39.187 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.c.storage.SnowflakeS3Client\u001b[0;39m - Sleep for 1,000 milliseconds before retry","stream":"stdout","timestamp":1715050839187}

[ERROR] {"log":"03:00:40.187 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[1;31mERROR\u001b[0;39m \u001b[36mn.s.c.j.SnowflakeFileTransferAgent\u001b[0;39m - Exception encountered during file upload:","stream":"stdout","timestamp":1715050840187}

{"log":"03:00:40.321 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.SnowflakeFileTransferAgent\u001b[0;39m - Begin upload data for 2024/5/7/3/0/sd3hp3_yGwIGLbycrwGKHxj0EQs2otKYyhBFI6FTVHAhbIDO28CC_1016_509_1246.bdec","stream":"stdout","timestamp":1715050840321}

{"log":"03:00:40.322 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-22\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.SnowflakeFileTransferAgent\u001b[0;39m - Started copying file to S3:sfc-oh-ds1-11-customer-stage/mxdb-s-ohsu4401/streaming_ingest/ destName: 2024/5/7/3/0/sd3hp3_yGwIGLbycrwGKHxj0EQs2otKYyhBFI6FTVHAhbIDO28CC_1016_509_1246.bdec compressed ? no size=73,792","stream":"stdout","timestamp":1715050840322}

{"log":"03:00:41.127 [\u001b[32m\u001b[0;39m] [\u001b[32m\u001b[0;39m] [\u001b[34mingest-build-upload-thread-23\u001b[0;39m] \u001b[39mDEBUG\u001b[0;39m \u001b[36mn.s.c.j.SnowflakeFileTransferAgent\u001b[0;39m - Begin upload data for 2024/5/7/3/0/sd3hp5_yGwIGLbycrwGKHxj0EQs2otKYyhBFI6FTVHAhbIDO28CC_1016_509_1247.bdec","stream":"stdout","timestamp":1715050841127} `

[sfc-gh-lsembera]

According to this log, upload fails due an expired token, which happens regularly every few hours, depending on the cloud vendor. However, the ingestion process should not be impacted as the token is successfuly renewed on second upload attempt.

Is the ingestion failing for you or is the issue just that you are seeing these noisy errors in logs.

[sliwamichal]

It turned out to be just a noisy log, but internally we rised a critial issue seeing such logs on production, as we thought that we might be losing data - after turning on debug, it turned out it was not true.

[sfc-gh-lsembera]

Thanks for the clarification. There is another issue raised recently (https://github.com/snowflakedb/snowflake-ingest-java/issues/753) to make sure these false positives don't appear in logs. Is it ok with you if we close this issue in favor of the other one?

[sfc-gh-lsembera]

Duplicate of https://github.com/snowflakedb/snowflake-ingest-java/issues/753.