Project

General

Profile

Bug #46882

client: mount abort hangs: [volumes INFO mgr_util] aborting connection from cephfs 'cephfs'

Added by Patrick Donnelly 2 months ago. Updated about 2 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
-
Target version:
% Done:

100%

Source:
Q/A
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Client
Labels (FS):
Pull request ID:
Crash signature:

Description

2020-08-08T03:29:45.508 INFO:teuthology.orchestra.run.smithi189:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 120 ceph --cluster ceph --log-early fs subvolume create cephfs subvolume_0000000000050640
...
2020-08-08T03:31:45.539 DEBUG:teuthology.orchestra.run:got remote process result: 124

From: /ceph/teuthology-archive/pdonnell-2020-08-08_02:16:26-fs-wip-pdonnell-testing-20200808.001303-distro-basic-smithi/5318975/teuthology.log

2020-08-08T03:29:45.819+0000 7f098a64f700  1 -- [v2:172.21.15.189:6800/17413,v1:172.21.15.189:6801/17413] <== client.7800 172.21.15.189:0/2577212952 1 ==== mgr_command(tid 0: {"prefix": "fs subvolume create", "vol_name": "cephfs", "sub_name": "subvolume_0000000000050640", "target": ["mon-mgr", ""]}) v1 ==== 148+0+0 (secure 0 0 0) 0x55d5a6fd2580 con 0x55d5aa7de800
2020-08-08T03:29:45.819+0000 7f098a64f700 10 mgr.server _handle_command decoded-size=4 prefix=fs subvolume create
2020-08-08T03:29:45.819+0000 7f098a64f700 20 is_capable service=py module=volumes command=fs subvolume create read write addr - on cap allow *
2020-08-08T03:29:45.819+0000 7f098a64f700 20  allow so far , doing grant allow *
2020-08-08T03:29:45.819+0000 7f098a64f700 20  allow all
2020-08-08T03:29:45.819+0000 7f098a64f700 10 mgr.server _allowed_command  client.admin capable
2020-08-08T03:29:45.819+0000 7f098a64f700  0 log_channel(audit) log [DBG] : from='client.7800 -' entity='client.admin' cmd=[{"prefix": "fs subvolume create", "vol_name": "cephfs", "sub_name": "subvolume_0000000000050640", "target": ["mon-mgr", ""]}]: dispatch
2020-08-08T03:29:45.819+0000 7f098a64f700 10 mgr.server _handle_command passing through 4
2020-08-08T03:29:45.819+0000 7f098ae50700 20 mgr Gil Switched to new thread state 0x55d5aa232d00
2020-08-08T03:29:45.819+0000 7f098ae50700  0 [volumes INFO volumes.module] Starting _cmd_fs_subvolume_create(prefix:fs subvolume create, sub_name:subvolume_0000000000050640, target:['mon-mgr', ''], vol_name:cephfs) < "" 
2020-08-08T03:29:45.819+0000 7f098ae50700  0 [volumes DEBUG mgr_util] self.fs_id=2, fs_id=3
2020-08-08T03:29:45.819+0000 7f098ae50700  0 [volumes WARNING mgr_util] filesystem id changed for volume 'cephfs', reconnecting...
2020-08-08T03:29:45.819+0000 7f098ae50700  0 [volumes DEBUG mgr_util] self.fs_id=2, fs_id=3
2020-08-08T03:29:45.819+0000 7f098ae50700  0 [volumes INFO mgr_util] aborting connection from cephfs 'cephfs'
2020-08-08T03:29:45.819+0000 7f098ae50700  2 client.5371 unmounting (abort)
2020-08-08T03:29:45.819+0000 7f098ae50700  5 client.5371 _closed_mds_session mds.0 seq 2922
...
2020-08-08T03:29:45.819+0000 7f098ae50700  2 client.5371 cache still has 0+2 items, waiting (for caps to release?)
...
2020-08-08T03:29:50.823+0000 7f098ae50700  1 client.5371 dump_cache
2020-08-08T03:29:50.823+0000 7f098ae50700  1 client.5371 dump_inode: DISCONNECTED inode 0x1000000029b #0x1000000029b ref 10x1000000029b.snapdir(faked_ino=0 ref=1 ll_ref=0 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=2020-08-08T03:27:39.445166+0000 mtime=2020-08-08T03:27:39.464824+0000 ctime=2020-08-08T03:27:39.464824+0000 caps=- 0x55d5aa97a580)
2020-08-08T03:29:50.823+0000 7f098ae50700  1 client.5371 dump_inode: DISCONNECTED inode 0x1000000029b #0x1000000029b ref 10x1000000029b.head(faked_ino=0 ref=1 ll_ref=0 cap_refs={} open={} mode=40755 size=0/0 nlink=0 btime=0.000000 mtime=2020-08-08T03:29:03.636284+0000 ctime=2020-08-08T03:29:03.655838+0000 caps=- 0x55d5aaa43b80)
2020-08-08T03:29:50.823+0000 7f098ae50700  2 client.5371 cache still has 0+2 items, waiting (for caps to release?)
...

