Ceph » Linux kernel client

From https://pulpito.ceph.com/xiubli-2020-08-11_04:26:09-multimds-wip-lxb-testing-defer-2020-0811-1023-distro-basic-smithi/5340304/teuthology.log

"2020-08-12T00:25:02.919422+0000 mds.f (mds.1) 1 : cluster [WRN] client.4478 isn't responding to mclientcaps(revoke), ino 0x1000000076a pending pAsLsXsFr issued pAsLsXsFrw, sent 60.556674 seconds ago" in cluster log

From https://pulpito.ceph.com/xiubli-2020-08-11_04:26:09-multimds-wip-lxb-testing-defer-2020-0811-1023-distro-basic-smithi/5340304/smithi148/log/ceph-mds.f.log.gz

2020-08-12T00:25:02.915+0000 7f3017f1c700 10 mds.1.locker scatter_tick
2020-08-12T00:25:02.915+0000 7f3017f1c700 20 mds.1.locker caps_tick 1 revoking caps
2020-08-12T00:25:02.915+0000 7f3017f1c700 20 mds.1.locker caps_tick age = 60.556674 client.4478.0x1000000076a
2020-08-12T00:25:02.915+0000 7f3017f1c700  0 log_channel(cluster) log [WRN] : client.4478 isn't responding to mclientcaps(revoke), ino 0x1000000076a pending pAsLsXsFr issued pAsLsXsFrw, sent 60.556674 seconds ago
2020-08-12T00:25:02.915+0000 7f3017f1c700 20 mds.1.locker caps_tick client.4478 isn't responding to mclientcaps(revoke), ino 0x1000000076a pending pAsLsXsFr issued pAsLsXsFrw, sent 60.556674 seconds ago
2020-08-12T00:25:02.915+0000 7f3017f1c700 20 mds.1.bal handle_export_pins export_pin_queue size=0
2020-08-12T00:25:02.915+0000 7f3017f1c700 15 mds.1.bal tick tick last_sample now 899.914346s
2020-08-12T00:25:02.915+0000 7f3017f1c700 15 mds.1.cache show_subtrees
...
2020-08-12T00:25:03.907+0000 7f3015717700 20 mds.1.cache upkeep thread waiting interval 1s
2020-08-12T00:25:04.603+0000 7f301971f700  1 -- [v2:172.21.15.148:6839/1573709161,v1:172.21.15.148:6841/1573709161] <== client.4478 v1:172.21.15.131:0/1823065202 120 ==== client_caps(update ino 0x1000000076a 224 seq 8 tid 1726 caps=pAsLsXs dirty=Fw wanted=- follows 1 mseq 1 size 104857600/0 mtime 2020-08-12T00:22:35.869663+0000) v10 ==== 236+0+0 (unknown 3013966134 0 0) 0x5609975b5500 con 0x5609964fb000
2020-08-12T00:25:04.603+0000 7f301971f700  7 mds.1.locker handle_client_caps  on 0x1000000076a tid 1726 follows 1 op update flags 0x0
2020-08-12T00:25:04.603+0000 7f301971f700 20 mds.1.8 get_session have 0x560997378880 client.4478 v1:172.21.15.131:0/1823065202 state open
2020-08-12T00:25:04.603+0000 7f301971f700 10 mds.1.locker  head inode [inode 0x1000000076a [2,head] /client.1/tmp/tmp/data/datafile54 auth{0=1} v2805 ap=2 dirtyparent s=104857600 n(v0 rc2020-08-12T00:22:35.869663+0000 b104857600 1=1+0) (ifile mix->sync) (iversion lock) cr={4478=0-213909504@1} caps={4478=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFxwb@8} mcw={0=AsXs} | ptrwaiter=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x56099745b080]
2020-08-12T00:25:04.603+0000 7f301971f700 10 mds.1.cache pick_inode_snap follows 1 on [inode 0x1000000076a [2,head] /client.1/tmp/tmp/data/datafile54 auth{0=1} v2805 ap=2 dirtyparent s=104857600 n(v0 rc2020-08-12T00:22:35.869663+0000 b104857600 1=1+0) (ifile mix->sync) (iversion lock) cr={4478=0-213909504@1} caps={4478=pAsLsXsFr/pAsLsXsFrw/pAsxXsxFxwb@8} mcw={0=AsXs} | ptrwaiter=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x56099745b080]
2020-08-12T00:25:04.603+0000 7f301971f700 10 mds.1.locker  follows 1 retains pAsLsXs dirty Fw on [inode 0x1000000076a [2,head] /client.1/tmp/tmp/data/datafile54 auth{0=1} v2805 ap=2 dirtyparent s=104857600 n(v0 rc2020-08-12T00:22:35.869663+0000 b104857600 1=1+0) (ifile mix->sync) (iversion lock) cr={4478=0-213909504@1} caps={4478=pAsLsXs/pAsxXsxFxwb@8} mcw={0=AsXs} | ptrwaiter=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x56099745b080]
2020-08-12T00:25:04.603+0000 7f301971f700  7 mds.1.locker  flush client.4478 dirty Fw seq 8 on [inode 0x1000000076a [2,head] /client.1/tmp/tmp/data/datafile54 auth{0=1} v2805 ap=2 dirtyparent s=104857600 n(v0 rc2020-08-12T00:22:35.869663+0000 b104857600 1=1+0) (ifile mix->sync) (iversion lock) cr={4478=0-213909504@1} caps={4478=pAsLsXs/pAsxXsxFxwb@8} mcw={0=AsXs} | ptrwaiter=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x56099745b080]
2020-08-12T00:25:04.603+0000 7f301971f700 10 mds.1.locker  wanted pAsxXsxFxwb -> -
2020-08-12T00:25:04.603+0000 7f301971f700 10 mds.1.locker _do_cap_update dirty Fw issued pAsLsXs wanted - on [inode 0x1000000076a [2,head] /client.1/tmp/tmp/data/datafile54 auth{0=1} v2805 ap=2 dirtyparent s=104857600 n(v0 rc2020-08-12T00:22:35.869663+0000 b104857600 1=1+0) (ifile mix->sync) (iversion lock) cr={4478=0-213909504@1} caps={4478=pAsLsXs/-@8} mcw={0=AsXs} | ptrwaiter=0 lock=0 importingcaps=0 caps=1 dirtyparent=1 replicated=1 dirty=1 waiter=0 authpin=1 0x56099745b080]
2020-08-12T00:25:04.603+0000 7f301971f700 20 mds.1.locker inode is file

Just after it timedout and give a WRN, 2 seconds later the mds received the revoke reply.