Project

General

Profile

Actions
Copy link

Bug #52671

closed

Bucket index not always created when new object added

Added by Pietro Di Marco over 2 years ago. Updated over 2 years ago.

Status:
Duplicate
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

BACKGROUND：
Ceph version 16.2.5 (0883bdea7337b95e4b611c768c0279868462204a) pacific (stable)
Ceph health is OK
Deployed using Rook
Using EC/REPLICATED pool with 3 RGW instances

DESCRIBE:
When use S3 LIST_OBJECT() to list, some uploaded objects cannot be listed.
I am sure that the object has been uploaded because I can get it with the exact key.
Moreover I experience this only with RGW instances > 1, with a single RGW instance the issue is not reported.

SOME ELSE：

These files are uploaded by S3a file committer. I doubt this has something to do with the issue because the HTTP requests to the RGW are identical both in case of object uploaded correctly and not

Logs even at debug-level=20 do not report any error/warning

REQUEST LOGGED BY RGW

"PUT /ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb/tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet HTTP/1.1" 
200 238 - "Hadoop 2.8.5, aws-sdk-java/1.11.751 Linux/5.6.11-200.fc31.x86_64 OpenJDK_64-Bit_Server_VM/25.232-b09 
java/1.8.0_232 scala/2.11.12 vendor/Oracle_Corporation com.amazonaws.services.s3.transfer.TransferManager/1.11.751" - latency=0.167005762s

LIST OF COMMANDS ISSUED AND RESULTS:

radosgw-admin bi list --bucket=ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb | grep part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet

2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: starting msgr at
2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: starting objecter
2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: setting wanted keys
2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: calling monclient init
2021-09-20T15:50:10.648+0000 7f9bc5581340  1 librados: init done
2021-09-20T15:50:11.337+0000 7f9bc5581340  2 all 8 watchers are set, enabling cache
2021-09-20T15:50:11.399+0000 7f9b86fe5700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: starting msgr at
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: starting objecter
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: setting wanted keys
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: calling monclient init
2021-09-20T15:50:11.408+0000 7f9bc5581340  1 librados: init done
2021-09-20T15:50:13.777+0000 7f9bc5581340  2 removed watcher, disabling cache
2021-09-20T15:50:14.202+0000 7f9b86fe5700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:50:14.285+0000 7f9bc5581340  1 librados: shutdown
2021-09-20T15:50:14.286+0000 7f9bc5581340  1 librados: shutdown

FOR A FILE UPLOADED CORRECTLY:

radosgw-admin bi list --bucket=ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb | grep part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: starting msgr at
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: starting objecter
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: setting wanted keys
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: calling monclient init
2021-09-20T15:51:14.815+0000 7f0f1820d340  1 librados: init done
2021-09-20T15:51:15.502+0000 7f0f1820d340  2 all 8 watchers are set, enabling cache
2021-09-20T15:51:15.593+0000 7f0eda7e4700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: starting msgr at
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: starting objecter
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: setting wanted keys
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: calling monclient init
2021-09-20T15:51:15.600+0000 7f0f1820d340  1 librados: init done
        "idx": "tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet",
            "name": "tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet",
2021-09-20T15:51:17.850+0000 7f0f1820d340  2 removed watcher, disabling cache
2021-09-20T15:51:18.544+0000 7f0eda7e4700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:51:18.568+0000 7f0f1820d340  1 librados: shutdown
2021-09-20T15:51:18.569+0000 7f0f1820d340  1 librados: shutdown

OBJ EXISTS!

 rados ls -p my-store.rgw.buckets.data | grep part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: starting msgr at
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: starting objecter
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: setting wanted keys
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: calling monclient init
2021-09-20T15:53:32.611+0000 7fa44c1edd00  1 librados: init done
1cabf71f-2fe9-4187-a928-537277185b62.51427781.1_tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:53:34.024+0000 7fa44c1edd00  1 librados: shutdown

