Bug #9892: radosgw_admin.py: failed len(out['entries']) == 0 on usage show - rgw - Ceph

Actions

Copy link

Bug #9892

closed

radosgw_admin.py: failed len(out['entries']) == 0 on usage show

Added by Sage Weil over 9 years ago. Updated over 9 years ago.

Status:

Resolved

Priority:

Urgent

Assignee:

Alfredo Deza

Target version:

% Done:

Source:

Q/A

Tags:

Backport:

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Pull request ID:

Crash signature (v1):

Crash signature (v2):

Description

2014-10-25T21:45:07.360 INFO:tasks.util.rgw: json result: {u'summary': [{u'total': {u'successful_ops': 7, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 7}, u'user': u'foo', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 7, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 7}]}], u'entries': [{u'owner': u'foo', u'buckets': [{u'epoch': 1414324800, u'bucket': u'mybar', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 2, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 2}], u'time': u'2014-10-26 12:00:00.000000Z'}, {u'epoch': 1414324800, u'bucket': u'myfoo', u'categories': [], u'time': u'2014-10-26 12:00:00.000000Z'}, {u'epoch': 1414324800, u'bucket': u'myfoo2', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 1, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 1}], u'time': u'2014-10-26 12:00:00.000000Z'}, {u'epoch': 1414324800, u'bucket': u'myfoo3', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 1, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 1}], u'time': u'2014-10-26 12:00:00.000000Z'}, {u'epoch': 1414324800, u'bucket': u'myfoo4', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 1, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 1}], u'time': u'2014-10-26 12:00:00.000000Z'}, {u'epoch': 1414324800, u'bucket': u'myfoodata', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 1, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 1}], u'time': u'2014-10-26 12:00:00.000000Z'}, {u'epoch': 1414324800, u'bucket': u'myfoodata2', u'categories': [{u'category': u'delete_bucket', u'successful_ops': 1, u'bytes_received': 0, u'bytes_sent': 0, u'ops': 1}], u'time': u'2014-10-26 12:00:00.000000Z'}]}]}
2014-10-25T21:45:07.360 INFO:tasks.util.rgw:rgwadmin: client.0 : ['usage', 'trim', '--uid', 'foo']
2014-10-25T21:45:07.360 INFO:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/home/ubuntu/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', 'usage', 'trim', '--uid', 'foo']
2014-10-25T21:45:07.361 INFO:teuthology.orchestra.run.plana18:Running: 'adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 usage trim --uid foo'
2014-10-25T21:45:08.496 INFO:tasks.util.rgw:rgwadmin: client.0 : ['usage', 'show', '--uid', 'foo']
2014-10-25T21:45:08.496 INFO:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/home/ubuntu/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', 'usage', 'show', '--uid', 'foo']
2014-10-25T21:45:08.497 INFO:teuthology.orchestra.run.plana18:Running: 'adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 usage show --uid foo'
2014-10-25T21:45:09.297 INFO:tasks.util.rgw: json result: {u'summary': [{u'total': {u'successful_ops': 1, u'bytes_received': 4, u'bytes_sent': 0, u'ops': 1}, u'user': u'foo', u'categories': [{u'category': u'put_obj', u'successful_ops': 1, u'bytes_received': 4, u'bytes_sent': 0, u'ops': 1}]}], u'entries': [{u'owner': u'foo', u'buckets': [{u'epoch': 1414324800, u'bucket': u'myfoo', u'categories': [{u'category': u'put_obj', u'successful_ops': 1, u'bytes_received': 4, u'bytes_sent': 0, u'ops': 1}], u'time': u'2014-10-26 12:00:00.000000Z'}]}]}
2014-10-25T21:45:09.297 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
  File "/home/teuthworker/src/teuthology_master/teuthology/run_tasks.py", line 53, in run_tasks
    manager = run_one_task(taskname, ctx=ctx, config=config)
  File "/home/teuthworker/src/teuthology_master/teuthology/run_tasks.py", line 41, in run_one_task
    return fn(**kwargs)
  File "/var/lib/teuthworker/src/ceph-qa-suite_giant/tasks/radosgw_admin.py", line 827, in task
    assert len(out['entries']) == 0
AssertionError

ubuntu@teuthology:/a/teuthology-2014-10-24_23:02:01-rgw-giant-distro-basic-multi/570664

Actions

Copy link

Updated by Yehuda Sadeh over 9 years ago

seem like a broken test. We write an object here:

