files not loaded occasionally due "another thread has locked it for loading"

[tomekzbrozek]

A small number of my files (around 10 out of 20k) is not loaded each day, with such error being returned after it hits the timeout:

error: The conditional request failed 
{
    "code": "ConditionalCheckFailedException",
    "time": "2021-08-23T21:16:14.506Z",
    "requestId": "5UCMPG1CQ6QRQAATPJPH8V536VVV4KQNSO5AEMVJF66Q9ASUAAJG",
    "statusCode": 400,
    "retryable": false,
    "retryDelay": 25.6182288251398
}

and logging this:

debug: Batch is ready to be processed, but another thread has locked it for loading

Despite the debug log above, I wasn't able to find any other batches with these files. My configuration is:

• batchTimeoutSecs: 240
• batchSize: 100
• batchSizeBytes: ""

I wonder if anyone else experienced similar issue and whether there's a simple config tweak that could be applied to mitigate this? Thanks.

[IanMeyers]

This is an expected message that is not considered an error and is fully built into the workflow. is the link between the debug message and the files not loaded clearly linked by the batch ID? What is the status of these batches? They should end up in status COMPLETED, and if they fail then end up in ERROR. If they are in LOCKED status it likely means that the Loader timed out before it completed, so. you need to increase your lambda function invocation time to 15 minutes.

[tomekzbrozek]

Thanks for a fast reply! Yes, the problematic files are clearly linked to the locked/failed batches, I can see that in another debug log.

The status of these batches is, for example:

...
   "status":{
      "S":"complete"
   },
   "lastUpdate":{
      "N":"1629724689.239"
   },
   "clusterLoadStatus":{
      "S":"{\"xyz\":{\"status\":0,\"error\":null}}"
   },
   "batchId":{
      "S":"bd8c1ba0-8fef-49a2-8b04-36d8474b4e82"
   }
}

My Lambda invocation timeout is already 15min.

[IanMeyers]

Ok. Can you determine if the lambdas are timing out?

[tomekzbrozek]

I hope I'm verifying it correctly but just checked the maximum duration and it didn't cross 315k ms (which is just slightly above 5min) so it seems to me that the timeout is never reached.

[tomekzbrozek]

Any suggestions on how to mitigate this issue (i.e. stop many threads to lock the same file) would also be very much appreciated! I'm not under big pressure to optimise for latency or multithreading here.

[IanMeyers]

This concurrency model is by design and should not be changed. We need to determine why your batches are infrequently getting a null status. Either way, for those files that are contained in errored batches, you can use the reprocessBatch.js script to resubmit them for processing, though this shouldn't be a long-term fix.

[JeanCodes]

Hi, I am seeing the same, however my batches are not erroring out, they are simply remaining locked and never getting processed.

[IanMeyers]

This is almost always due to the 'other thread' timing out before the load completes. Can you look at your Lambda logs for timeouts?

[JeanCodes]

Hi, there are no timeouts that I can see in the logs and from the metrics, i do not come close to timing out the lambda. I have it set at 15 minutes. The only errors I get in the lambda logs are:
error:
{
"Key": {
"batchId": {
"S": "41071cb5-a111-450a-a218-31e6c6d4762b"
},
"s3Prefix": {
"S": "bucketnameand/prefix"
}
},
"TableName": "LambdaRedshiftBatches",
"AttributeUpdates": {
"status": {
"Action": "PUT",
"Value": {
"S": "locked"
}
},
"lastUpdate": {
"Action": "PUT",
"Value": {
"N": "1638294640.478"
}
}
},
"Expected": {
"status": {
"AttributeValueList": [
{
"S": "open"
}
],
"ComparisonOperator": "EQ"
}
},
"ReturnValues": "ALL_NEW"
}

and
error: The conditional request failed
{
"code": "ConditionalCheckFailedException",
"time": "2021-11-30T17:50:40.538Z",
"requestId": "TE5D5B72DIRE3B131KA26UQ3KVVV4KQNSO5AEMVJF66Q9ASUAAJG",
"statusCode": 400,
"retryable": false,
"retryDelay": 48.689234335095435
}
I have added the below environment variables, but still see nothing else of note that would je

DEBUG TRUE
LOG_LEVEL silly

[IanMeyers]

Have you setup a failure SNS topic so you can be notified of errors?

[JeanCodes]

The logs even show the actual COPY command, however I do not see that COPY command in redshift query history. Its like it either never executes that COPY command, or actually, I am not sure at all... Directly after the COPY command output, I see connecting to database , but then the request ends... all without error.

I have added an SNS Topic with subscription, however I am not receiving anything (neither success nor failed)

[IanMeyers]

The connection to the database should occur before the COPY, not after. Can you please upload a logfile collection from CloudWatch to this issue so I can see the full output?

[JeanCodes]

log-events-viewer-result.csv
Please see attached. I have removed the names and endpoints of our specific items

[JeanCodes]

Good day, have you managed to identify what the root cause may be from these logs? If there is a connectivity or permissions error, I assume that would appear somewhere in the cloudwatch logs?

Do you have any suggestions as to how we can troubleshoot this item?