[ceph-users] Nautilus 14.2.7 radosgw lifecycle not removing expired objects

9 Apr 2020

      Hello,

I'm running a cluster with Ceph version 14.2.7 (3d58626ebeec02d8385a4cefb92c6cbc3a45bfe8) nautilus (stable).

I've encountered an issue with my cluster where objects are marked as expired but are not removed during lifecycle processing. These buckets have a mix of objects with and without special characters in their names. I set debug_rgw to 20/5 overnight so I could get more detailed logs when the lifecycle processing happened. The lifecycle function seems to correctly identify expired objects that should be removed, however they are not deleted. This is happening across multiple buckets and users.

This cluster does have dynamic bucket index resharding enabled, however this issue affects buckets regardless of their reshard status. I also have cache tiering set to readproxy for the buckets data pool.

root@rgw01 # ceph daemon /var/run/ceph/ceph-rgw-rgw01.asok config show | grep -E "lifecycle|lc"
    "rgw_lifecycle_work_time": "00:00-06:00",
    "rgw_enable_lc_threads": "true",
    "rgw_lc_debug_interval": "-1",
    "rgw_lc_lock_max_time": "60",
    "rgw_lc_max_objs": "32",
    "rgw_lc_max_rules": "1000",
    "rgw_lc_thread_delay": "0",
root@mon01 # radosgw-admin lc list
[
    {
        "bucket": ":testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50",
        "status": "COMPLETE"
    }
]
root@mon01 # radosgw-admin lc get --bucket testgso
{
    "prefix_map": {
        "": {
            "status": true,
            "dm_expiration": false,
            "expiration": 1,
            "noncur_expiration": 0,
            "mp_expiration": 1
        }
    },
    "rule_map": [
        {
            "id": "111222333",
            "rule": {
                "id": "111222333",
                "prefix": "",
                "status": "Enabled",
                "expiration": {
                    "days": "1",
                    "date": ""
                },
                "noncur_expiration": {
                    "days": "",
                    "date": ""
                },
                "mp_expiration": {
                    "days": "1",
                    "date": ""
                },
                "filter": {
                    "prefix": "",
                    "obj_tags": {}
                },
                "dm_expiration": false
            }
        }
    ]
}

goneill@mbp $ s3cmd -c Documents/s3cfg/testgso.cfg ls s3://testgso
                       DIR   s3://testgso/lifecycle/
2020-03-31 17:26        12   s3://testgso/file!test.txt
2020-03-31 17:29        12   s3://testgso/file$test.txt
2020-03-31 17:29        12   s3://testgso/file&test.txt
2020-03-31 17:26        12   s3://testgso/file'test.txt
2020-03-31 17:26        12   s3://testgso/file(test.txt
2020-03-31 17:26        12   s3://testgso/file)test.txt
2020-03-31 17:29        12   s3://testgso/file*test.txt
2020-03-31 17:30        12   s3://testgso/file+test.txt
2020-03-31 17:30        12   s3://testgso/file,test.txt
2020-03-31 17:26        12   s3://testgso/file-test.txt
2020-03-31 17:30        12   s3://testgso/file:test.txt
2020-03-31 17:30        12   s3://testgso/file;test.txt
2020-03-31 17:30        12   s3://testgso/file=test.txt
2020-03-31 17:30        12   s3://testgso/file?test.txt
2020-03-31 17:06        12   s3://testgso/file@test.txt
2019-08-05 21:02        12   s3://testgso/test.txt

goneill@mbp $ s3cmd -c Documents/s3cfg/testgso.cfg getlifecycle s3://testgso
<?xml version="1.0" ?>
<LifecycleConfiguration xmlns="http://s3.amazonaws.com/doc/2006-03-01/">
	<Rule>
		<ID>111222333</ID>
		<Prefix/>
		<Status>Enabled</Status>
		<Expiration>
			<Days>1</Days>
		</Expiration>
		<AbortIncompleteMultipartUpload>
			<DaysAfterInitiation>1</DaysAfterInitiation>
		</AbortIncompleteMultipartUpload>
	</Rule>
</LifecycleConfiguration>