2014-10-25T21:44:45.899 INFO:tasks.util.rgw: json result: {u'log_entries': [{u'total_time': 0, u'remote_addr': u'10.214.137.23', u'bytes_sent': 0, u'bucket': u'myfoo', u'uri': u'/myfoo/', u'referrer': u'', u'user': u'foo', u'http_status': u'200', u'time': u'2014-10-26 04:44:22.208199Z', u'object_size': 0, u'time_local': u'2014-10-25 21:44:22.208199', u'operation': u'PUT', u'bytes_received': 0, u'error_code': u'', u'user_agent': u'Boto/2.2.2 (linux2)'}, {u'total_time': 0, u'remote_addr': u'10.214.137.23', u'bytes_sent': 0, u'bucket': u'myfoo', u'uri': u'/myfoo/f97c5d29941bfb1b2fdab0874906ab82', u'referrer': u'', u'user': u'foo', u'http_status': u'200', u'time': u'2014-10-26 04:44:28.427984Z', u'object_size': 3, u'time_local': u'2014-10-25 21:44:28.427984', u'operation': u'PUT', u'bytes_received': 3, u'error_code': u'', u'user_agent': u'Boto/2.2.2 (linux2)'}, {u'total_time': 0, u'remote_addr': u'10.214.137.23', u'bytes_sent': 0, u'bucket': u'myfoo', u'uri': u'/myfoo/f97c5d29941bfb1b2fdab0874906ab82', u'referrer': u'', u'user': u'foo', u'http_status': u'204', u'time': u'2014-10-26 04:44:29.302892Z', u'object_size': 0, u'time_local': u'2014-10-25 21:44:29.302892', u'operation': u'DELETE', u'bytes_received': 0, u'error_code': u'NoContent', u'user_agent': u'Boto/2.2.2 (linux2)'}, {u'total_time': 0, u'remote_addr': u'10.214.137.23', u'bytes_sent': 0, u'bucket': u'myfoo', u'uri': u'/myfoo/b8a9f715dbb64fd5c56e7783c6820a61', u'referrer': u'', u'user': u'foo', u'http_status': u'200', u'time': u'2014-10-26 04:44:32.247065Z', u'object_size': 3, u'time_local': u'2014-10-25 21:44:32.247065', u'operation': u'PUT', u'bytes_received': 3, u'error_code': u'', u'user_agent': u'Boto/2.2.2 (linux2)'}, {u'total_time': 0, u'remote_addr': u'10.214.137.23', u'bytes_sent': 0, u'bucket': u'myfoo', u'uri': u'/myfoo/b8a9f715dbb64fd5c56e7783c6820a61', u'referrer': u'', u'user': u'foo', u'http_status': u'204', u'time': u'2014-10-26 04:44:32.350745Z', u'object_size': 0, u'time_local': u'2014-10-25 21:44:32.350745', u'operation': u'DELETE', u'bytes_received': 0, u'error_code': u'NoContent', u'user_agent': u'Boto/2.2.2 (linux2)'}, {u'total_time': 0, u'remote_addr': u'10.214.137.23', u'bytes_sent': 0, u'bucket': u'myfoo', u'uri': u'/myfoo/four', u'referrer': u'', u'user': u'foo', u'http_status': u'200', u'time': u'2014-10-26 04:44:40.236470Z', u'object_size': 4, u'time_local': u'2014-10-25 21:44:40.236470', u'operation': u'PUT', u'bytes_received': 4, u'error_code': u'', u'user_agent': u'Boto/2.2.2 (linux2)'}], u'bucket_id': u'r0z1.4148.6', u'bucket': u'myfoo', u'bucket_owner': u'foo', u'log_sum': {u'total_time': 0, u'total_entries': 6, u'bytes_received': 10, u'bytes_sent': 0}}
2014-10-25T21:44:45.899 INFO:tasks.util.rgw:rgwadmin: client.0 : ['log', 'rm', '--object', u'2014-10-25-21-r0z1.4148.6-myfoo']

clear the usage log here:

2014-10-25T21:45:07.360 INFO:tasks.util.rgw:rgwadmin: client.0 : ['usage', 'trim', '--uid', 'foo']

and read it again here:

2014-10-25T21:45:08.497 INFO:teuthology.orchestra.run.plana18:Running: 'adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 usage show --uid foo'

Since the usage tick interval is 30 seconds, this shouldn't really work, and it is very likely that we the usage flush raced with the usage trim/show. We should either modify the test to wait longer, or explicitly configure rgw to use a shorter usage interval (as with do with the gc interval).

Actions

Copy link