From: /ceph/teuthology-archive/pdonnell-2020-08-08_02:16:26-fs-wip-pdonnell-testing-20200808.001303-distro-basic-smithi/5318975/remote/smithi189/log/ceph-mgr.y.log.gz


Subtasks

Bug #47033: client: inode ref leakDuplicateXiubo Li


Related issues

Duplicated by fs - Bug #47140: mgr/volumes: unresponsive Client::abort_conn() when cleaning stale libcephfs handle Duplicate

History

#1 Updated by Xiubo Li 2 months ago

  • Status changed from New to In Progress

#2 Updated by Xiubo Li 2 months ago

Checked it, it seems the write ops didn't finished and kept going while the _umount() just stopped the tick(), then the client got blacklisted after 300s:

Such as we can see the write ops is slow, for some files even after around 300s:

2020-08-10T15:22:28.081+0000 7f54882511c0  2 client.4593 unmounting
...

3358 30000000236.00000005 [write 225280~4096] v24'15524 uv15524 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f5464014780 con 0x7f5444008dd0
2020-08-10T15:26:33.535+0000 7f5478fe8700  1 -- 172.21.15.175:0/1466508553 <== osd.6 v2:172.21.15.116:6826/35233 30701 ==== osd_op_reply(68696 30000000219.00000012 [write 1245184~4096] v24'16219 uv16219 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f5464014780 con 0x7f5444008dd0
2020-08-10T15:26:33.535+0000 7f5478fe8700  1 -- 172.21.15.175:0/1466508553 <== osd.6 v2:172.21.15.116:6826/35233 30702 ==== osd_op_reply(54634 3000000020c.0000000f [write 3837952~4096] v24'14784 uv14784 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f5464014780 con 0x7f5444008dd0
2020-08-10T15:26:33.593+0000 7f5478fe8700  1 -- 172.21.15.175:0/1466508553 <== osd.6 v2:172.21.15.116:6826/35233 30703 ==== osd_op_reply(57125 30000000214.00000009 [write 487424~4096] v24'15290 uv15290 ondisk = 0) v8 ==== 164+0+0 (crc 0 0 0) 0x7f5464014780 con 0x7f5444008dd0

#3 Updated by Xiubo Li 2 months ago

Additional info:

From the logs we can see that the inode ref was increased by:

_flush(in, new C_Client_FlushComplete(this, in));

But never be decreased before the client was blacklisted:

2020-08-10T15:22:28.081+0000 7f54882511c0 15 inode.get on 0x7f545c062670 0x10000000352.head now 4
2020-08-10T15:22:28.081+0000 7f54882511c0 20 client.4593 _release 0x10000000352.head(faked_ino=0 ref=4 ll_ref=0 cap_refs={4=0,1024=1,4096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=0 btime=0.000000 mtime=2020-08-10T15:16:36.423961+0000 ctime=2020-08-10T15:22:08.870067+0000 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[0x10000000352 ts 0/0 objects 25 dirty_or_tx 1347584] 0x7f545c062670)
2020-08-10T15:22:28.081+0000 7f54882511c0 15 inode.get on 0x7f545c062670 0x10000000352.head now 5
2020-08-10T15:22:28.081+0000 7f54882511c0 10 client.4593 _flush 0x10000000352.head(faked_ino=0 ref=5 ll_ref=0 cap_refs={4=0,1024=1,4096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=0 btime=0.000000 mtime=2020-08-10T15:16:36.423961+0000 ctime=2020-08-10T15:22:08.870067+0000 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[0x10000000352 ts 0/0 objects 25 dirty_or_tx 1347584] 0x7f545c062670)
...

The following decrease was for `anchor.emplace_back(in);`

096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=0 btime=0.000000 mtime=2020-08-10T15:16:36.423961+0000 ctime=2020-08-10T15:22:08.870067+0000 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb) objectset[0x10000000352 ts 0/0 objects 25 dirty_or_tx 1347584] 0x7f545c062670)
2020-08-10T15:22:28.087+0000 7f54882511c0 15 inode.put on 0x7f545c062670 0x10000000352.head now 4

...

2020-08-10T15:26:08.112+0000 7f54882511c0  1 client.4593 dump_cache
2020-08-10T15:26:08.112+0000 7f54882511c0  1 client.4593 dump_inode: DISCONNECTED inode 0x10000000352 #0x10000000352 ref 40x10000000352.head(faked_ino=0 ref=4 ll_ref=0 cap_refs={4=0,1024=1,4096=0,8192=1} open={2=0,3=0} mode=100700 size=104857600/213909504 nlink=0 btime=0.000000 mtime=2020-08-10T15:16:36.423961+0000 ctime=2020-08-10T15:22:08.870067+0000 caps=-(0=pAsLsXsFsxcrwb) objectset[0x10000000352 ts 0/0 objects 25 dirty_or_tx 24576] 0x7f545c062670)

#4 Updated by Xiubo Li 2 months ago

The above was from /a/pdonnell-2020-08-08_02\:21\:01-multimds-wip-pdonnell-testing-20200808.001303-distro-basic-smithi/5319314 instead.

This tracker you are referencing is a little different.

#5 Updated by Xiubo Li 2 months ago

  • Pull request ID set to 36580

#6 Updated by Xiubo Li 2 months ago

  • Status changed from In Progress to Fix Under Review

#7 Updated by Xiubo Li 2 months ago

In case:

func()
{
  InodeRef in;

  std::scoped_lock cl{client_lock};

}

The InodeRef will call the put_inode() out of the client_lock scope, which will be buggy. Then the inode->_put() maybe racy in mutiple thread contexts.

#8 Updated by Ramana Raja 2 months ago

Shyam spotted this issue in a recent mgr/volumes testing,
https://github.com/ceph/ceph/pull/35756#issuecomment-676670500

#9 Updated by Patrick Donnelly 2 months ago

Another: /ceph/teuthology-archive/pdonnell-2020-08-21_07:42:41-fs-wip-pdonnell-testing-20200821.043335-distro-basic-smithi/5364893/remote/smithi082/log/ceph-client.libcephfs_readonly_test.403460584.111789.log.gz

#10 Updated by Venky Shankar about 2 months ago

  • Duplicated by Bug #47140: mgr/volumes: unresponsive Client::abort_conn() when cleaning stale libcephfs handle added

#11 Updated by Patrick Donnelly about 2 months ago

  • Status changed from Fix Under Review to Resolved
  • Backport deleted (octopus,nautilus)

I don't think this issue exists in Octopus or Nautilus? I think this is fallout from Xiubo's work on breaking the client_lock. So I'm removing the backports for now.

Also available in: Atom PDF