Project

General

Profile

Actions

Bug #59534

open

qa/workunits/suites/dbench.sh failed with "write failed on handle 9938 (Input/output error)"

Added by Xiubo Li 12 months ago. Updated 3 months ago.

Status:
Triaged
Priority:
Normal
Assignee:
Category:
Correctness/Safety
Target version:
% Done:

100%

Source:
Tags:
Backport:
reef,quincy,pacific
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Client
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

https://pulpito.ceph.com/vshankar-2023-04-20_04:50:51-fs-wip-vshankar-testing-20230412.053558-testing-default-smithi/7245942/

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.


Subtasks 1 (0 open1 closed)

Bug #64265: Command failed (workunit test suites/dbench.sh)Duplicate

Actions
Actions #3

Updated by Venky Shankar 12 months ago

  • Category set to Correctness/Safety
  • Assignee set to Xiubo Li
  • Target version set to v19.0.0
Actions #4

Updated by Venky Shankar 12 months 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?

Actions #5

Updated by Venky Shankar 12 months 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?

Actions #6

Updated by Xiubo Li 12 months 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.

Actions #7

Updated by Xiubo Li 12 months 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.

Actions #8

Updated by Venky Shankar 12 months ago

  • Assignee set to Xiubo Li
  • Priority changed from Normal to High
  • Severity changed from 3 - minor to 2 - major
  • Component(FS) Client added
Actions #9

Updated by Venky Shankar 12 months ago

  • Status changed from New to Triaged
Actions #10

Updated by Venky Shankar 12 months 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).

Actions #11

Updated by Venky Shankar 12 months 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).

Actions #12

Updated by Xiubo Li 12 months 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/1855002755

mentions 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.

Actions #13

Updated by Venky Shankar 12 months ago

BTW - all failures are for ceph-fuse. kclient seems fine.

Actions #14

Updated by Xiubo Li 12 months 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.

Actions #16

Updated by Xiubo Li 12 months 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.

Actions #17

Updated by Xiubo Li 12 months 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.

https://pulpito.ceph.com/vshankar-2023-04-21_04:40:06-fs-wip-vshankar-testing-20230420.132447-testing-default-smithi/7247276/

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

Actions #18

Updated by Xiubo Li 12 months ago

Xiubo Li wrote:

https://pulpito.ceph.com/vshankar-2023-04-20_04:50:51-fs-wip-vshankar-testing-20230412.053558-testing-default-smithi/7245942/

[...]

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.

Actions #19

Updated by Venky Shankar 12 months ago

  • Assignee changed from Xiubo Li to Venky Shankar
  • Backport set to reef,quincy,pacific

Taking this from Xiubo (spoke verbally over call).

Actions #20

Updated by Xiubo Li 12 months ago

  • Assignee changed from Venky Shankar to Xiubo Li

Xiubo Li wrote:

Xiubo Li wrote:

https://pulpito.ceph.com/vshankar-2023-04-20_04:50:51-fs-wip-vshankar-testing-20230412.053558-testing-default-smithi/7245942/

[...]

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.

Actions #21

Updated by Xiubo Li 12 months ago

  • Assignee changed from Xiubo Li to Venky Shankar

Sorry the comments conflict and assigned it back when committing it.

Actions #22

Updated by Xiubo Li 12 months 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.

Actions #23

Updated by Venky Shankar 12 months 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.

Actions #24

Updated by Xiubo Li 12 months 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.

Actions

Also available in: Atom PDF