Bug #59534
openqa/workunits/suites/dbench.sh failed with "write failed on handle 9938 (Input/output error)"
100%
Description
2023-04-23T00:13:25.693 INFO:tasks.workunit.client.0.smithi179.stdout: 0 12 0.00 MB/sec warmup 894 sec latency 894023.068 ms 2023-04-23T00:13:26.693 INFO:tasks.workunit.client.0.smithi179.stdout: 0 12 0.00 MB/sec warmup 895 sec latency 895023.186 ms 2023-04-23T00:13:27.693 INFO:tasks.workunit.client.0.smithi179.stdout: 0 12 0.00 MB/sec warmup 896 sec latency 896023.282 ms 2023-04-23T00:13:28.693 INFO:tasks.workunit.client.0.smithi179.stdout: 0 12 0.00 MB/sec warmup 897 sec latency 897023.398 ms 2023-04-23T00:13:29.693 INFO:tasks.workunit.client.0.smithi179.stdout: 0 12 0.00 MB/sec warmup 898 sec latency 898023.508 ms 2023-04-23T00:13:30.693 INFO:tasks.workunit.client.0.smithi179.stdout: 0 12 0.00 MB/sec warmup 899 sec latency 899023.569 ms 2023-04-23T00:13:31.671 INFO:tasks.workunit.client.0.smithi179.stdout:[12] write failed on handle 9938 (Input/output error) 2023-04-23T00:13:31.671 INFO:tasks.workunit.client.0.smithi179.stdout:Child failed with status 1 2023-04-23T00:13:31.672 DEBUG:teuthology.orchestra.run:got remote process result: 1 2023-04-23T00:13:31.673 INFO:tasks.workunit:Stopping ['suites/dbench.sh'] on client.0... 2023-04-23T00:13:31.673 DEBUG:teuthology.orchestra.run.smithi179:> sudo rm -rf -- /home/ubuntu/cephtest/workunits.list.client.0 /home/ubuntu/cephtest/clone.client.0 2023-04-23T00:13:32.570 ERROR:teuthology.run_tasks:Saw exception from tasks. Traceback (most recent call last):
And from the fuse client logs:
remote/smithi179/log/ceph-client.0.134417.log.gz
2023-04-22T23:58:31.670+0000 7fb2bbfff700 1 -- 172.21.15.179:0/1855002755 --> v1:172.21.15.90:6812/134863 -- osd_op(unknown.0.0:3 3.9 3:9258b67d:::10000000005.00000000:head [stat] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e17) v9 -- 0x7fb2b40320a0 con 0x7fb2b402e390 2023-04-22T23:58:31.670+0000 7fb2bbfff700 1 -- 172.21.15.179:0/1855002755 --> v1:172.21.15.90:6812/134863 -- osd_op(unknown.0.0:4 3.9 3:9258b67d:::10000000005.00000000:head [create] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e17) v9 -- 0x7fb2b4032ae0 con 0x7fb2b402e390 2023-04-22T23:58:31.671+0000 7fb2d37fe700 10 client.14477 ms_handle_connect on v1:172.21.15.90:6812/134863 2023-04-22T23:58:31.671+0000 7fb2d37fe700 1 -- 172.21.15.179:0/1855002755 <== osd.3 v1:172.21.15.90:6812/134863 1 ==== osd_map(17..17 src has 1..17) v4 ==== 3194+0+0 (unknown 3046238503 0 0) 0x7fb2d400bd20 con 0x7fb2b402e390 2023-04-22T23:58:32.326+0000 7fb2d1ffb700 20 client.14477 tick ... 2023-04-23T00:13:31.670+0000 7fb2bbfff700 10 client.14477 check_pool_perm on pool 3 ns rd_err = -110 wr_err = -110 2023-04-23T00:13:31.670+0000 7fb2bbfff700 10 client.14477 check_pool_perm on pool 3 ns rd_err = -110 wr_err = -110 2023-04-23T00:13:31.670+0000 7fb2bbfff700 3 client.14477 ll_write 0x7fb2ac002cc0 65534~1 = -5 2023-04-23T00:13:31.670+0000 7fb2d0ff9700 3 client.14477 ll_flush 0x7fb2ac002cc0 0x10000000005
The write failed when checking the pool's perms with -110 errno, which is timedout.
From the osd.3 logs:
remote/smithi090/log/ceph-osd.3.log.gz
90:6812/134863 target_addr v1:172.21.15.179:38462/0
2023-04-22 23:58:31.670 7efdec7fe700 10 osd.3 17 ms_handle_authentication new session 0x562db8c1bb80 con 0x562db8ba0400 entity client.0 addr v1:172.21.15.179:0/1855002755
2023-04-22 23:58:31.670 7efdec7fe700 10 osd.3 17 ms_handle_authentication session 0x562db8c1bb80 client.0 has caps osdcap[grant(rwx)] 'allow rwx'
2023-04-22 23:58:31.671 7efdec7fe700 1 -- v1:172.21.15.90:6812/134863 <== client.14477 v1:172.21.15.179:0/1855002755 1 ==== osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9 ==== 236+0+0 (unknown 1119608350 0 0) 0x562dbb778600 con 0x562db8ba0400
2023-04-22 23:58:31.671 7efdec7fe700 15 osd.3 17 enqueue_op 0x562db8bfef20 prio 63 cost 0 latency 0.000021 epoch 0 osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9
2023-04-22 23:58:31.671 7efdec7fe700 20 osd.3 op_wq(0) _enqueue OpQueueItem(0.0 PGOpItem(op=osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9) prio 63 cost 0 e0)
2023-04-22 23:58:31.671 7efdec7fe700 1 -- v1:172.21.15.90:6812/134863 <== client.14477 v1:172.21.15.179:0/1855002755 2 ==== osd_op(client.14477.0:4 0.0 0.0 (undecoded) - e0) v9 ==== 236+0+0 (unknown 3820315456 0 0) 0x562dbb778900 con 0x562db8ba0400
2023-04-22 23:58:31.671 7efdec7fe700 15 osd.3 17 enqueue_op 0x562db8f3e580 prio 63 cost 0 latency 0.000007 epoch 0 osd_op(client.14477.0:4 0.0 0.0 (undecoded) - e0) v9
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 op_wq(0) _process 0.0 (new) to_process <> waiting <> waiting_peering {}
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 op_wq(0) _process OpQueueItem(0.0 PGOpItem(op=osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9) prio 63 cost 0 e0) queued
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 op_wq(0) _process 0.0 to_process <OpQueueItem(0.0 PGOpItem(op=osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9) prio 63 cost 0 e0)> waiting <> waiting_peering {}
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 op_wq(0) _process OpQueueItem(0.0 PGOpItem(op=osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9) prio 63 cost 0 e0) pg 0
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 op_wq(0) _process 0.0 no pg, shouldn't exist e17, dropping OpQueueItem(0.0 PGOpItem(op=osd_op(client.14477.0:3 0.0 0.0 (undecoded) - e0) v9) prio 63 cost 0 e0)
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 17 share_map client.14477 v1:172.21.15.179:0/1855002755 0
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 17 should_share_map client.14477 v1:172.21.15.179:0/1855002755 0
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 17 client session last_sent_epoch: 0 versus osdmap epoch 17
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 client.14477 has old map 0 < 17
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 send_incremental_map 0 -> 17 to 0x562db8ba0400 v1:172.21.15.179:0/1855002755
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 add_map_bl 17 3150 bytes
The osd requests are just dropped by osd.3 because of the osdmap versions were mismatched.
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
This should be a incompatible issue between latest clients and nautilus osd code.
Updated by Xiubo Li about 1 year ago
Updated by Venky Shankar about 1 year ago
- Category set to Correctness/Safety
- Assignee set to Xiubo Li
- Target version set to v19.0.0
Updated by Venky Shankar about 1 year ago
- Assignee deleted (
Xiubo Li)
Xiubo, I saw updates in this tracker late and assigned the tracker to you in a rush. Do we know what is causing the op incompatibility b/w a newer client and on old OSD?
Updated by Venky Shankar about 1 year ago
Xiubo Li wrote:
[...]
The osd requests are just dropped by osd.3 because of the osdmap versions were mismatched.
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
Are these OSDMap epoch numbers?
Updated by Xiubo Li about 1 year ago
Venky Shankar wrote:
Xiubo Li wrote:
[...]
The osd requests are just dropped by osd.3 because of the osdmap versions were mismatched.
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
Are these OSDMap epoch numbers?
yeah, they are.
Updated by Xiubo Li about 1 year ago
Venky Shankar wrote:
Xiubo, I saw updates in this tracker late and assigned the tracker to you in a rush. Do we know what is causing the op incompatibility b/w a newer client and on old OSD?
I have no idea yet. Need to dig it further.
Updated by Venky Shankar about 1 year ago
- Assignee set to Xiubo Li
- Priority changed from Normal to High
- Severity changed from 3 - minor to 2 - major
- Component(FS) Client added
Updated by Venky Shankar about 1 year ago
Xiubo Li wrote:
Venky Shankar wrote:
Xiubo Li wrote:
[...]
The osd requests are just dropped by osd.3 because of the osdmap versions were mismatched.
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
Are these OSDMap epoch numbers?
yeah, they are.
Its really odd that the OSD sees an incorrect epoch (0) versus that of the client (17).
Updated by Venky Shankar about 1 year ago
Xiubo Li wrote:
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
Xiubo, isn't this the other way around? The log entry:
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 17 client session last_sent_epoch: 0 versus osdmap epoch 17
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 client.14477 has old map 0 < 17
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 send_incremental_map 0 -> 17 to 0x562db8ba0400 v1:172.21.15.179:0/1855002755
mentions that the client has an old map (with e0) and and incremental map is sent back by the OSD (with e17).
Updated by Xiubo Li about 1 year ago
Venky Shankar wrote:
Xiubo Li wrote:
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
Xiubo, isn't this the other way around? The log entry:
2023-04-22 23:58:31.671 7efdcebe9700 20 osd.3 17 client session last_sent_epoch: 0 versus osdmap epoch 17
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 client.14477 has old map 0 < 17
2023-04-22 23:58:31.671 7efdcebe9700 10 osd.3 17 send_incremental_map 0 -> 17 to 0x562db8ba0400 v1:172.21.15.179:0/1855002755mentions that the client has an old map (with e0) and and incremental map is sent back by the OSD (with e17).
Yeah, but the client has already had the e17 osdmap:
2023-04-22T23:58:31.670+0000 7fb2bbfff700 1 -- 172.21.15.179:0/1855002755 --> v1:172.21.15.90:6812/134863 -- osd_op(unknown.0.0:3 3.9 3:9258b67d:::10000000005.00000000:head [stat] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e17) v9 -- 0x7fb2b40320a0 con 0x7fb2b402e390 2023-04-22T23:58:31.670+0000 7fb2bbfff700 1 -- 172.21.15.179:0/1855002755 --> v1:172.21.15.90:6812/134863 -- osd_op(unknown.0.0:4 3.9 3:9258b67d:::10000000005.00000000:head [create] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e17) v9 -- 0x7fb2b4032ae0 con 0x7fb2b402e390
I will dig it further tomorrow, it seems the version was reset during sending the request.
Updated by Venky Shankar about 1 year ago
BTW - all failures are for ceph-fuse. kclient seems fine.
Updated by Xiubo Li about 1 year ago
Venky Shankar wrote:
BTW - all failures are for ceph-fuse. kclient seems fine.
Yeah, because the upgrade client test doesn't support the kclient yet.
Updated by Xiubo Li about 1 year ago
This one is using the pacific cluster and also has the same issue : https://pulpito.ceph.com/vshankar-2023-04-20_04:50:51-fs-wip-vshankar-testing-20230412.053558-testing-default-smithi/7245970/
Updated by Xiubo Li about 1 year ago
Xiubo Li wrote:
This one is using the pacific cluster and also has the same issue : https://pulpito.ceph.com/vshankar-2023-04-20_04:50:51-fs-wip-vshankar-testing-20230412.053558-testing-default-smithi/7245970/
There also some osd_op from the mgr clients and had no this issue. Only the requests from libcephfs will fail.
Updated by Xiubo Li about 1 year ago
This is a normal case: the client sent two requests with e95 then the osd handled it and at the same time sent back a new osdmap with e96.
2023-04-23T00:08:23.514+0000 7fc6a57f2700 3 client.15522 ll_write 0x7fc688004bb0 0x10000000007 0~16384 2023-04-23T00:08:23.514+0000 7fc6a57f2700 10 client.15522 get_quota_root realm 0x10000000002 2023-04-23T00:08:23.514+0000 7fc6a57f2700 10 client.15522 get_quota_root realm 0x1 2023-04-23T00:08:23.514+0000 7fc6a57f2700 10 client.15522 get_quota_root 0x10000000007.head -> 0x1.head 2023-04-23T00:08:23.514+0000 7fc6a57f2700 10 client.15522 cur file size is 0 2023-04-23T00:08:23.514+0000 7fc6a57f2700 1 --2- 192.168.0.1:0/1199226876 >> [v2:172.21.15.125:6800/821601430,v1:172.21.15.125:6801/821601430] conn(0x7fc68800eac0 0x7fc688010f70 unknown :-1 s=NONE pgs=0 cs=0 l=1 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect 2023-04-23T00:08:23.514+0000 7fc6a57f2700 1 -- 192.168.0.1:0/1199226876 --> [v2:172.21.15.125:6800/821601430,v1:172.21.15.125:6801/821601430] -- osd_op(unknown.0.0:2 4.1ds0 4:bbf5850a:::10000000007.00000000:head [stat] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e95) v9 -- 0x7fc6880116a0 con 0x7fc68800eac0 2023-04-23T00:08:23.514+0000 7fc6a57f2700 1 -- 192.168.0.1:0/1199226876 --> [v2:172.21.15.125:6800/821601430,v1:172.21.15.125:6801/821601430] -- osd_op(unknown.0.0:3 4.1ds0 4:bbf5850a:::10000000007.00000000:head [create] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e95) v9 -- 0x7fc6880120b0 con 0x7fc68800eac0 2023-04-23T00:08:23.514+0000 7fc6c0b9b700 1 --2- 192.168.0.1:0/1199226876 >> [v2:172.21.15.125:6800/821601430,v1:172.21.15.125:6801/821601430] conn(0x7fc68800eac0 0x7fc688010f70 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=1 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0 2023-04-23T00:08:23.515+0000 7fc6c0b9b700 1 --2- 192.168.0.1:0/1199226876 >> [v2:172.21.15.125:6800/821601430,v1:172.21.15.125:6801/821601430] conn(0x7fc68800eac0 0x7fc688010f70 crc :-1 s=READY pgs=23 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).ready entity=osd.2 client_cookie=0 server_cookie=0 in_seq=0 out_seq=0 2023-04-23T00:08:23.515+0000 7fc6a87f8700 10 client.15522 ms_handle_connect on v2:172.21.15.125:6800/821601430 2023-04-23T00:08:23.515+0000 7fc6a87f8700 1 -- 192.168.0.1:0/1199226876 <== osd.2 v2:172.21.15.125:6800/821601430 1 ==== osd_map(96..96 src has 1..96) v4 ==== 952+0+0 (crc 0 0 0) 0x7fc6b4029040 con 0x7fc68800eac0 2023-04-23T00:08:23.516+0000 7fc6c0b9b700 1 -- 192.168.0.1:0/1199226876 <== osd.2 v2:172.21.15.125:6800/821601430 2 ==== osd_op_reply(2 10000000007.00000000 [stat] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 164+0+0 (crc 0 0 0) 0x7fc6b402ecb0 con 0x7fc68800eac0 2023-04-23T00:08:23.517+0000 7fc6c0b9b700 1 -- 192.168.0.1:0/1199226876 <== osd.2 v2:172.21.15.125:6800/821601430 3 ==== osd_op_reply(3 10000000007.00000000 [create] v96'1 uv1 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7fc6b402ecb0 con 0x7fc68800eac0 2023-04-23T00:08:23.517+0000 7fc6a57f2700 10 client.15522 wanted_max_size 0 -> 16384
Updated by Xiubo Li about 1 year ago
Xiubo Li wrote:
[...]
And from the fuse client logs:
remote/smithi179/log/ceph-client.0.134417.log.gz
[...]
The write failed when checking the pool's perms with -110 errno, which is timedout.
From the osd.3 logs:
remote/smithi090/log/ceph-osd.3.log.gz
[...]
The osd requests are just dropped by osd.3 because of the osdmap versions were mismatched.
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
This should be a incompatible issue between latest clients and nautilus osd code.
Not only the epoch was reset to 0, and also the pgid and object info osd_op(unknown.0.0:3 3.9 3:9258b67d:::10000000005.00000000:head --> osd_op(client.14477.0:3 0.0 0.0, which are 3.9 --> 0.0 and 3:9258b67d --> 0.0.
Updated by Venky Shankar about 1 year ago
- Assignee changed from Xiubo Li to Venky Shankar
- Backport set to reef,quincy,pacific
Taking this from Xiubo (spoke verbally over call).
Updated by Xiubo Li about 1 year ago
- Assignee changed from Venky Shankar to Xiubo Li
Xiubo Li wrote:
Xiubo Li wrote:
[...]
And from the fuse client logs:
remote/smithi179/log/ceph-client.0.134417.log.gz
[...]
The write failed when checking the pool's perms with -110 errno, which is timedout.
From the osd.3 logs:
remote/smithi090/log/ceph-osd.3.log.gz
[...]
The osd requests are just dropped by osd.3 because of the osdmap versions were mismatched.
This is a upgrade client test case from nautilus, and the client sent two osd request with e17, while the osd just get a incorrect epoch number, witch is e0.
This should be a incompatible issue between latest clients and nautilus osd code.
Not only the epoch was reset to 0, and also the pgid and object info osd_op(unknown.0.0:3 3.9 3:9258b67d:::10000000005.00000000:head --> osd_op(client.14477.0:3 0.0 0.0, which are 3.9 --> 0.0 and 3:9258b67d --> 0.0.
For the nautilus and pacific the MOSDOp head version are both HEAD_VERSION = 8;, while the latest code the version is 9. So I think the nautilus and pacific couldn't correctly decode it.
Updated by Xiubo Li about 1 year ago
- Assignee changed from Xiubo Li to Venky Shankar
Sorry the comments conflict and assigned it back when committing it.
Updated by Xiubo Li about 1 year ago
This https://github.com/ceph/ceph/pull/47457 PR just merged 3 weeks ago and changed the MOSDOp head version to 9 and caused this issue.
Updated by Venky Shankar about 1 year ago
Xiubo Li wrote:
This https://github.com/ceph/ceph/pull/47457 PR just merged 3 weeks ago and changed the MOSDOp head version to 9 and caused this issue.
What head version of MOSDOp would the kclient use? If that's to <9, then the issue would be observed with kclients too.
Updated by Xiubo Li about 1 year ago
Venky Shankar wrote:
Xiubo Li wrote:
This https://github.com/ceph/ceph/pull/47457 PR just merged 3 weeks ago and changed the MOSDOp head version to 9 and caused this issue.
What head version of MOSDOp would the kclient use?
Recently there is no change for kclient about this.
msg->hdr.version = cpu_to_le16(8); /* MOSDOp v8 */
If that's to <9, then the issue would be observed with kclients too.
No, only when the version changed, which is > 8 will this issue be observed.