Bug #17257: ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP - RADOS - Ceph

Actions

Copy link

Bug #17257

closed

ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP

Added by Kefu Chai over 7 years ago. Updated almost 3 years ago.

Status:

Can't reproduce

Priority:

High

Assignee:

Category:

Target version:

% Done:

Source:

Development

Tags:

Backport:

mimic,luminous

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Component(RADOS):

Pull request ID:

Crash signature (v1):

Crash signature (v2):

Description

2016-09-10T16:37:03.892 INFO:tasks.workunit.client.0.mira082.stdout:                 api_lock: [ RUN      ] LibRadosLockEC.LockExclusiveDur
2016-09-10T16:37:03.892 INFO:tasks.workunit.client.0.mira082.stdout:                 api_lock: /srv/autobuild-ceph/gitbuilder.git/build/out~/ceph-11.0.0-2224-g12cba55/src/test/librados/lock.cc:224: Failure
2016-09-10T16:37:03.892 INFO:tasks.workunit.client.0.mira082.stdout:                 api_lock:       Expected: 0
2016-09-10T16:37:03.892 INFO:tasks.workunit.client.0.mira082.stdout:                 api_lock: To be equal to: rados_lock_exclusive(ioctx, "foo", "TestLock", "Cookie", "", __null, 0)
2016-09-10T16:37:03.892 INFO:tasks.workunit.client.0.mira082.stdout:                 api_lock:       Which is: -17
2016-09-10T16:37:03.892 INFO:tasks.workunit.client.0.mira082.stdout:                 api_lock: [  FAILED  ] LibRadosLockEC.LockExclusiveDur (984 ms)

see /a/kchai-2016-09-10_15:46:37-rados-wip-kefu-testing---basic-mira/408471/teuthology.log

http://pulpito.ceph.com/kchai-2016-09-10_15:46:37-rados-wip-kefu-testing---basic-mira/408471/

and

2016-09-19T08:15:51.021 INFO:tasks.workunit.client.0.mira034.stdout:                 api_lock: [ RUN      ] LibRadosLockPP.LockExclusiveDurPP
2016-09-19T08:15:51.021 INFO:tasks.workunit.client.0.mira034.stdout:                 api_lock: /srv/autobuild-ceph/gitbuilder.git/build/rpmbuild/BUILD/ceph-11.0.0/src/test/librados
/lock.cc:54: Failure
2016-09-19T08:15:51.021 INFO:tasks.workunit.client.0.mira034.stdout:                 api_lock:       Expected: 0
2016-09-19T08:15:51.021 INFO:tasks.workunit.client.0.mira034.stdout:                 api_lock: To be equal to: ioctx.lock_exclusive("foo", "TestLock", "Cookie", "", __null, 0)
2016-09-19T08:15:51.021 INFO:tasks.workunit.client.0.mira034.stdout:                 api_lock:       Which is: -17
2016-09-19T08:15:51.022 INFO:tasks.workunit.client.0.mira034.stdout:                 api_lock: [  FAILED  ] LibRadosLockPP.LockExclusiveDurPP (1031 ms)

in http://pulpito.ceph.com/kchai-2016-09-19_07:07:02-rados-wip-kefu-testing---basic-mira/423445/

Actions

Copy link

Updated by Kefu Chai over 7 years ago

rerunning at http://pulpito.ceph.com/kchai-2016-09-11_03:15:51-rados-master---basic-mira/, and it failed also with a different reason. it seems..

2016-09-11T11:35:44.131 INFO:tasks.workunit.client.0.mira037.stdout:                 api_list: [ RUN      ] LibRadosList.EnumerateObjects
2016-09-11T11:35:44.131 INFO:tasks.workunit.client.0.mira037.stdout:                 api_list: /srv/autobuild-ceph/gitbuilder.git/build/rpmbuild/BUILD/ceph-11.0.0/src/test/librados/list.cc:689: Failure
2016-09-11T11:35:44.131 INFO:tasks.workunit.client.0.mira037.stdout:                 api_list: Value of: err_str.empty()
2016-09-11T11:35:44.131 INFO:tasks.workunit.client.0.mira037.stdout:                 api_list:   Actual: false
2016-09-11T11:35:44.131 INFO:tasks.workunit.client.0.mira037.stdout:                 api_list: Expected: true

Actions

Copy link

Updated by Kefu Chai over 7 years ago