OMAP KEY NOT PRESENT FOR THE OBJECT:

rados listomapkeys -p my-store.rgw.buckets.index .dir.1cabf71f-2fe9-4187-a928-537277185b62.51427781.2.1 | grep part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: starting msgr at
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: starting objecter
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: setting wanted keys
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: calling monclient init
2021-09-20T15:55:14.333+0000 7f2549dc4d00  1 librados: init done
2021-09-20T15:55:14.339+0000 7f2549dc4d00  1 librados: shutdown

 rados listomapkeys -p my-store.rgw.buckets.index .dir.1cabf71f-2fe9-4187-a928-537277185b62.51427781.2.1 | grep part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: starting msgr at
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: starting objecter
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: setting wanted keys
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: calling monclient init
2021-09-20T15:55:21.651+0000 7f326ae01d00  1 librados: init done
2021-09-20T15:55:21.656+0000 7f326ae01d00  1 librados: shutdowntlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet

radosgw-admin bucket limit check

 {
        "user_id": "ceph-user-ibQM7j55",
        "buckets": [
            {
                "bucket": "ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb",
                "tenant": "",
                "num_objects": 608,
                "num_shards": 2,
                "objects_per_shard": 304,
                "fill_status": "OK" 
            }
        ]
    }
BACKGROUND：
Ceph version 16.2.5 (0883bdea7337b95e4b611c768c0279868462204a) pacific (stable)
Ceph health is OK
Deployed using Rook
Using EC/REPLICATED pool with 3 RGW instances

DESCRIBE:
When use S3 LIST_OBJECT() to list, some uploaded objects cannot be listed.
I am sure that the object has been uploaded because I can get it with the exact key.
Moreover I experience this only with RGW instances > 1, with a single RGW instance the issue is not reported.

SOME ELSE：

These files are uploaded by S3a file committer. I doubt this has something to do with the issue because the HTTP requests to the RGW are identical both in case of object uploaded correctly and not

Logs even at debug-level=20 do not report any error/warning

REQUEST LOGGED BY RGW

"PUT /ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb/tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet HTTP/1.1" 
200 238 - "Hadoop 2.8.5, aws-sdk-java/1.11.751 Linux/5.6.11-200.fc31.x86_64 OpenJDK_64-Bit_Server_VM/25.232-b09 
java/1.8.0_232 scala/2.11.12 vendor/Oracle_Corporation com.amazonaws.services.s3.transfer.TransferManager/1.11.751" - latency=0.167005762s

LIST OF COMMANDS ISSUED AND RESULTS:

radosgw-admin bi list --bucket=ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb | grep part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet

2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: starting msgr at
2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: starting objecter
2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: setting wanted keys
2021-09-20T15:50:10.647+0000 7f9bc5581340  1 librados: calling monclient init
2021-09-20T15:50:10.648+0000 7f9bc5581340  1 librados: init done
2021-09-20T15:50:11.337+0000 7f9bc5581340  2 all 8 watchers are set, enabling cache
2021-09-20T15:50:11.399+0000 7f9b86fe5700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: starting msgr at
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: starting objecter
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: setting wanted keys
2021-09-20T15:50:11.405+0000 7f9bc5581340  1 librados: calling monclient init
2021-09-20T15:50:11.408+0000 7f9bc5581340  1 librados: init done
2021-09-20T15:50:13.777+0000 7f9bc5581340  2 removed watcher, disabling cache
2021-09-20T15:50:14.202+0000 7f9b86fe5700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:50:14.285+0000 7f9bc5581340  1 librados: shutdown
2021-09-20T15:50:14.286+0000 7f9bc5581340  1 librados: shutdown

FOR A FILE UPLOADED CORRECTLY:

