Bug #18230
openrgw: ERROR: got unexpected error when trying to read object: -2
0%
Description
I'm getting this error in the rgw log (client gets 404) when trying to GET some files (HEAD / bucket listing works properly).
Files
Updated by Martin Bureau over 7 years ago
I attached a log with the end of the multipart upload and the gc process removing files 3 hours later.
Following that, HEAD returns 200 but GET returns 404:
2016-12-11 02:14:10.151682 7f95267fc700 1 ====== starting new request req=0x7f95267f6710 =====
2016-12-11 02:14:10.156423 7f95267fc700 1 ====== req done req=0x7f95267f6710 op status=0 http_status=200 ======
2016-12-11 02:14:10.156476 7f95267fc700 1 civetweb: 0x7f95140008c0: 10.250.60.81 - - [11/Dec/2016:02:14:10 +0000] "HEAD /data/000/054/521/000054521823 HTTP/1.1" 200 0 - aws-sdk-java/1.11.37 Linux/2.6.32-431.23.3.el6.x86_64 OpenJDK_64-Bit_Server_VM/25.91-b14/1.8.0_91
2016-12-11 02:14:13.311567 7f94277fe700 1 ====== starting new request req=0x7f94277f8710 =====
2016-12-11 02:14:13.312386 7f94277fe700 1 ====== req done req=0x7f94277f8710 op status=0 http_status=200 ======
2016-12-11 02:14:13.312427 7f94277fe700 1 civetweb: 0x7f940c0008c0: 10.250.60.81 - - [11/Dec/2016:02:14:13 +0000] "HEAD / HTTP/1.0" 200 0 - -
2016-12-11 02:14:27.549083 7f9425ffb700 1 ====== starting new request req=0x7f9425ff5710 =====
2016-12-11 02:14:27.549903 7f9425ffb700 1 ====== req done req=0x7f9425ff5710 op status=0 http_status=200 ======
2016-12-11 02:14:27.549943 7f9425ffb700 1 civetweb: 0x7f93f80008c0: 10.250.60.81 - - [11/Dec/2016:02:14:27 +0000] "HEAD / HTTP/1.0" 200 0 - -
2016-12-11 02:14:43.321881 7f94d6ffd700 1 ====== starting new request req=0x7f94d6ff7710 =====
2016-12-11 02:14:43.322720 7f94d6ffd700 1 ====== req done req=0x7f94d6ff7710 op status=0 http_status=200 ======
2016-12-11 02:14:43.322776 7f94d6ffd700 1 civetweb: 0x7f94900008c0: 10.250.60.81 - - [11/Dec/2016:02:14:43 +0000] "HEAD / HTTP/1.0" 200 0 - -
2016-12-11 02:14:55.387455 7f941e7fc700 1 ====== starting new request req=0x7f941e7f6710 =====
2016-12-11 02:14:55.388294 7f941e7fc700 1 ====== req done req=0x7f941e7f6710 op status=0 http_status=200 ======
2016-12-11 02:14:55.388338 7f941e7fc700 1 civetweb: 0x7f93ec0008c0: 10.250.60.81 - - [11/Dec/2016:02:14:55 +0000] "GET / HTTP/1.1" 200 0 - nagios
2016-12-11 02:15:07.561363 7f94157fa700 1 ====== starting new request req=0x7f94157f4710 =====
2016-12-11 02:15:07.562213 7f94157fa700 1 ====== req done req=0x7f94157f4710 op status=0 http_status=200 ======
2016-12-11 02:15:07.562268 7f94157fa700 1 civetweb: 0x7f93c00008c0: 10.250.60.81 - - [11/Dec/2016:02:15:07 +0000] "HEAD / HTTP/1.0" 200 0 - -
2016-12-11 02:15:10.387223 7f94e7fff700 1 ====== starting new request req=0x7f94e7ff9710 =====
2016-12-11 02:15:10.392089 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
2016-12-11 02:15:10.392110 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
2016-12-11 02:15:10.392174 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
2016-12-11 02:15:10.392190 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
2016-12-11 02:15:10.392264 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
2016-12-11 02:15:10.392267 7f94e7fff700 1 ====== req done req=0x7f94e7ff9710 op status=-2 http_status=404 ======
2016-12-11 02:15:10.392350 7f94e7fff700 1 civetweb: 0x7f94d80008c0: 10.250.60.81 - - [11/Dec/2016:02:15:10 +0000] "GET /data/000/054/521/000054521823 HTTP/1.1" 404 0 - aws-sdk-java/1.11.37 Linux/2.6.32-431.23.3.el6.x86_64 OpenJDK_64-Bit_Server_VM/25.91-b14/1.8.0_91 com.amazonaws.services.s3.transfer.TransferManager/1.11.37
2016-12-11 02:15:10.392360 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
2016-12-11 02:15:10.392479 7f9672ffd700 0 ERROR: got unexpected error when trying to read object: -2
Updated by Martin Bureau over 7 years ago
Uploaded wrong logfile, this is the right file.
Updated by Martin Bureau over 7 years ago
object stat :
# radosgw-admin object stat --bucket=sam-storage-mtl-8m-00 --object=data/000/054/521/000054521823
{
"name": "data\/000\/054\/521\/000054521823",
"size": 29665881166,
"policy": {
"acl": {
"acl_user_map": [
{
"user": "sam",
"acl": 15
}
],
"acl_group_map": [
{
"group": 2,
"acl": 1
}
],
"grant_map": [
{
"id": "",
"grant": {
"type": {
"type": 2
},
"id": "",
"email": "",
"permission": {
"flags": 1
},
"name": "",
"group": 2
}
},
{
"id": "sam",
"grant": {
"type": {
"type": 0
},
"id": "sam",
"email": "",
"permission": {
"flags": 1
},
"name": "SAM User",
"group": 0
}
},
{
"id": "sam",
"grant": {
"type": {
"type": 0
},
"id": "sam",
"email": "",
"permission": {
"flags": 2
},
"name": "SAM User",
"group": 0
}
},
{
"id": "sam",
"grant": {
"type": {
"type": 0
},
"id": "sam",
"email": "",
"permission": {
"flags": 4
},
"name": "SAM User",
"group": 0
}
},
{
"id": "sam",
"grant": {
"type": {
"type": 0
},
"id": "sam",
"email": "",
"permission": {
"flags": 8
},
"name": "SAM User",
"group": 0
}
},
{
"id": "sam",
"grant": {
"type": {
"type": 0
},
"id": "sam",
"email": "",
"permission": {
"flags": 15
},
"name": "SAM User",
"group": 0
}
}
]
},
"owner": {
"id": "sam",
"display_name": "SAM User"
}
},
"etag": "130b76849d5707c09c0d6b87821d840e-5659\u0000",
"tag": "9efa3174-0317-4a8d-b1e0-4c37570e7b4c.764116.39751\u0000",
"manifest": {
"objs": [],
"obj_size": 29665881166,
"explicit_objs": "false",
"head_obj": {
"bucket": {
"name": "sam-storage-mtl-8m-00",
"pool": "default.rgw.buckets.data",
"data_extra_pool": "default.rgw.buckets.non-ec",
"index_pool": "default.rgw.buckets.index",
"marker": "9efa3174-0317-4a8d-b1e0-4c37570e7b4c.144598.1",
"bucket_id": "9efa3174-0317-4a8d-b1e0-4c37570e7b4c.144598.1",
"tenant": ""
},
"key": "",
"ns": "",
"object": "data\/000\/054\/521\/000054521823",
"instance": "",
"orig_obj": "data\/000\/054\/521\/000054521823"
},
"head_size": 0,
"max_head_size": 0,
"prefix": "data\/000\/054\/521\/000054521823.2~uzFqWJC-p3eihx-QqYx9OSJr4ulge9X",
"tail_bucket": {
"name": "sam-storage-mtl-8m-00",
"pool": "default.rgw.buckets.data",
"data_extra_pool": "default.rgw.buckets.non-ec",
"index_pool": "default.rgw.buckets.index",
"marker": "9efa3174-0317-4a8d-b1e0-4c37570e7b4c.144598.1",
"bucket_id": "9efa3174-0317-4a8d-b1e0-4c37570e7b4c.144598.1",
"tenant": ""
},
"rules": [
{
"key": 0,
"val": {
"start_part_num": 1,
"start_ofs": 0,
"part_size": 5242880,
"stripe_max_size": 4194304,
"override_prefix": ""
}
},
{
"key": 29664215040,
"val": {
"start_part_num": 5659,
"start_ofs": 29664215040,
"part_size": 1666126,
"stripe_max_size": 4194304,
"override_prefix": ""
}
}
],
"tail_instance": ""
},
"attrs": {
"user.rgw.content_type": "application\/octet-stream\u0000",
"user.rgw.pg_ver": "�J\u000f\u0000\u0000\u0000\u0000\u0000",
"user.rgw.source_zone": "\u0000\u0000\u0000\u0000",
"user.rgw.x-amz-grant-full-control": "id=\"sam\"\u0000",
"user.rgw.x-amz-grant-read": "uri=\"http:\/\/acs.amazonaws.com\/groups\/global\/AuthenticatedUsers\", id=\"sam\"\u0000",
"user.rgw.x-amz-grant-read-acp": "id=\"sam\"\u0000",
"user.rgw.x-amz-grant-write": "id=\"sam\"\u0000",
"user.rgw.x-amz-grant-write-acp": "id=\"sam\"\u0000",
"user.rgw.x-amz-storage-class": "REDUCED_REDUNDANCY\u0000"
}
}
Updated by Yehuda Sadeh over 7 years ago
the log provided shows that the multipart upload failed to complete for some reason, but can't really say what happened. Can you provide a log with 'debug rgw = 20' and 'debug ms = 1'?
Updated by Martin Bureau over 7 years ago
I will upload detailed logs as soon as I can reproduce the problem.
Updated by Yehuda Sadeh over 7 years ago
- Subject changed from ERROR: got unexpected error when trying to read object: -2 to rgw: ERROR: got unexpected error when trying to read object: -2
Updated by Matt Benjamin about 7 years ago
- Status changed from New to Need More Info
Still waiting for more info
Updated by Carles Pina Estany about 3 years ago
I'm a user of a Ceph installation (I don't have access to the server side logs). We recently had a case that looks similar to this ticket so I'm adding some information from the client point of view. I cannot confirm the exact versions of the server or log outputs.
Recap we have a situation like:
HEAD /file -> returns 200
GET /file -> returns 404
The file was a multi-part upload and it was not assembled correctly: the server had returned 500 and 502 to the client on that step.
The client tried to upload the file later on but before uploading the data the client tried to verify that the file is not already there requesting "HEAD /file". The client received HTTP 200 and never uploaded the data again assuming that the file was in the server at that point (file size and modified time or ETag match for this this client to assume that the file is there).
I think that the client (rclone v1.54.0) is well behaved: expects the HEAD headers (HTTP 200) to be the same as GET headers as per https://tools.ietf.org/html/rfc7231#section-4.3.2 ("The server SHOULD send the same header fields in response to a HEAD request as it would have sent if the request had been a GET").