test again at http://pulpito.ceph.com/kchai-2016-09-12_04:34:59-rados-master---basic-mira/ passed.

Actions

Copy link

Updated by Kefu Chai over 7 years ago

Description updated (diff)

Actions

Copy link

Updated by Kefu Chai over 7 years ago

Description updated (diff)

Actions

Copy link

Updated by Kefu Chai over 7 years ago

Priority changed from Normal to Urgent

Actions

Copy link

Updated by Samuel Just over 7 years ago

Status changed from New to Can't reproduce

Actions

Copy link

Updated by Sage Weil about 6 years ago

Subject changed from ceph_test_rados_api_lock fails in qa run to ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP (luminous)
Status changed from Can't reproduce to 12
Backport set to luminous

2018-04-04T04:15:11.032 INFO:tasks.workunit.client.0.smithi190.stdout:                 api_lock: [ RUN      ] LibRadosLockPP.LockExclusiveDurPP
2018-04-04T04:15:11.032 INFO:tasks.workunit.client.0.smithi190.stdout:                 api_lock: /build/ceph-12.2.4-264-g6f2ebf5/src/test/librados/lock.cc:54: Failure
2018-04-04T04:15:11.032 INFO:tasks.workunit.client.0.smithi190.stdout:                 api_lock:       Expected: 0
2018-04-04T04:15:11.032 INFO:tasks.workunit.client.0.smithi190.stdout:                 api_lock: To be equal to: ioctx.lock_exclusive("foo", "TestLock", "Cookie", "", __null, 0)
2018-04-04T04:15:11.032 INFO:tasks.workunit.client.0.smithi190.stdout:                 api_lock:       Which is: -17
2018-04-04T04:15:11.032 INFO:tasks.workunit.client.0.smithi190.stdout:                 api_lock: [  FAILED  ] LibRadosLockPP.LockExclusiveDurPP (1007 ms)

/a/yuriw-2018-04-03_19:42:03-rados-wip-yuri2-testing-2018-04-03-1604-luminous-distro-basic-smithi/2349124

client log remote/smithi190/log/ceph-client.admin.14769.log.gz

