Closed caiiiycuk closed 5 years ago
I set timeout for lambda to 900, and invoke lambda with aws lambda invoke:
time aws lambda invoke --function-name profile-StoragePut-11YEYJRHHTYRM --region us-east-1 /tmp/log --payload "\
{\
\"httpMethod\": \"POST\", \
\"queryStringParameters\": {\"id\":\"test-player-id\", \"game\":\"test-game-id\"}, \
\"body\": \"{'prefix1.v1':'value1','prefix1.v2':'value2','prefix1.v3':'value3'}\" \
}\
"
Time needed to second call is:
real 1m15,940s
user 0m0,516s
sys 0m0,053s
But strangest thing is that cloudwatch does not show any logs after stuck point:
START RequestId: 465ae721-f95c-11e8-ac02-41e55ecfcd40 Version: $LATEST
29590 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Creating an interceptor chain that will apply interceptors in the following order: []
29591 [main] DEBUG software.amazon.awssdk.request - Sending Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=https, host=dynamodb.us-east-1.amazonaws.com, encodedPath=/, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent, X-Amz-Target], queryParameters=[])
29592 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 Canonical Request: POST
/
amz-sdk-invocation-id:f5e2afe0-f557-1b41-03d4-ff5301ceea80
amz-sdk-retry:0/0/500
content-length:104
content-type:application/x-amz-json-1.0
host:dynamodb.us-east-1.amazonaws.com
x-amz-date:20181206T133854Z
x-amz-security-token:FQoGZXIvYXdzEAcaDCWPbFtwXb7Q1QABKiKCAjkIJo4bFeTPIQWncQPesu+2mdrEsHtJp+f3U+DUJa/GREeRgWMLPyghDn9daGQ5Qv/Ao/QtH8ztgzad+7I1mmAEhOTwzhMmCScMrNNFWpuH/WM8Dgb6KYBFo0GMp3Y5IDy1TwfSSYN2r0riNWIm8vGizNkS9cpARXCLCMdd/u4oevg9vXjeuIhEtdkDeNoRvmJcpCExfo01bLpG5NFNkd0FbIv7BujlV9AOtA26ybTj0VpUiVAXG+gZ+GIrv5vEW1pna4vU7EjxRsJ+1t6FXne7iug4Zf8twCmm8FHcifWrWF6anmufTuyTWIwIs+k+wUTBZaQK3woCMxMbdddTy7oE4yiRxKTgBQ==
x-amz-target:DynamoDB_20120810.GetItem
amz-sdk-invocation-id;amz-sdk-retry;content-length;content-type;host;x-amz-date;x-amz-security-token;x-amz-target
c27ae70d80ef53c618222243ba0c04c18c8aed3c612512d545881038402a232e
29592 [main] DEBUG software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 String to sign: AWS4-HMAC-SHA256
20181206T133854Z
20181206/us-east-1/dynamodb/aws4_request
4ac99edb39a8a2d8317a34783358353dfa1d24407db7201eb1e288d717b8ee08
29609 [main] DEBUG com.gamepix.SimplifiedFuture - Operation db.getItem pk: test-player-id sk: test-game-id_storage is started
29610 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Creating an interceptor chain that will apply interceptors in the following order: [software.amazon.awssdk.services.s3.internal.handlers.EndpointAddressInterceptor@51e5fc98, software.amazon.awssdk.services.s3.internal.handlers.CreateBucketInterceptor@7c469c48, software.amazon.awssdk.services.s3.internal.handlers.PutObjectInterceptor@12e61fe6, software.amazon.awssdk.services.s3.internal.handlers.CreateMultipartUploadRequestInterceptor@7ee955a8, software.amazon.awssdk.services.s3.internal.handlers.EnableChunkedEncodingInterceptor@1677d1, software.amazon.awssdk.services.s3.internal.handlers.DisableDoubleUrlEncodingInterceptor@48fa0f47, software.amazon.awssdk.services.s3.internal.handlers.DecodeUrlEncodedResponseInterceptor@6ac13091, software.amazon.awssdk.services.s3.internal.handlers.AddContentMd5HeaderInterceptor@5e316c74, software.amazon.awssdk.services.s3.internal.handlers.GetBucketPolicyInterceptor@6d2a209c, software.amazon.awssdk.services.s3.internal.handlers.AsyncChecksumValidationInterceptor@75329a49, software.amazon.awssdk.services.s3.internal.handlers.SyncChecksumValidationInterceptor@161479c6, software.amazon.awssdk.services.s3.internal.handlers.EnableTrailingChecksumInterceptor@4313f5bc]
29611 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Interceptor 'software.amazon.awssdk.services.s3.internal.handlers.EndpointAddressInterceptor@51e5fc98' modified the message with its modifyHttpRequest method.
29611 [main] TRACE software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Old: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=s3.amazonaws.com, encodedPath=/gpx-play-profile/storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe, headers=[], queryParameters=[])
New: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe, headers=[], queryParameters=[])
29611 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Interceptor 'software.amazon.awssdk.services.s3.internal.handlers.PutObjectInterceptor@12e61fe6' modified the message with its modifyHttpRequest method.
29611 [main] TRACE software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Old: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe, headers=[], queryParameters=[])
New: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe, headers=[Expect], queryParameters=[])
29612 [main] DEBUG software.amazon.awssdk.request - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe, headers=[amz-sdk-invocation-id, Expect, User-Agent], queryParameters=[])
29613 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 Canonical Request: PUT
/storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe
amz-sdk-invocation-id:7121b55f-1d42-2b8b-fdd6-670d2b738d94
amz-sdk-retry:0/0/500
host:gpx-play-profile.s3.amazonaws.com
x-amz-content-sha256:UNSIGNED-PAYLOAD
x-amz-date:20181206T133854Z
x-amz-security-token:FQoGZXIvYXdzEAcaDCWPbFtwXb7Q1QABKiKCAjkIJo4bFeTPIQWncQPesu+2mdrEsHtJp+f3U+DUJa/GREeRgWMLPyghDn9daGQ5Qv/Ao/QtH8ztgzad+7I1mmAEhOTwzhMmCScMrNNFWpuH/WM8Dgb6KYBFo0GMp3Y5IDy1TwfSSYN2r0riNWIm8vGizNkS9cpARXCLCMdd/u4oevg9vXjeuIhEtdkDeNoRvmJcpCExfo01bLpG5NFNkd0FbIv7BujlV9AOtA26ybTj0VpUiVAXG+gZ+GIrv5vEW1pna4vU7EjxRsJ+1t6FXne7iug4Zf8twCmm8FHcifWrWF6anmufTuyTWIwIs+k+wUTBZaQK3woCMxMbdddTy7oE4yiRxKTgBQ==
amz-sdk-invocation-id;amz-sdk-retry;host;x-amz-content-sha256;x-amz-date;x-amz-security-token
UNSIGNED-PAYLOAD
29613 [main] DEBUG software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 String to sign: AWS4-HMAC-SHA256
20181206T133854Z
20181206/us-east-1/s3/aws4_request
be6140950463375120424c132c69ca5a51b7f6c9dc6e6b09dac075c83049f64f
29631 [main] DEBUG com.gamepix.SimplifiedFuture - Operation s3.putObject storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe is started
29631 [main] DEBUG com.gamepix.SimplifiedFuture - Awaiting end of operation s3.putObject storage/test-game-id/test-player-id/93aec021-51cd-452f-852b-6b3dbef6fcbe, time out 899722 ms
29693 [aws-java-sdk-NettyEventLoop-0-2] DEBUG software.amazon.awssdk.request - Received successful response: 200
29790 [Thread-4] TRACE software.amazon.awssdk.request - Parsing service response JSON.
29790 [Thread-4] DEBUG software.amazon.awssdk.requestId - x-amzn-RequestId : CB6NE7HGMTO9FEHNU8LB38HBBBVV4KQNSO5AEMVJF66Q9ASUAAJG
29791 [Thread-4] TRACE software.amazon.awssdk.request - Done parsing service response.
Event there is no 'REPORT RequestId: ...' record with duration time...
with --log-type Tail:
caiiiycuk@caiiiycuk-xps:~$ time aws lambda invoke --function-name gpx-play-profile-StoragePut-11YEYJRHHTYRM --region us-east-1 /tmp/log --log-type Tail --payload "\
{\
\"httpMethod\": \"POST\", \
\"queryStringParameters\": {\"id\":\"test-player-id\", \"game\":\"test-game-id\"}, \
\"body\": \"{'prefix1.v1':'value1','prefix1.v2':'value2','prefix1.v3':'value3'}\" \
}\
"
{
"StatusCode": 200,
"LogResult": "LnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkNyZWF0ZU11bHRpcGFydFVwbG9hZFJlcXVlc3RJbnRlcmNlcHRvckA3ZWU5NTVhOCwgc29mdHdhcmUuYW1hem9uLmF3c3Nkay5zZXJ2aWNlcy5zMy5pbnRlcm5hbC5oYW5kbGVycy5FbmFibGVDaHVua2VkRW5jb2RpbmdJbnRlcmNlcHRvckAxNjc3ZDEsIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuc2VydmljZXMuczMuaW50ZXJuYWwuaGFuZGxlcnMuRGlzYWJsZURvdWJsZVVybEVuY29kaW5nSW50ZXJjZXB0b3JANDhmYTBmNDcsIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuc2VydmljZXMuczMuaW50ZXJuYWwuaGFuZGxlcnMuRGVjb2RlVXJsRW5jb2RlZFJlc3BvbnNlSW50ZXJjZXB0b3JANmFjMTMwOTEsIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuc2VydmljZXMuczMuaW50ZXJuYWwuaGFuZGxlcnMuQWRkQ29udGVudE1kNUhlYWRlckludGVyY2VwdG9yQDVlMzE2Yzc0LCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkdldEJ1Y2tldFBvbGljeUludGVyY2VwdG9yQDZkMmEyMDljLCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkFzeW5jQ2hlY2tzdW1WYWxpZGF0aW9uSW50ZXJjZXB0b3JANzUzMjlhNDksIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuc2VydmljZXMuczMuaW50ZXJuYWwuaGFuZGxlcnMuU3luY0NoZWNrc3VtVmFsaWRhdGlvbkludGVyY2VwdG9yQDE2MTQ3OWM2LCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkVuYWJsZVRyYWlsaW5nQ2hlY2tzdW1JbnRlcmNlcHRvckA0MzEzZjViY10KMTE5NzMgW21haW5dIERFQlVHIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuY29yZS5pbnRlcmNlcHRvci5FeGVjdXRpb25JbnRlcmNlcHRvckNoYWluIC0gSW50ZXJjZXB0b3IgJ3NvZnR3YXJlLmFtYXpvbi5hd3NzZGsuc2VydmljZXMuczMuaW50ZXJuYWwuaGFuZGxlcnMuRW5kcG9pbnRBZGRyZXNzSW50ZXJjZXB0b3JANTFlNWZjOTgnIG1vZGlmaWVkIHRoZSBtZXNzYWdlIHdpdGggaXRzIG1vZGlmeUh0dHBSZXF1ZXN0IG1ldGhvZC4KMTE5NzMgW21haW5dIFRSQUNFIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuY29yZS5pbnRlcmNlcHRvci5FeGVjdXRpb25JbnRlcmNlcHRvckNoYWluIC0gT2xkOiBEZWZhdWx0U2RrSHR0cEZ1bGxSZXF1ZXN0KGh0dHBNZXRob2Q9REVMRVRFLCBwcm90b2NvbD1odHRwcywgaG9zdD1zMy5hbWF6b25hd3MuY29tLCBlbmNvZGVkUGF0aD0vZ3B4LXBsYXktcHJvZmlsZS9zdG9yYWdlL3Rlc3QtZ2FtZS1pZC90ZXN0LXBsYXllci1pZC8wMmIyY2UzNC0zZDJmLTQwMTMtYTAzYS0xZGI0NTQxZGJkMjYsIGhlYWRlcnM9W10sIHF1ZXJ5UGFyYW1ldGVycz1bXSkKTmV3OiBEZWZhdWx0U2RrSHR0cEZ1bGxSZXF1ZXN0KGh0dHBNZXRob2Q9REVMRVRFLCBwcm90b2NvbD1odHRwcywgaG9zdD1ncHgtcGxheS1wcm9maWxlLnMzLmFtYXpvbmF3cy5jb20sIHBvcnQ9NDQzLCBlbmNvZGVkUGF0aD0vc3RvcmFnZS90ZXN0LWdhbWUtaWQvdGVzdC1wbGF5ZXItaWQvMDJiMmNlMzQtM2QyZi00MDEzLWEwM2EtMWRiNDU0MWRiZDI2LCBoZWFkZXJzPVtdLCBxdWVyeVBhcmFtZXRlcnM9W10pCjExOTc0IFttYWluXSBERUJVRyBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnJlcXVlc3QgLSBTZW5kaW5nIFJlcXVlc3Q6IERlZmF1bHRTZGtIdHRwRnVsbFJlcXVlc3QoaHR0cE1ldGhvZD1ERUxFVEUsIHByb3RvY29sPWh0dHBzLCBob3N0PWdweC1wbGF5LXByb2ZpbGUuczMuYW1hem9uYXdzLmNvbSwgcG9ydD00NDMsIGVuY29kZWRQYXRoPS9zdG9yYWdlL3Rlc3QtZ2FtZS1pZC90ZXN0LXBsYXllci1pZC8wMmIyY2UzNC0zZDJmLTQwMTMtYTAzYS0xZGI0NTQxZGJkMjYsIGhlYWRlcnM9W2Ftei1zZGstaW52b2NhdGlvbi1pZCwgVXNlci1BZ2VudF0sIHF1ZXJ5UGFyYW1ldGVycz1bXSkKMTE5NzUgW21haW5dIFRSQUNFIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuYXV0aC5zaWduZXIuQXdzNFNpZ25lciAtIEFXUzQgQ2Fub25pY2FsIFJlcXVlc3Q6IERFTEVURQovc3RvcmFnZS90ZXN0LWdhbWUtaWQvdGVzdC1wbGF5ZXItaWQvMDJiMmNlMzQtM2QyZi00MDEzLWEwM2EtMWRiNDU0MWRiZDI2CgphbXotc2RrLWludm9jYXRpb24taWQ6YjAyNDEwOGQtNWUwMS1lMzUwLTc4NWItYzBlOTY3ZWRlODBmCmFtei1zZGstcmV0cnk6MC8wLzUwMApob3N0OmdweC1wbGF5LXByb2ZpbGUuczMuYW1hem9uYXdzLmNvbQp4LWFtei1jb250ZW50LXNoYTI1NjpVTlNJR05FRC1QQVlMT0FECngtYW16LWRhdGU6MjAxODEyMDZUMTM1MzA0Wgp4LWFtei1zZWN1cml0eS10b2tlbjpGUW9HWlhJdllYZHpFQWNhRENXUGJGdHdYYjdRMVFBQktpS0NBamtJSm80YkZlVFBJUVduY1FQZXN1KzJtZHJFc0h0SnArZjNVK0RVSmEvR1JFZVJnV01MUHlnaERuOWRhR1E1UXYvQW8vUXRIOHp0Z3phZCs3STFtbUFFaE9Ud3poTW1DU2NNck5ORldwdUgvV004RGdiNktZQkZvMEdNcDNZNUlEeTFUd2ZTU1lOMnIwcmlOV0ltOHZHaXpOa1M5Y3BBUlhDTENNZGQvdTRvZXZnOXZYamV1SWhFdGRrRGVOb1J2bUpjcENFeGZvMDFiTHBHNU5GTmtkMEZiSXY3QnVqbFY5QU90QTI2eWJUajBWcFVpVkFYRytnWitHSXJ2NXZFVzFwbmE0dlU3RWp4UnNKKzF0NkZYbmU3aXVnNFpmOHR3Q21tOEZIY2lmV3JXRjZhbm11ZlR1eVRXSXdJcytrK3dVVEJaYVFLM3dvQ014TWJkZGRUeTdvRTR5aVJ4S1RnQlE9PQoKYW16LXNkay1pbnZvY2F0aW9uLWlkO2Ftei1zZGstcmV0cnk7aG9zdDt4LWFtei1jb250ZW50LXNoYTI1Njt4LWFtei1kYXRlO3gtYW16LXNlY3VyaXR5LXRva2VuClVOU0lHTkVELVBBWUxPQUQKMTE5NzUgW21haW5dIERFQlVHIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuYXV0aC5zaWduZXIuQXdzNFNpZ25lciAtIEFXUzQgU3RyaW5nIHRvIHNpZ246IEFXUzQtSE1BQy1TSEEyNTYKMjAxODEyMDZUMTM1MzA0WgoyMDE4MTIwNi91cy1lYXN0LTEvczMvYXdzNF9yZXF1ZXN0CmZhOTdmNmUyMTU3OTBjYjExZmI1NDBmZTgxNjQ2MTdlOTViYWRiZTkzNzNlNDZmNzRmNDRlNTgxMWIyMDJkOWQKMTE5OTIgW21haW5dIERFQlVHIGNvbS5nYW1lcGl4LlNpbXBsaWZpZWRGdXR1cmUgLSBPcGVyYXRpb24gczMuZGVsZXRlT2JqZWN0IHN0b3JhZ2UvdGVzdC1nYW1lLWlkL3Rlc3QtcGxheWVyLWlkLzAyYjJjZTM0LTNkMmYtNDAxMy1hMDNhLTFkYjQ1NDFkYmQyNiBpcyBzdGFydGVkCjEyMDExIFttYWluXSBERUJVRyBjb20uZ2FtZXBpeC5TaW1wbGlmaWVkRnV0dXJlIC0gQXdhaXRpbmcgZW5kIG9mIG9wZXJhdGlvbiBzMy5kZWxldGVPYmplY3Qgc3RvcmFnZS90ZXN0LWdhbWUtaWQvdGVzdC1wbGF5ZXItaWQvMDJiMmNlMzQtM2QyZi00MDEzLWEwM2EtMWRiNDU0MWRiZDI2LCB0aW1lIG91dCA4ODgyNDYgbXMKMTIwNjIgW2F3cy1qYXZhLXNkay1OZXR0eUV2ZW50TG9vcC0wLTFdIERFQlVHIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsucmVxdWVzdCAtIFJlY2VpdmVkIHN1Y2Nlc3NmdWwgcmVzcG9uc2U6IDIwNAoxMjA3MiBbVGhyZWFkLTNdIFRSQUNFIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsucmVxdWVzdCAtIFBhcnNpbmcgc2VydmljZSByZXNwb25zZSBYTUwuCjEyMDkyIFtUaHJlYWQtM10gVFJBQ0Ugc29mdHdhcmUuYW1hem9uLmF3c3Nkay5yZXF1ZXN0IC0gRG9uZSBwYXJzaW5nIHNlcnZpY2UgcmVzcG9uc2UuCjEyMTExIFttYWluXSBERUJVRyBjb20uZ2FtZXBpeC5TaW1wbGlmaWVkRnV0dXJlIC0gT3BlcmF0aW9uIHMzLmRlbGV0ZU9iamVjdCBzdG9yYWdlL3Rlc3QtZ2FtZS1pZC90ZXN0LXBsYXllci1pZC8wMmIyY2UzNC0zZDJmLTQwMTMtYTAzYS0xZGI0NTQxZGJkMjYgaXMgZmluaXNoZWQsIGNvbnN1bWVkIHRpbWUgMTAxIG1zCkVORCBSZXF1ZXN0SWQ6IDM5MjQ0M2RkLWY5NWUtMTFlOC1hMzRkLTAxODQyZDk3ZmUyYwpSRVBPUlQgUmVxdWVzdElkOiAzOTI0NDNkZC1mOTVlLTExZTgtYTM0ZC0wMTg0MmQ5N2ZlMmMJRHVyYXRpb246IDExODE3LjM2IG1zCUJpbGxlZCBEdXJhdGlvbjogMTE5MDAgbXMgCU1lbW9yeSBTaXplOiA1MTIgTUIJTWF4IE1lbW9yeSBVc2VkOiAxMDIgTUIJCg==",
"ExecutedVersion": "$LATEST"
}
real 0m14,227s
user 0m0,405s
sys 0m0,077s
caiiiycuk@caiiiycuk-xps:~$ time aws lambda invoke --function-name gpx-play-profile-StoragePut-11YEYJRHHTYRM --region us-east-1 /tmp/log --log-type Tail --payload "\
{\
\"httpMethod\": \"POST\", \
\"queryStringParameters\": {\"id\":\"test-player-id\", \"game\":\"test-game-id\"}, \
\"body\": \"{'prefix1.v1':'value1','prefix1.v2':'value2','prefix1.v3':'value3'}\" \
}\
"
{
"StatusCode": 200,
"LogResult": "ay5zZXJ2aWNlcy5zMy5pbnRlcm5hbC5oYW5kbGVycy5DcmVhdGVNdWx0aXBhcnRVcGxvYWRSZXF1ZXN0SW50ZXJjZXB0b3JAN2VlOTU1YTgsIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsuc2VydmljZXMuczMuaW50ZXJuYWwuaGFuZGxlcnMuRW5hYmxlQ2h1bmtlZEVuY29kaW5nSW50ZXJjZXB0b3JAMTY3N2QxLCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkRpc2FibGVEb3VibGVVcmxFbmNvZGluZ0ludGVyY2VwdG9yQDQ4ZmEwZjQ3LCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkRlY29kZVVybEVuY29kZWRSZXNwb25zZUludGVyY2VwdG9yQDZhYzEzMDkxLCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkFkZENvbnRlbnRNZDVIZWFkZXJJbnRlcmNlcHRvckA1ZTMxNmM3NCwgc29mdHdhcmUuYW1hem9uLmF3c3Nkay5zZXJ2aWNlcy5zMy5pbnRlcm5hbC5oYW5kbGVycy5HZXRCdWNrZXRQb2xpY3lJbnRlcmNlcHRvckA2ZDJhMjA5Yywgc29mdHdhcmUuYW1hem9uLmF3c3Nkay5zZXJ2aWNlcy5zMy5pbnRlcm5hbC5oYW5kbGVycy5Bc3luY0NoZWNrc3VtVmFsaWRhdGlvbkludGVyY2VwdG9yQDc1MzI5YTQ5LCBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLlN5bmNDaGVja3N1bVZhbGlkYXRpb25JbnRlcmNlcHRvckAxNjE0NzljNiwgc29mdHdhcmUuYW1hem9uLmF3c3Nkay5zZXJ2aWNlcy5zMy5pbnRlcm5hbC5oYW5kbGVycy5FbmFibGVUcmFpbGluZ0NoZWNrc3VtSW50ZXJjZXB0b3JANDMxM2Y1YmNdCjExNzc5IFttYWluXSBERUJVRyBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLmNvcmUuaW50ZXJjZXB0b3IuRXhlY3V0aW9uSW50ZXJjZXB0b3JDaGFpbiAtIEludGVyY2VwdG9yICdzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnNlcnZpY2VzLnMzLmludGVybmFsLmhhbmRsZXJzLkVuZHBvaW50QWRkcmVzc0ludGVyY2VwdG9yQDUxZTVmYzk4JyBtb2RpZmllZCB0aGUgbWVzc2FnZSB3aXRoIGl0cyBtb2RpZnlIdHRwUmVxdWVzdCBtZXRob2QuCjExNzc5IFttYWluXSBUUkFDRSBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLmNvcmUuaW50ZXJjZXB0b3IuRXhlY3V0aW9uSW50ZXJjZXB0b3JDaGFpbiAtIE9sZDogRGVmYXVsdFNka0h0dHBGdWxsUmVxdWVzdChodHRwTWV0aG9kPURFTEVURSwgcHJvdG9jb2w9aHR0cHMsIGhvc3Q9czMuYW1hem9uYXdzLmNvbSwgZW5jb2RlZFBhdGg9L2dweC1wbGF5LXByb2ZpbGUvc3RvcmFnZS90ZXN0LWdhbWUtaWQvdGVzdC1wbGF5ZXItaWQvODM0ZjBiNTctM2M0NS00ZTRjLWIzYjctZDExYWQ3OGE1NTI1LCBoZWFkZXJzPVtdLCBxdWVyeVBhcmFtZXRlcnM9W10pCk5ldzogRGVmYXVsdFNka0h0dHBGdWxsUmVxdWVzdChodHRwTWV0aG9kPURFTEVURSwgcHJvdG9jb2w9aHR0cHMsIGhvc3Q9Z3B4LXBsYXktcHJvZmlsZS5zMy5hbWF6b25hd3MuY29tLCBwb3J0PTQ0MywgZW5jb2RlZFBhdGg9L3N0b3JhZ2UvdGVzdC1nYW1lLWlkL3Rlc3QtcGxheWVyLWlkLzgzNGYwYjU3LTNjNDUtNGU0Yy1iM2I3LWQxMWFkNzhhNTUyNSwgaGVhZGVycz1bXSwgcXVlcnlQYXJhbWV0ZXJzPVtdKQoxMTc4MCBbbWFpbl0gREVCVUcgc29mdHdhcmUuYW1hem9uLmF3c3Nkay5yZXF1ZXN0IC0gU2VuZGluZyBSZXF1ZXN0OiBEZWZhdWx0U2RrSHR0cEZ1bGxSZXF1ZXN0KGh0dHBNZXRob2Q9REVMRVRFLCBwcm90b2NvbD1odHRwcywgaG9zdD1ncHgtcGxheS1wcm9maWxlLnMzLmFtYXpvbmF3cy5jb20sIHBvcnQ9NDQzLCBlbmNvZGVkUGF0aD0vc3RvcmFnZS90ZXN0LWdhbWUtaWQvdGVzdC1wbGF5ZXItaWQvODM0ZjBiNTctM2M0NS00ZTRjLWIzYjctZDExYWQ3OGE1NTI1LCBoZWFkZXJzPVthbXotc2RrLWludm9jYXRpb24taWQsIFVzZXItQWdlbnRdLCBxdWVyeVBhcmFtZXRlcnM9W10pCjExNzgwIFttYWluXSBUUkFDRSBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLmF1dGguc2lnbmVyLkF3czRTaWduZXIgLSBBV1M0IENhbm9uaWNhbCBSZXF1ZXN0OiBERUxFVEUKL3N0b3JhZ2UvdGVzdC1nYW1lLWlkL3Rlc3QtcGxheWVyLWlkLzgzNGYwYjU3LTNjNDUtNGU0Yy1iM2I3LWQxMWFkNzhhNTUyNQoKYW16LXNkay1pbnZvY2F0aW9uLWlkOmM1ZDIyOTc5LTNjYzgtZjNkMi1mOGI3LTZlZjkzM2ZjMWE2YQphbXotc2RrLXJldHJ5OjAvMC81MDAKaG9zdDpncHgtcGxheS1wcm9maWxlLnMzLmFtYXpvbmF3cy5jb20KeC1hbXotY29udGVudC1zaGEyNTY6VU5TSUdORUQtUEFZTE9BRAp4LWFtei1kYXRlOjIwMTgxMjA2VDEzNTUzOFoKeC1hbXotc2VjdXJpdHktdG9rZW46RlFvR1pYSXZZWGR6RUFjYURDV1BiRnR3WGI3UTFRQUJLaUtDQWprSUpvNGJGZVRQSVFXbmNRUGVzdSsybWRyRXNIdEpwK2YzVStEVUphL0dSRWVSZ1dNTFB5Z2hEbjlkYUdRNVF2L0FvL1F0SDh6dGd6YWQrN0kxbW1BRWhPVHd6aE1tQ1NjTXJOTkZXcHVIL1dNOERnYjZLWUJGbzBHTXAzWTVJRHkxVHdmU1NZTjJyMHJpTldJbTh2R2l6TmtTOWNwQVJYQ0xDTWRkL3U0b2V2Zzl2WGpldUloRXRka0RlTm9Sdm1KY3BDRXhmbzAxYkxwRzVORk5rZDBGYkl2N0J1amxWOUFPdEEyNnliVGowVnBVaVZBWEcrZ1orR0lydjV2RVcxcG5hNHZVN0VqeFJzSisxdDZGWG5lN2l1ZzRaZjh0d0NtbThGSGNpZldyV0Y2YW5tdWZUdXlUV0l3SXMrayt3VVRCWmFRSzN3b0NNeE1iZGRkVHk3b0U0eWlSeEtUZ0JRPT0KCmFtei1zZGstaW52b2NhdGlvbi1pZDthbXotc2RrLXJldHJ5O2hvc3Q7eC1hbXotY29udGVudC1zaGEyNTY7eC1hbXotZGF0ZTt4LWFtei1zZWN1cml0eS10b2tlbgpVTlNJR05FRC1QQVlMT0FECjExNzgxIFttYWluXSBERUJVRyBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLmF1dGguc2lnbmVyLkF3czRTaWduZXIgLSBBV1M0IFN0cmluZyB0byBzaWduOiBBV1M0LUhNQUMtU0hBMjU2CjIwMTgxMjA2VDEzNTUzOFoKMjAxODEyMDYvdXMtZWFzdC0xL3MzL2F3czRfcmVxdWVzdAo4NDVlY2E4NmI5MGU0NTFiMzNhZDZmMmM1MDMzZDNlODBhNTJmYWQ0MDY1N2VmNmRhNTQ2Y2I5ZmU4ZGNmMzI3CjExNzk4IFttYWluXSBERUJVRyBjb20uZ2FtZXBpeC5TaW1wbGlmaWVkRnV0dXJlIC0gT3BlcmF0aW9uIHMzLmRlbGV0ZU9iamVjdCBzdG9yYWdlL3Rlc3QtZ2FtZS1pZC90ZXN0LXBsYXllci1pZC84MzRmMGI1Ny0zYzQ1LTRlNGMtYjNiNy1kMTFhZDc4YTU1MjUgaXMgc3RhcnRlZAoxMTc5OCBbbWFpbl0gREVCVUcgY29tLmdhbWVwaXguU2ltcGxpZmllZEZ1dHVyZSAtIEF3YWl0aW5nIGVuZCBvZiBvcGVyYXRpb24gczMuZGVsZXRlT2JqZWN0IHN0b3JhZ2UvdGVzdC1nYW1lLWlkL3Rlc3QtcGxheWVyLWlkLzgzNGYwYjU3LTNjNDUtNGU0Yy1iM2I3LWQxMWFkNzhhNTUyNSwgdGltZSBvdXQgODg4NDQ5IG1zCjExODEwIFthd3MtamF2YS1zZGstTmV0dHlFdmVudExvb3AtMC0xXSBERUJVRyBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnJlcXVlc3QgLSBSZWNlaXZlZCBzdWNjZXNzZnVsIHJlc3BvbnNlOiAyMDQKMTE4MTcgW1RocmVhZC0zXSBUUkFDRSBzb2Z0d2FyZS5hbWF6b24uYXdzc2RrLnJlcXVlc3QgLSBQYXJzaW5nIHNlcnZpY2UgcmVzcG9uc2UgWE1MLgoxMTgyMSBbVGhyZWFkLTNdIFRSQUNFIHNvZnR3YXJlLmFtYXpvbi5hd3NzZGsucmVxdWVzdCAtIERvbmUgcGFyc2luZyBzZXJ2aWNlIHJlc3BvbnNlLgoxMTgyMSBbbWFpbl0gREVCVUcgY29tLmdhbWVwaXguU2ltcGxpZmllZEZ1dHVyZSAtIE9wZXJhdGlvbiBzMy5kZWxldGVPYmplY3Qgc3RvcmFnZS90ZXN0LWdhbWUtaWQvdGVzdC1wbGF5ZXItaWQvODM0ZjBiNTctM2M0NS00ZTRjLWIzYjctZDExYWQ3OGE1NTI1IGlzIGZpbmlzaGVkLCBjb25zdW1lZCB0aW1lIDIzIG1zCkVORCBSZXF1ZXN0SWQ6IDk1OGJjZjk1LWY5NWUtMTFlOC1iNjE5LTlkN2YwZDcwZGU5MwpSRVBPUlQgUmVxdWVzdElkOiA5NThiY2Y5NS1mOTVlLTExZTgtYjYxOS05ZDdmMGQ3MGRlOTMJRHVyYXRpb246IDExNDc0LjM0IG1zCUJpbGxlZCBEdXJhdGlvbjogMTE1MDAgbXMgCU1lbW9yeSBTaXplOiA1MTIgTUIJTWF4IE1lbW9yeSBVc2VkOiAxMDMgTUIJCg==",
"ExecutedVersion": "$LATEST"
}
real 2m16,552s
user 0m0,478s
sys 0m0,057s
decoded logs:
k.services.s3.internal.handlers.CreateMultipartUploadRequestInterceptor@7ee955a8, software.amazon.awssdk.services.s3.internal.handlers.EnableChunkedEncodingInterceptor@1677d1, software.amazon.awssdk.services.s3.internal.handlers.DisableDoubleUrlEncodingInterceptor@48fa0f47, software.amazon.awssdk.services.s3.internal.handlers.DecodeUrlEncodedResponseInterceptor@6ac13091, software.amazon.awssdk.services.s3.internal.handlers.AddContentMd5HeaderInterceptor@5e316c74, software.amazon.awssdk.services.s3.internal.handlers.GetBucketPolicyInterceptor@6d2a209c, software.amazon.awssdk.services.s3.internal.handlers.AsyncChecksumValidationInterceptor@75329a49, software.amazon.awssdk.services.s3.internal.handlers.SyncChecksumValidationInterceptor@161479c6, software.amazon.awssdk.services.s3.internal.handlers.EnableTrailingChecksumInterceptor@4313f5bc]
11779 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Interceptor 'software.amazon.awssdk.services.s3.internal.handlers.EndpointAddressInterceptor@51e5fc98' modified the message with its modifyHttpRequest method.
11779 [main] TRACE software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Old: DefaultSdkHttpFullRequest(httpMethod=DELETE, protocol=https, host=s3.amazonaws.com, encodedPath=/gpx-play-profile/storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525, headers=[], queryParameters=[])
New: DefaultSdkHttpFullRequest(httpMethod=DELETE, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525, headers=[], queryParameters=[])
11780 [main] DEBUG software.amazon.awssdk.request - Sending Request: DefaultSdkHttpFullRequest(httpMethod=DELETE, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525, headers=[amz-sdk-invocation-id, User-Agent], queryParameters=[])
11780 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 Canonical Request: DELETE
/storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525
amz-sdk-invocation-id:c5d22979-3cc8-f3d2-f8b7-6ef933fc1a6a
amz-sdk-retry:0/0/500
host:gpx-play-profile.s3.amazonaws.com
x-amz-content-sha256:UNSIGNED-PAYLOAD
x-amz-date:20181206T135538Z
x-amz-security-token:FQoGZXIvYXdzEAcaDCWPbFtwXb7Q1QABKiKCAjkIJo4bFeTPIQWncQPesu+2mdrEsHtJp+f3U+DUJa/GREeRgWMLPyghDn9daGQ5Qv/Ao/QtH8ztgzad+7I1mmAEhOTwzhMmCScMrNNFWpuH/WM8Dgb6KYBFo0GMp3Y5IDy1TwfSSYN2r0riNWIm8vGizNkS9cpARXCLCMdd/u4oevg9vXjeuIhEtdkDeNoRvmJcpCExfo01bLpG5NFNkd0FbIv7BujlV9AOtA26ybTj0VpUiVAXG+gZ+GIrv5vEW1pna4vU7EjxRsJ+1t6FXne7iug4Zf8twCmm8FHcifWrWF6anmufTuyTWIwIs+k+wUTBZaQK3woCMxMbdddTy7oE4yiRxKTgBQ==
amz-sdk-invocation-id;amz-sdk-retry;host;x-amz-content-sha256;x-amz-date;x-amz-security-token
UNSIGNED-PAYLOAD
11781 [main] DEBUG software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 String to sign: AWS4-HMAC-SHA256
20181206T135538Z
20181206/us-east-1/s3/aws4_request
845eca86b90e451b33ad6f2c5033d3e80a52fad40657ef6da546cb9fe8dcf327
11798 [main] DEBUG com.gamepix.SimplifiedFuture - Operation s3.deleteObject storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525 is started
11798 [main] DEBUG com.gamepix.SimplifiedFuture - Awaiting end of operation s3.deleteObject storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525, time out 888449 ms
11810 [aws-java-sdk-NettyEventLoop-0-1] DEBUG software.amazon.awssdk.request - Received successful response: 204
11817 [Thread-3] TRACE software.amazon.awssdk.request - Parsing service response XML.
11821 [Thread-3] TRACE software.amazon.awssdk.request - Done parsing service response.
11821 [main] DEBUG com.gamepix.SimplifiedFuture - Operation s3.deleteObject storage/test-game-id/test-player-id/834f0b57-3c45-4e4c-b3b7-d11ad78a5525 is finished, consumed time 23 ms
END RequestId: 958bcf95-f95e-11e8-b619-9d7f0d70de93
REPORT RequestId: 958bcf95-f95e-11e8-b619-9d7f0d70de93 Duration: 11474.34 ms Billed Duration: 11500 ms Memory Size: 512 MB Max Memory Used: 103 MB
real time is 2m, but in logs only 11 sec. But in cloud logs I did not see this "tail part", looks like jvm was terminated in the middle and then request is restart, is it possible?
Another log with >900s execution time:
START RequestId: 7091b82f-f95e-11e8-9ca8-93046b8ed0c5 Version: $LATEST
881 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
917 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
917 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 8
919 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
920 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
920 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
920 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: available
921 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
921 [main] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
921 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
921 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
922 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
922 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
923 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 441974784 bytes
923 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
925 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
925 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
1000 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 4
1158 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
1158 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
1200 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
1222 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@22a67b4
1223 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@57855c9a
1223 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3b084709
1223 [main] TRACE io.netty.channel.nio.NioEventLoop - instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@3224f60b
3518 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Creating an interceptor chain that will apply interceptors in the following order: []
3919 [main] DEBUG software.amazon.awssdk.request - Sending Request: DefaultSdkHttpFullRequest(httpMethod=POST, protocol=https, host=dynamodb.us-east-1.amazonaws.com, encodedPath=/, headers=[amz-sdk-invocation-id, Content-Length, Content-Type, User-Agent, X-Amz-Target], queryParameters=[])
4078 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 Canonical Request: POST
/
amz-sdk-invocation-id:3dbd83ab-5ec1-4a28-912e-5698105227de
amz-sdk-retry:0/0/500
content-length:104
content-type:application/x-amz-json-1.0
host:dynamodb.us-east-1.amazonaws.com
x-amz-date:20181206T135428Z
x-amz-security-token:FQoGZXIvYXdzEAcaDCWPbFtwXb7Q1QABKiKCAjkIJo4bFeTPIQWncQPesu+2mdrEsHtJp+f3U+DUJa/GREeRgWMLPyghDn9daGQ5Qv/Ao/QtH8ztgzad+7I1mmAEhOTwzhMmCScMrNNFWpuH/WM8Dgb6KYBFo0GMp3Y5IDy1TwfSSYN2r0riNWIm8vGizNkS9cpARXCLCMdd/u4oevg9vXjeuIhEtdkDeNoRvmJcpCExfo01bLpG5NFNkd0FbIv7BujlV9AOtA26ybTj0VpUiVAXG+gZ+GIrv5vEW1pna4vU7EjxRsJ+1t6FXne7iug4Zf8twCmm8FHcifWrWF6anmufTuyTWIwIs+k+wUTBZaQK3woCMxMbdddTy7oE4yiRxKTgBQ==
x-amz-target:DynamoDB_20120810.GetItem
amz-sdk-invocation-id;amz-sdk-retry;content-length;content-type;host;x-amz-date;x-amz-security-token;x-amz-target
c27ae70d80ef53c618222243ba0c04c18c8aed3c612512d545881038402a232e
4080 [main] DEBUG software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 String to sign: AWS4-HMAC-SHA256
20181206T135428Z
20181206/us-east-1/dynamodb/aws4_request
fc078909d83f05f7f26222b0c216601be7d3a95ba36d46e1937bc9765f7fe1d9
4099 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - Generating a new signing key as the signing key not available in the cache for the date: 1544054400000
4484 [main] DEBUG io.netty.handler.ssl.OpenSsl - netty-tcnative not in the classpath; OpenSslEngine will be unavailable.
5540 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1]
5540 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA]
5839 [main] DEBUG com.gamepix.SimplifiedFuture - Operation db.getItem pk: test-player-id sk: test-game-id_storage is started
5839 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 1 (auto-detected)
5862 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: true
5862 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
5864 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.NetUtil - Loopback interface: lo (lo, 127.0.0.1)
5865 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 128
5918 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 9e:9e:c5:ff:fe:1d:ac:1a (auto-detected)
5961 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
5997 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
6080 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
6080 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
6321 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Creating an interceptor chain that will apply interceptors in the following order: [software.amazon.awssdk.services.s3.internal.handlers.EndpointAddressInterceptor@51e5fc98, software.amazon.awssdk.services.s3.internal.handlers.CreateBucketInterceptor@7c469c48, software.amazon.awssdk.services.s3.internal.handlers.PutObjectInterceptor@12e61fe6, software.amazon.awssdk.services.s3.internal.handlers.CreateMultipartUploadRequestInterceptor@7ee955a8, software.amazon.awssdk.services.s3.internal.handlers.EnableChunkedEncodingInterceptor@1677d1, software.amazon.awssdk.services.s3.internal.handlers.DisableDoubleUrlEncodingInterceptor@48fa0f47, software.amazon.awssdk.services.s3.internal.handlers.DecodeUrlEncodedResponseInterceptor@6ac13091, software.amazon.awssdk.services.s3.internal.handlers.AddContentMd5HeaderInterceptor@5e316c74, software.amazon.awssdk.services.s3.internal.handlers.GetBucketPolicyInterceptor@6d2a209c, software.amazon.awssdk.services.s3.internal.handlers.AsyncChecksumValidationInterceptor@75329a49, software.amazon.awssdk.services.s3.internal.handlers.SyncChecksumValidationInterceptor@161479c6, software.amazon.awssdk.services.s3.internal.handlers.EnableTrailingChecksumInterceptor@4313f5bc]
6401 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 4
6401 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 4
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
6417 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
6558 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
6577 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
6577 [aws-java-sdk-NettyEventLoop-0-0] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
6598 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Interceptor 'software.amazon.awssdk.services.s3.internal.handlers.EndpointAddressInterceptor@51e5fc98' modified the message with its modifyHttpRequest method.
6598 [main] TRACE software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Old: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=s3.amazonaws.com, encodedPath=/gpx-play-profile/storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7, headers=[], queryParameters=[])
New: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7, headers=[], queryParameters=[])
6697 [main] DEBUG software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Interceptor 'software.amazon.awssdk.services.s3.internal.handlers.PutObjectInterceptor@12e61fe6' modified the message with its modifyHttpRequest method.
6697 [main] TRACE software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain - Old: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7, headers=[], queryParameters=[])
New: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7, headers=[Expect], queryParameters=[])
6700 [main] DEBUG software.amazon.awssdk.request - Sending Request: DefaultSdkHttpFullRequest(httpMethod=PUT, protocol=https, host=gpx-play-profile.s3.amazonaws.com, port=443, encodedPath=/storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7, headers=[amz-sdk-invocation-id, Expect, User-Agent], queryParameters=[])
6817 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 Canonical Request: PUT
/storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7
amz-sdk-invocation-id:de6cbcb7-fd00-80e2-10fe-40953e276375
amz-sdk-retry:0/0/500
host:gpx-play-profile.s3.amazonaws.com
x-amz-content-sha256:UNSIGNED-PAYLOAD
x-amz-date:20181206T135431Z
x-amz-security-token:FQoGZXIvYXdzEAcaDCWPbFtwXb7Q1QABKiKCAjkIJo4bFeTPIQWncQPesu+2mdrEsHtJp+f3U+DUJa/GREeRgWMLPyghDn9daGQ5Qv/Ao/QtH8ztgzad+7I1mmAEhOTwzhMmCScMrNNFWpuH/WM8Dgb6KYBFo0GMp3Y5IDy1TwfSSYN2r0riNWIm8vGizNkS9cpARXCLCMdd/u4oevg9vXjeuIhEtdkDeNoRvmJcpCExfo01bLpG5NFNkd0FbIv7BujlV9AOtA26ybTj0VpUiVAXG+gZ+GIrv5vEW1pna4vU7EjxRsJ+1t6FXne7iug4Zf8twCmm8FHcifWrWF6anmufTuyTWIwIs+k+wUTBZaQK3woCMxMbdddTy7oE4yiRxKTgBQ==
amz-sdk-invocation-id;amz-sdk-retry;host;x-amz-content-sha256;x-amz-date;x-amz-security-token
UNSIGNED-PAYLOAD
6818 [main] DEBUG software.amazon.awssdk.auth.signer.Aws4Signer - AWS4 String to sign: AWS4-HMAC-SHA256
20181206T135431Z
20181206/us-east-1/s3/aws4_request
4a9dc9470e48bfe0127f06f037e46bdbb28a50b8fa19aed0bf58254b431168ba
6818 [main] TRACE software.amazon.awssdk.auth.signer.Aws4Signer - Generating a new signing key as the signing key not available in the cache for the date: 1544054400000
6898 [main] DEBUG com.gamepix.SimplifiedFuture - Operation s3.putObject storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7 is started
6899 [main] DEBUG com.gamepix.SimplifiedFuture - Awaiting end of operation s3.putObject storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7, time out 893345 ms
7198 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
7198 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
7200 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@981c9b7
7444 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
7444 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
7444 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
7444 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
10938 [aws-java-sdk-NettyEventLoop-0-3] DEBUG io.netty.handler.ssl.SslHandler - [id: 0xc1d00814, L:/169.254.76.17:40058 - R:gpx-play-profile.s3.amazonaws.com/52.216.132.243:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
10977 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0x8d5ff028, L:/169.254.76.17:54874 - R:dynamodb.us-east-1.amazonaws.com/52.119.232.242:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
11037 [aws-java-sdk-NettyEventLoop-0-2] DEBUG io.netty.handler.ssl.SslHandler - [id: 0xb5749af7, L:/169.254.76.17:54878 - R:dynamodb.us-east-1.amazonaws.com/52.119.232.242:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
11197 [aws-java-sdk-NettyEventLoop-0-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0x3f65a3f8, L:/169.254.76.17:40064 - R:gpx-play-profile.s3.amazonaws.com/52.216.132.243:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
11499 [aws-java-sdk-NettyEventLoop-0-2] DEBUG software.amazon.awssdk.request - Received successful response: 200
12101 [Thread-0] TRACE software.amazon.awssdk.request - Parsing service response JSON.
12177 [Thread-0] DEBUG software.amazon.awssdk.requestId - x-amzn-RequestId : DHG9364635E0J6O9TSLR2NTT3FVV4KQNSO5AEMVJF66Q9ASUAAJG
12338 [Thread-0] TRACE software.amazon.awssdk.request - Done parsing service response.
900244 [main] DEBUG com.gamepix.SimplifiedFuture - Operation s3.putObject storage/test-game-id/test-player-id/d2c95db2-bbf6-4c64-b405-d6027dd908a7 is time outed
900244 [main] ERROR com.gamepix.gateway.StoragePut - null
java.util.concurrent.TimeoutException
at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at com.gamepix.SimplifiedFuture.await(SimplifiedFuture.java:56)
at com.gamepix.gateway.StoragePut.handleRequest(StoragePut.java:75)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at lambdainternal.EventHandlerLoader$PojoMethodRequestHandler.handleRequest(EventHandlerLoader.java:259)
at lambdainternal.EventHandlerLoader$PojoHandlerAsStreamHandler.handleRequest(EventHandlerLoader.java:178)
at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:888)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:293)
at lambdainternal.AWSLambda.<clinit>(AWSLambda.java:64)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at lambdainternal.LambdaRTEntry.main(LambdaRTEntry.java:104)
END RequestId: 7091b82f-f95e-11e8-9ca8-93046b8ed0c5
REPORT RequestId: 7091b82f-f95e-11e8-9ca8-93046b8ed0c5 Duration: 899917.67 ms Billed Duration: 900000 ms Memory Size: 512 MB Max Memory Used: 110 MB
It's strange because my http client is configured for timeout for 5s on connection/read/write
Thank you for reporting. This has been fixed via #889 and we will do a release soon.
Please try with 2.1.4
and feel free to reopen if you continue to see this error.
Looks working! Thanks!
Hi! I am trying to write simple endpoint that put string into s3 object. I use this code to create client:
Where httpClient is:
I create
S3AsyncClient
and save it in static variable, so while my lambda is live this client is reused. Next I have lambda that simply put 'string' into s3 object:Lambda is triggered by API endpoint. I deploy this lambda on aws, and then make request to it with curl.
My first request completes successfully My second request, third and next requests always failed by timeout on putObject. And after a while ... all others request completes successfully
This logs for first call:
This is logs of second call
This is logs for calls after a while:
Your Environment