### Logs from rgw01
2020-04-08 00:00:00.645 7fc55bbcc700 20 get_system_obj_state: rctx=0x7fc55bbc9bf0 obj=default.rgw.meta:root:testgso state=0x561a8bc0ac40 s->prefetch_data=0
2020-04-08 00:00:00.645 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+testgso : expiry miss
2020-04-08 00:00:00.645 7fc55bbcc700 10 cache put: name=default.rgw.meta+root+testgso info.flags=0x16
2020-04-08 00:00:00.645 7fc55bbcc700 10 adding default.rgw.meta+root+testgso to cache LRU end
2020-04-08 00:00:00.645 7fc55bbcc700 10 updating xattr: name=ceph.objclass.version bl.length()=42
2020-04-08 00:00:00.645 7fc55bbcc700 20 get_system_obj_state: s->obj_tag was set empty
2020-04-08 00:00:00.645 7fc55bbcc700 20 Read xattr: user.rgw.idtag
2020-04-08 00:00:00.645 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+testgso : type miss (requested=0x13, cached=0x16)
2020-04-08 00:00:00.645 7fc55bbcc700 20 rados->read ofs=0 len=0
2020-04-08 00:00:00.646 7fc55bbcc700 20 rados_obj.operate() r=0 bl.length=181
2020-04-08 00:00:00.646 7fc55bbcc700 10 cache put: name=default.rgw.meta+root+testgso info.flags=0x13
2020-04-08 00:00:00.646 7fc55bbcc700 10 moving default.rgw.meta+root+testgso to cache LRU end
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=ceph.objclass.version bl.length()=42
2020-04-08 00:00:00.646 7fc55bbcc700 20 rgw_get_bucket_info: bucket instance: testgso[0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50]
2020-04-08 00:00:00.646 7fc55bbcc700 20 reading from default.rgw.meta:root:.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50
2020-04-08 00:00:00.646 7fc55bbcc700 20 get_system_obj_state: rctx=0x7fc55bbc9bf0 obj=default.rgw.meta:root:.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 state=0x561a9d27d540 s->prefetch_data=0
2020-04-08 00:00:00.646 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 : expiry miss
2020-04-08 00:00:00.646 7fc55bbcc700 10 cache put: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 info.flags=0x16
2020-04-08 00:00:00.646 7fc55bbcc700 10 adding default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 to cache LRU end
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=ceph.objclass.version bl.length()=42
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=user.rgw.acl bl.length()=153
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=user.rgw.lc bl.length()=130
2020-04-08 00:00:00.646 7fc55bbcc700 20 get_system_obj_state: s->obj_tag was set empty
2020-04-08 00:00:00.646 7fc55bbcc700 20 Read xattr: user.rgw.acl
2020-04-08 00:00:00.646 7fc55bbcc700 20 Read xattr: user.rgw.idtag
2020-04-08 00:00:00.646 7fc55bbcc700 20 Read xattr: user.rgw.lc
2020-04-08 00:00:00.646 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 : type miss (requested=0x13, cached=0x16)
2020-04-08 00:00:00.646 7fc55bbcc700 20 rados->read ofs=0 len=0
2020-04-08 00:00:00.646 7fc55bbcc700 20 rados_obj.operate() r=0 bl.length=281
2020-04-08 00:00:00.646 7fc55bbcc700 10 cache put: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 info.flags=0x13
2020-04-08 00:00:00.646 7fc55bbcc700 10 moving default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 to cache LRU end
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=ceph.objclass.version bl.length()=42
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=user.rgw.acl bl.length()=153
2020-04-08 00:00:00.646 7fc55bbcc700 10 updating xattr: name=user.rgw.lc bl.length()=130
2020-04-08 00:00:00.646 7fc55bbcc700 10 chain_cache_entry: cache_locator=default.rgw.meta+root+testgso
2020-04-08 00:00:00.646 7fc55bbcc700 10 chain_cache_entry: cache_locator=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50
2020-04-08 00:00:00.647 7fc55bbcc700 10 lifecycle: bucket_lc_process() prefix_map size=1
2020-04-08 00:00:00.647 7fc55bbcc700 20 lifecycle: bucket_lc_process(): prefix=
2020-04-08 00:00:00.647 7fc55bbcc700 10 cls_bucket_list_unordered testgso[0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50] start [] num_entries 1100
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file!test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file$test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file&test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file'test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file(test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file)test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file*test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file+test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file,test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file-test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file:test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file;test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file=test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file?test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got file@test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got lifecycle/file.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 10 RGWRados::cls_bucket_list_unordered: got test.txt[]
2020-04-08 00:00:00.647 7fc55bbcc700 20 lifecycle: bucket_lc_process(): key=file!test.txt
2020-04-08 00:00:00.648 7fc55bbcc700 20 obj_has_expired(): mtime=2020-03-31 13:26:07.0.481384s days=1 base_time=2020-04-08 00:00:00.000000 timediff=642833 cmp=86400
2020-04-08 00:00:00.648 7fc55bbcc700 20 check(): key=file!test.txt: is_expired=1
2020-04-08 00:00:00.648 7fc55bbcc700 20 get_obj_state: rctx=0x7fc55bbc8ff8 obj=testgso:file!test.txt state=0x561aa0c64aa0 s->prefetch_data=0
2020-04-08 00:00:00.657 7fc44f1b3700 10 manifest: total_size = 49667
2020-04-08 00:00:00.657 7fc44f1b3700 20 get_obj_state: setting s->obj_tag to 0a6e5079-ad65-4ea7-a868-b2133099e0d0.22351662.19462946
2020-04-08 00:00:00.672 7fc55bbcc700 20 get_obj_state: setting s->obj_tag to 0a6e5079-ad65-4ea7-a868-b2133099e0d0.25454121.7727201
2020-04-08 00:00:00.672 7fc55bbcc700 10 If-UnModified-Since: 2020-03-31 13:26:07.0.481384s Last-Modified: 2020-03-31 13:26:07.000000
2020-04-08 00:00:00.672 7fc55bbcc700 20 get_obj_state: rctx=0x7fc55bbc8ff8 obj=testgso:file!test.txt state=0x561aa0c64aa0 s->prefetch_data=0
2020-04-08 00:00:00.672 7fc55bbcc700 20 prepare_atomic_modification: state is not atomic. state=0x561aa0c64aa0
2020-04-08 00:00:00.672 7fc55bbcc700 20 reading from default.rgw.meta:root:.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50
2020-04-08 00:00:00.672 7fc55bbcc700 20 get_system_obj_state: rctx=0x7fc55bbc8330 obj=default.rgw.meta:root:.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 state=0x561a9d27d0c0 s->prefetch_data=0
2020-04-08 00:00:00.672 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 : type miss (requested=0x16, cached=0x13)
2020-04-08 00:00:00.672 7fc55bbcc700 10 cache put: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 info.flags=0x16
2020-04-08 00:00:00.672 7fc55bbcc700 10 moving default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 to cache LRU end
2020-04-08 00:00:00.672 7fc55bbcc700 10 updating xattr: name=ceph.objclass.version bl.length()=42
2020-04-08 00:00:00.672 7fc55bbcc700 10 updating xattr: name=user.rgw.acl bl.length()=153
2020-04-08 00:00:00.672 7fc55bbcc700 10 updating xattr: name=user.rgw.lc bl.length()=130
2020-04-08 00:00:00.672 7fc55bbcc700 20 get_system_obj_state: s->obj_tag was set empty
2020-04-08 00:00:00.672 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 : hit (requested=0x11, cached=0x17)
2020-04-08 00:00:00.672 7fc55bbcc700 20  bucket index object: .dir.0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50
2020-04-08 00:00:00.683 7fc55bbcc700  0 ERROR: remove_expired_obj
2020-04-08 00:00:00.683 7fc55bbcc700  0 ERROR: remove_expired_obj
2020-04-08 00:00:00.683 7fc55bbcc700 20 lifecycle: ERROR: orule.process() returned ret=-125
2020-04-08 00:00:00.683 7fc55bbcc700 20 lifecycle: bucket_lc_process(): key=file$test.txt
2020-04-08 00:00:00.683 7fc55bbcc700 20 obj_has_expired(): mtime=2020-03-31 13:29:57.0.916797s days=1 base_time=2020-04-08 00:00:00.000000 timediff=642603 cmp=86400
2020-04-08 00:00:00.683 7fc55bbcc700 20 check(): key=file$test.txt: is_expired=1
2020-04-08 00:00:00.683 7fc55bbcc700 20 get_obj_state: rctx=0x7fc55bbc8ff8 obj=testgso:file$test.txt state=0x561aa0c64aa0 s->prefetch_data=0
2020-04-08 00:00:00.684 7fc55bbcc700 10 manifest: total_size = 12
2020-04-08 00:00:00.684 7fc55bbcc700 20 get_obj_state: setting s->obj_tag to 0a6e5079-ad65-4ea7-a868-b2133099e0d0.25454121.7731015
2020-04-08 00:00:00.684 7fc55bbcc700 10 If-UnModified-Since: 2020-03-31 13:29:57.0.916797s Last-Modified: 2020-03-31 13:29:57.000000
2020-04-08 00:00:00.684 7fc55bbcc700 20 get_obj_state: rctx=0x7fc55bbc8ff8 obj=testgso:file$test.txt state=0x561aa0c64aa0 s->prefetch_data=0
2020-04-08 00:00:00.684 7fc55bbcc700 20 prepare_atomic_modification: state is not atomic. state=0x561aa0c64aa0
2020-04-08 00:00:00.684 7fc55bbcc700 20 reading from default.rgw.meta:root:.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50
2020-04-08 00:00:00.684 7fc55bbcc700 20 get_system_obj_state: rctx=0x7fc55bbc8330 obj=default.rgw.meta:root:.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 state=0x561a9d27d0c0 s->prefetch_data=0
2020-04-08 00:00:00.684 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 : hit (requested=0x16, cached=0x17)
2020-04-08 00:00:00.684 7fc55bbcc700 20 get_system_obj_state: s->obj_tag was set empty
2020-04-08 00:00:00.684 7fc55bbcc700 10 cache get: name=default.rgw.meta+root+.bucket.meta.testgso:0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50 : hit (requested=0x11, cached=0x17)
2020-04-08 00:00:00.684 7fc55bbcc700 20  bucket index object: .dir.0a6e5079-ad65-4ea7-a868-b2133099e0d0.5495934.50
2020-04-08 00:00:00.711 7fc55bbcc700  0 ERROR: remove_expired_obj
2020-04-08 00:00:00.711 7fc55bbcc700  0 ERROR: remove_expired_obj
2020-04-08 00:00:00.711 7fc55bbcc700 20 lifecycle: ERROR: orule.process() returned ret=-125

[ceph-users] Nautilus 14.2.7 radosgw lifecycle not removing expired objects

oneill.gs＠gmail.com