2018-04-04 04:15:10.996633 7fcc74a18980 10 librados: call oid=foo nspace=test-rados-api-smithi190-14769-24
2018-04-04 04:15:10.996643 7fcc74a18980 10 client.4388.objecter _op_submit op 0x555fe1ff8f20
2018-04-04 04:15:10.996648 7fcc74a18980 20 client.4388.objecter _calc_target epoch 32 base foo @43;test-rados-api-smithi190-14769-24 precalc_pgid 0 pgid 0.0 is_write
2018-04-04 04:15:10.996654 7fcc74a18980 20 client.4388.objecter _calc_target target foo @43;test-rados-api-smithi190-14769-24 -> pgid 43.a1893c02
2018-04-04 04:15:10.996674 7fcc74a18980 10 client.4388.objecter _calc_target  raw pgid 43.a1893c02 -> actual 43.2s0 acting [4,7,5] primary 4
2018-04-04 04:15:10.996679 7fcc74a18980 20 client.4388.objecter _get_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:10.996690 7fcc74a18980 10 client.4388.objecter _op_submit oid foo '@43;test-rados-api-smithi190-14769-24' '@43;test-rados-api-smithi190-14769-24' [call lock.lock] tid 9 osd.4
2018-04-04 04:15:10.996697 7fcc74a18980 20 client.4388.objecter get_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:10.996701 7fcc74a18980 15 client.4388.objecter _session_op_assign 4 9
2018-04-04 04:15:10.996704 7fcc74a18980 15 client.4388.objecter _send_op 9 to 43.2s0 on osd.4
2018-04-04 04:15:10.996708 7fcc74a18980  1 -- 172.21.15.190:0/4133745564 --> 172.21.15.39:6804/13236 -- osd_op(unknown.0.0:9 43.2s0 43:403c9185:test-rados-api-smithi190-14769-24::foo:head [call lock.lock] snapc 0=[] ondisk+write+known_if_redirected e32) v8 -- 0x555fe1ff9fb0 con 0
2018-04-04 04:15:10.996739 7fcc74a18980 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 4
2018-04-04 04:15:10.996742 7fcc74a18980  5 client.4388.objecter 1 in flight
2018-04-04 04:15:11.000251 7fcc622a0700  1 -- 172.21.15.190:0/4133745564 <== osd.4 172.21.15.39:6804/13236 4 ==== osd_op_reply(9 foo [call] v32'1 uv1 ondisk = 0) v8 ==== 147+0+0 (2155262854 0 0) 0x7fcc54005220 con 0x555fe1ff15f0
2018-04-04 04:15:11.000279 7fcc622a0700 10 client.4388.objecter ms_dispatch 0x555fe1e20830 osd_op_reply(9 foo [call] v32'1 uv1 ondisk = 0) v8
2018-04-04 04:15:11.000286 7fcc622a0700 10 client.4388.objecter in handle_osd_op_reply
2018-04-04 04:15:11.000291 7fcc622a0700  7 client.4388.objecter handle_osd_op_reply 9 ondisk uv 1 in 43.2 attempt 0
2018-04-04 04:15:11.000294 7fcc622a0700 10 client.4388.objecter  op 0 rval 0 len 0
2018-04-04 04:15:11.000296 7fcc622a0700 15 client.4388.objecter handle_osd_op_reply completed tid 9
2018-04-04 04:15:11.000298 7fcc622a0700 15 client.4388.objecter finish_op 9
2018-04-04 04:15:11.000301 7fcc622a0700 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 4
2018-04-04 04:15:11.000303 7fcc622a0700 15 client.4388.objecter _session_op_remove 4 9
2018-04-04 04:15:11.000308 7fcc622a0700  5 client.4388.objecter 0 in flight
2018-04-04 04:15:11.000317 7fcc622a0700 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.000322 7fcc74a18980 10 librados: Objecter returned from call r=0
2018-04-04 04:15:11.000345 7fcc74a18980 10 librados: call oid=foo nspace=test-rados-api-smithi190-14769-24
2018-04-04 04:15:11.000353 7fcc74a18980 10 client.4388.objecter _op_submit op 0x555fe1ff9fb0
2018-04-04 04:15:11.000356 7fcc74a18980 20 client.4388.objecter _calc_target epoch 32 base foo @43;test-rados-api-smithi190-14769-24 precalc_pgid 0 pgid 0.0 is_write
2018-04-04 04:15:11.000361 7fcc74a18980 20 client.4388.objecter _calc_target target foo @43;test-rados-api-smithi190-14769-24 -> pgid 43.a1893c02
2018-04-04 04:15:11.000375 7fcc74a18980 10 client.4388.objecter _calc_target  raw pgid 43.a1893c02 -> actual 43.2s0 acting [4,7,5] primary 4
2018-04-04 04:15:11.000379 7fcc74a18980 20 client.4388.objecter _get_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.000386 7fcc74a18980 10 client.4388.objecter _op_submit oid foo '@43;test-rados-api-smithi190-14769-24' '@43;test-rados-api-smithi190-14769-24' [call lock.lock] tid 10 osd.4
2018-04-04 04:15:11.000392 7fcc74a18980 20 client.4388.objecter get_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.000395 7fcc74a18980 15 client.4388.objecter _session_op_assign 4 10
2018-04-04 04:15:11.000396 7fcc74a18980 15 client.4388.objecter _send_op 10 to 43.2s0 on osd.4
2018-04-04 04:15:11.000399 7fcc74a18980  1 -- 172.21.15.190:0/4133745564 --> 172.21.15.39:6804/13236 -- osd_op(unknown.0.0:10 43.2s0 43:403c9185:test-rados-api-smithi190-14769-24::foo:head [call lock.lock] snapc 0=[] ondisk+write+known_if_redirected e32) v8 -- 0x555fe1ffb040 con 0
2018-04-04 04:15:11.000423 7fcc74a18980 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 4
2018-04-04 04:15:11.000426 7fcc74a18980  5 client.4388.objecter 1 in flight
2018-04-04 04:15:11.003425 7fcc622a0700  1 -- 172.21.15.190:0/4133745564 <== osd.4 172.21.15.39:6804/13236 5 ==== osd_op_reply(10 foo [call] v32'2 uv1 ondisk = -17 ((17) File exists)) v8 ==== 147+0+0 (919667873 0 0) 0x7fcc54005e20 con 0x555fe1ff15f0
2018-04-04 04:15:11.003456 7fcc622a0700 10 client.4388.objecter ms_dispatch 0x555fe1e20830 osd_op_reply(10 foo [call] v32'2 uv1 ondisk = -17 ((17) File exists)) v8
2018-04-04 04:15:11.003462 7fcc622a0700 10 client.4388.objecter in handle_osd_op_reply
2018-04-04 04:15:11.003466 7fcc622a0700  7 client.4388.objecter handle_osd_op_reply 10 ondisk uv 1 in 43.2 attempt 0
2018-04-04 04:15:11.003470 7fcc622a0700 10 client.4388.objecter  op 0 rval -17 len 0
2018-04-04 04:15:11.003472 7fcc622a0700 15 client.4388.objecter handle_osd_op_reply completed tid 10
2018-04-04 04:15:11.003473 7fcc622a0700 15 client.4388.objecter finish_op 10
2018-04-04 04:15:11.003476 7fcc622a0700 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 4
2018-04-04 04:15:11.003478 7fcc622a0700 15 client.4388.objecter _session_op_remove 4 10
2018-04-04 04:15:11.003482 7fcc622a0700  5 client.4388.objecter 0 in flight
2018-04-04 04:15:11.003489 7fcc622a0700 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.003496 7fcc74a18980 10 librados: Objecter returned from call r=-17
2018-04-04 04:15:11.003518 7fcc74a18980 10 librados: call oid=foo nspace=test-rados-api-smithi190-14769-24
2018-04-04 04:15:11.003524 7fcc74a18980 10 client.4388.objecter _op_submit op 0x555fe1ffb040
2018-04-04 04:15:11.003527 7fcc74a18980 20 client.4388.objecter _calc_target epoch 32 base foo @43;test-rados-api-smithi190-14769-24 precalc_pgid 0 pgid 0.0 is_write
2018-04-04 04:15:11.003531 7fcc74a18980 20 client.4388.objecter _calc_target target foo @43;test-rados-api-smithi190-14769-24 -> pgid 43.a1893c02
2018-04-04 04:15:11.003545 7fcc74a18980 10 client.4388.objecter _calc_target  raw pgid 43.a1893c02 -> actual 43.2s0 acting [4,7,5] primary 4
2018-04-04 04:15:11.003549 7fcc74a18980 20 client.4388.objecter _get_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.003556 7fcc74a18980 10 client.4388.objecter _op_submit oid foo '@43;test-rados-api-smithi190-14769-24' '@43;test-rados-api-smithi190-14769-24' [call lock.lock] tid 11 osd.4
2018-04-04 04:15:11.003561 7fcc74a18980 20 client.4388.objecter get_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.003564 7fcc74a18980 15 client.4388.objecter _session_op_assign 4 11
2018-04-04 04:15:11.003565 7fcc74a18980 15 client.4388.objecter _send_op 11 to 43.2s0 on osd.4
2018-04-04 04:15:11.003568 7fcc74a18980  1 -- 172.21.15.190:0/4133745564 --> 172.21.15.39:6804/13236 -- osd_op(unknown.0.0:11 43.2s0 43:403c9185:test-rados-api-smithi190-14769-24::foo:head [call lock.lock] snapc 0=[] ondisk+write+known_if_redirected e32) v8 -- 0x555fe1ffc0d0 con 0
2018-04-04 04:15:11.003595 7fcc74a18980 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 4
2018-04-04 04:15:11.003599 7fcc74a18980  5 client.4388.objecter 1 in flight
2018-04-04 04:15:11.009841 7fcc622a0700  1 -- 172.21.15.190:0/4133745564 <== osd.4 172.21.15.39:6804/13236 6 ==== osd_op_reply(11 foo [call] v32'3 uv3 ondisk = 0) v8 ==== 147+0+0 (1769456686 0 0) 0x7fcc54006930 con 0x555fe1ff15f0
2018-04-04 04:15:11.009870 7fcc622a0700 10 client.4388.objecter ms_dispatch 0x555fe1e20830 osd_op_reply(11 foo [call] v32'3 uv3 ondisk = 0) v8
2018-04-04 04:15:11.009877 7fcc622a0700 10 client.4388.objecter in handle_osd_op_reply
2018-04-04 04:15:11.009882 7fcc622a0700  7 client.4388.objecter handle_osd_op_reply 11 ondisk uv 3 in 43.2 attempt 0
2018-04-04 04:15:11.009886 7fcc622a0700 10 client.4388.objecter  op 0 rval 0 len 0
2018-04-04 04:15:11.009889 7fcc622a0700 15 client.4388.objecter handle_osd_op_reply completed tid 11
2018-04-04 04:15:11.009891 7fcc622a0700 15 client.4388.objecter finish_op 11
2018-04-04 04:15:11.009895 7fcc622a0700 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 4
2018-04-04 04:15:11.009898 7fcc622a0700 15 client.4388.objecter _session_op_remove 4 11
2018-04-04 04:15:11.009906 7fcc622a0700  5 client.4388.objecter 0 in flight
2018-04-04 04:15:11.009917 7fcc622a0700 20 client.4388.objecter put_session s=0x555fe1ff0e70 osd=4 3
2018-04-04 04:15:11.009939 7fcc74a18980 10 librados: Objecter returned from call r=0

Actions

Copy link

Updated by Sage Weil almost 6 years ago

Subject changed from ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP (luminous) to luminous: ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP

Actions

Copy link

Updated by Sage Weil almost 6 years ago

Subject changed from luminous: ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP to ceph_test_rados_api_lock fails LibRadosLockPP.LockExclusiveDurPP
Backport changed from luminous to mimic,luminous

2018-05-24T10:01:03.004 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock: [ RUN      ] LibRadosLockEC.LockExclusiveDur
2018-05-24T10:01:03.005 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock: /build/ceph-13.1.1-65-ge8d43bc/src/test/librados/lock.cc:264: Failure
2018-05-24T10:01:03.005 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock:       Expected: expected
2018-05-24T10:01:03.005 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock:       Which is: 0
2018-05-24T10:01:03.005 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock: To be equal to: wait_until(1.0s, 0.1s, expected, lock_exclusive, nullptr)
2018-05-24T10:01:03.008 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock:       Which is: -17
2018-05-24T10:01:03.009 INFO:tasks.workunit.client.0.smithi124.stdout:                 api_lock: [  FAILED  ] LibRadosLockEC.LockExclusiveDur (836 ms)

/a/sage-2018-05-23_14:55:44-rados-wip-sage3-testing-2018-05-22-2126-distro-basic-smithi/2577171

Actions

Copy link

#10

Updated by Neha Ojha almost 6 years ago

2018-06-28T00:17:59.962 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock: [ RUN      ] LibRadosLockEC.LockExclusiveDur
2018-06-28T00:17:59.962 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock: /build/ceph-14.0.0-732-gb68920d/src/test/librados/lock.cc:264: Failure
2018-06-28T00:17:59.962 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock:       Expected: expected
2018-06-28T00:17:59.962 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock:       Which is: 0
2018-06-28T00:17:59.962 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock: To be equal to: wait_until(1.0s, 0.1s, expected, lock_exclusive, nullptr)
2018-06-28T00:17:59.963 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock:       Which is: -17
2018-06-28T00:17:59.963 INFO:tasks.workunit.client.0.smithi023.stdout:                 api_lock: [  FAILED  ] LibRadosLockEC.LockExclusiveDur (988 ms)

/a/nojha-2018-06-27_22:32:36-rados-wip-23979-distro-basic-smithi/2715634/

Actions

Copy link

#11

Updated by Kefu Chai over 5 years ago

2018-12-06T18:10:37.797 INFO:tasks.workunit.client.0.smithi167.stdout:                 api_lock: /build/ceph-14.0.1-1461-g7b2d092/src/test/librados/lock.cc:38
: Failure
2018-12-06T18:10:37.797 INFO:tasks.workunit.client.0.smithi167.stdout:                 api_lock:       Expected: expected
2018-12-06T18:10:37.797 INFO:tasks.workunit.client.0.smithi167.stdout:                 api_lock:       Which is: 0
2018-12-06T18:10:37.797 INFO:tasks.workunit.client.0.smithi167.stdout:                 api_lock: To be equal to: wait_until(1.0s, 0.1s, expected, lock_exclusi
ve, nullptr)
2018-12-06T18:10:37.797 INFO:tasks.workunit.client.0.smithi167.stdout:                 api_lock:       Which is: -17
2018-12-06T18:10:37.797 INFO:tasks.workunit.client.0.smithi167.stdout:                 api_lock: [  FAILED  ] LibRadosLock.LockExclusiveDur (1120 ms)

http://pulpito.ceph.com/ifed01-2018-12-06_17:39:52-rados-wip-ifed-testing-distro-basic-smithi/3311934/

Actions

Copy link

#12