radosgw-admin bi list --bucket=ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb | grep part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: starting msgr at
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: starting objecter
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: setting wanted keys
2021-09-20T15:51:14.814+0000 7f0f1820d340  1 librados: calling monclient init
2021-09-20T15:51:14.815+0000 7f0f1820d340  1 librados: init done
2021-09-20T15:51:15.502+0000 7f0f1820d340  2 all 8 watchers are set, enabling cache
2021-09-20T15:51:15.593+0000 7f0eda7e4700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: starting msgr at
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: starting objecter
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: setting wanted keys
2021-09-20T15:51:15.598+0000 7f0f1820d340  1 librados: calling monclient init
2021-09-20T15:51:15.600+0000 7f0f1820d340  1 librados: init done
        "idx": "tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet",
            "name": "tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet",
2021-09-20T15:51:17.850+0000 7f0f1820d340  2 removed watcher, disabling cache
2021-09-20T15:51:18.544+0000 7f0eda7e4700  2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2021-09-20T15:51:18.568+0000 7f0f1820d340  1 librados: shutdown
2021-09-20T15:51:18.569+0000 7f0f1820d340  1 librados: shutdown

OBJ EXISTS!

 rados ls -p my-store.rgw.buckets.data | grep part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: starting msgr at
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: starting objecter
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: setting wanted keys
2021-09-20T15:53:32.609+0000 7fa44c1edd00  1 librados: calling monclient init
2021-09-20T15:53:32.611+0000 7fa44c1edd00  1 librados: init done
1cabf71f-2fe9-4187-a928-537277185b62.51427781.1_tlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:53:34.024+0000 7fa44c1edd00  1 librados: shutdown

OMAP KEY NOT PRESENT FOR THE OBJECT:

rados listomapkeys -p my-store.rgw.buckets.index .dir.1cabf71f-2fe9-4187-a928-537277185b62.51427781.2.1 | grep part-00005-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: starting msgr at
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: starting objecter
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: setting wanted keys
2021-09-20T15:55:14.331+0000 7f2549dc4d00  1 librados: calling monclient init
2021-09-20T15:55:14.333+0000 7f2549dc4d00  1 librados: init done
2021-09-20T15:55:14.339+0000 7f2549dc4d00  1 librados: shutdown

 rados listomapkeys -p my-store.rgw.buckets.index .dir.1cabf71f-2fe9-4187-a928-537277185b62.51427781.2.1 | grep part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: starting msgr at
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: starting objecter
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: setting wanted keys
2021-09-20T15:55:21.649+0000 7f326ae01d00  1 librados: calling monclient init
2021-09-20T15:55:21.651+0000 7f326ae01d00  1 librados: init done
2021-09-20T15:55:21.656+0000 7f326ae01d00  1 librados: shutdowntlap_635_rewrites_5_iterations/2021-09-20T082916.979Z/rewrite_1.parquet/part-00004-0bb55c0f-755f-4299-80ee-142d65e38eb4-c000.snappy.parquet

radosgw-admin bucket limit check

 {
        "user_id": "ceph-user-ibQM7j55",
        "buckets": [
            {
                "bucket": "ceph-bkt-31c9b571-6495-4edd-a0f1-8f2cb9ff97cb",
                "tenant": "",
                "num_objects": 608,
                "num_shards": 2,
                "objects_per_shard": 304,
                "fill_status": "OK" 
            }
        ]
    }

Related issues 1 (0 open — 1 closed)

Has duplicate rgw - Bug #52669: Bucket index not always created when new object addedDuplicate

Actions
Actions
Copy link
 #1

Updated by Pietro Di Marco over 2 years ago

This can be removed since duplicate: https://tracker.ceph.com/issues/52669

Actions
Copy link
 #2

Updated by Casey Bodley over 2 years ago

  • Has duplicate Bug #52669: Bucket index not always created when new object added added
Actions
Copy link
 #3

Updated by Casey Bodley over 2 years ago

  • Status changed from New to Duplicate
Actions
Copy link

Also available in: Atom PDF