Project

General

Profile

Actions
Copy link

Bug #5162

closed

File is locked unexpected and not released anymore

Added by joe huang almost 11 years ago. Updated almost 8 years ago.

Status:
Can't reproduce
Priority:
High
Assignee:
-
Category:
-
Target version:
v0.61 - Cuttlefish
% Done:

0%

Source:
other
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
libcephfs
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

I deployed a ceph cluster and mount cephfs via kernel module. After using it few days later, when I ls a particular folder it hangs there. And then I found a file(owncloud.log) in that folder(/data) was locked but no one was using it. I issued # cat data/owncloud.log (and it hangs) and MDS's log shows

2013-05-24 13:56:26.332527 7f4ac1711700 10 mds.0.server ref is [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=32 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332643 7f4ac1711700 20 mds.0.locker must rdlock (iauth excl->sync) [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332670 7f4ac1711700 20 mds.0.locker must rdlock (ilink sync) [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332703 7f4ac1711700 20 mds.0.locker must rdlock (ifile excl->xsyn) [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332721 7f4ac1711700 20 mds.0.locker must rdlock (ixattr excl->sync) [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332738 7f4ac1711700 20 mds.0.locker must rdlock (isnap sync r=32) [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332817 7f4ac1711700 10 mds.0.locker must authpin [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332837 7f4ac1711700 10 mds.0.locker must authpin [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332858 7f4ac1711700 10 mds.0.locker must authpin [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332875 7f4ac1711700 10 mds.0.locker must authpin [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.332893 7f4ac1711700 10 mds.0.locker must authpin [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333051 7f4ac1711700 10 mds.0.locker auth_pinning [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=35+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333070 7f4ac1711700 10 mds.0.cache.ino(10000000072) auth_pin by 0x5af8800 on [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80] now 36+0

2013-05-24 13:56:26.333112 7f4ac1711700 10 mds.0.locker already auth_pinned [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333131 7f4ac1711700 10 mds.0.locker already auth_pinned [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333148 7f4ac1711700 10 mds.0.locker already auth_pinned [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333165 7f4ac1711700 10 mds.0.locker already auth_pinned [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333273 7f4ac1711700 7 mds.0.locker rdlock_start on (isnap sync r=32) on [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333293 7f4ac1711700 10 mds.0.locker got rdlock on (isnap sync r=33) [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333311 7f4ac1711700 7 mds.0.locker rdlock_start on (ifile excl->xsyn) on [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333331 7f4ac1711700 7 mds.0.locker rdlock_start waiting on (ifile excl->xsyn) on [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

2013-05-24 13:56:26.333356 7f4ac1711700 10 mds.0.locker nudge_log (ifile excl->xsyn) on [inode 10000000072 [2,head] /data/owncloud.log auth v1125157 ap=36+0 s=513713224 n(v0 b513713224 1=1+0) (iauth excl->sync) (ifile excl->xsyn) (ixattr excl->sync) (iversion lock) cr={5898=0-1073741824@1} caps={5898=pAsLsXsFcb/pAsxLsXsxFscrb/pAsxXsxFsxcrwb@8,6241=pLs/-@0,6859=pLsFcb/pFscr@11},l=5898(-1) | ptrwaiter=1 request=33 lock=1 caps=1 dirty=0 waiter=1 authpin=1 0x22bbd80]

Actions
Copy link
 #1

Updated by Zheng Yan almost 11 years ago

looks like client's fault. try following command on client.5898 and upload debug.txt:

  1. echo module ceph +p >/sys/kernel/debug/dynamic_debug/control
  2. dmesg -c > /dev/null
  3. cat data/owncloud.log
    ctrl^c
  4. ls -l data/owncloud.log
    ctrl^c
  5. dmesg > debug.txt
Actions
Copy link
 #2

Updated by joe huang almost 11 years ago

Hi Zheng,
Sorry for reply late. Here is the kernel msg.
[ 219.824078] ceph: mdsc delayed_work
[ 219.824085] ceph: check_delayed_caps
[ 219.824090] ceph: lookup_mds_session ffff880118e22800 3
[ 219.824093] ceph: mdsc get_session ffff880118e22800 3 -> 4
[ 219.824096] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 219.824098] ceph: mdsc con_get ffff880118e22800 ok (5)
[ 219.824102] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 219.824105] ceph: send_cap_releases mds0
[ 219.824107] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 219.824131] ceph: mdsc con_put ffff880118e22800 (3)
[ 219.824133] ceph: mdsc put_session ffff880118e22800 4 -> 3
[ 224.832061] ceph: mdsc delayed_work
[ 224.832065] ceph: check_delayed_caps
[ 224.832068] ceph: lookup_mds_session ffff880118e22800 3
[ 224.832069] ceph: mdsc get_session ffff880118e22800 3 -> 4
[ 224.832071] ceph: send_renew_caps to mds0 (up:active)
[ 224.832074] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 224.832075] ceph: mdsc con_get ffff880118e22800 ok (5)
[ 224.832076] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 224.832077] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 224.832080] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 224.832081] ceph: send_cap_releases mds0
[ 224.832082] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 224.832118] ceph: mdsc con_put ffff880118e22800 (4)
[ 224.832119] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 224.832698] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 224.832701] ceph: mdsc con_get ffff880118e22800 ok (5)
[ 224.832727] ceph: mdsc con_put ffff880118e22800 (4)
[ 224.832728] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 224.832731] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 224.832732] ceph: mdsc con_get ffff880118e22800 ok (5)
[ 224.832736] ceph: mdsc con_put ffff880118e22800 (4)
[ 224.832737] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 224.832739] ceph: handle_session mds0 renewcaps ffff880118e22800 state open seq 11
[ 224.832741] ceph: renewed_caps mds0 ttl now 4294963504, was fresh, now stale
[ 224.832745] ceph: mdsc con_put ffff880118e22800 (3)
[ 224.832746] ceph: mdsc put_session ffff880118e22800 4 -> 3
[ 229.824053] ceph: mdsc delayed_work
[ 229.824057] ceph: check_delayed_caps
[ 229.824061] ceph: lookup_mds_session ffff880118e22800 3
[ 229.824063] ceph: mdsc get_session ffff880118e22800 3 -> 4
[ 229.824066] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 229.824067] ceph: mdsc con_get ffff880118e22800 ok (5)
[ 229.824071] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 229.824073] ceph: send_cap_releases mds0
[ 229.824074] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 229.824094] ceph: mdsc con_put ffff880118e22800 (3)
[ 229.824096] ceph: mdsc put_session ffff880118e22800 4 -> 3
[ 230.941787] ceph: do_getattr inode ffff880117218308 mask As mode 040755
[ 230.941792] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask As)
[ 230.941794] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 230.941796] ceph: d_revalidate ffff880117201e40 'data' inode ffff880117288308 offset 0
[ 230.941798] ceph: dentry_lease_is_valid - dentry ffff880117201e40 = 0
[ 230.941799] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask Fs)
[ 230.941800] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 230.941809] ceph: dir_lease_is_valid dir ffff880117218308 v1 dentry ffff880117201e40 v1 = 1
[ 230.941811] ceph: d_revalidate ffff880117201e40 valid
[ 230.941812] ceph: dentry_lru_touch ffff8801171e3058 ffff880117201e40 'data' (offset 0)
[ 230.941814] ceph: do_getattr inode ffff880117288308 mask As mode 040750
[ 230.941815] ceph: __ceph_caps_issued_mask ffff880117288308 cap ffff8801171e2100 issued pAsLsXsFs (mask As)
[ 230.941816] ceph: __touch_cap ffff880117288308 cap ffff8801171e2100 mds0
[ 230.941818] ceph: d_revalidate ffff880117201d80 'owncloud.log' inode ffff880117288848 offset 53
[ 230.941819] ceph: dentry_lease_is_valid - dentry ffff880117201d80 = 0
[ 230.941820] ceph: __ceph_caps_issued_mask ffff880117288308 cap ffff8801171e2100 issued pAsLsXsFs (mask Fs)
[ 230.941821] ceph: __touch_cap ffff880117288308 cap ffff8801171e2100 mds0
[ 230.941823] ceph: dir_lease_is_valid dir ffff880117288308 v1 dentry ffff880117201d80 v1 = 1
[ 230.941823] ceph: d_revalidate ffff880117201d80 valid
[ 230.941824] ceph: dentry_lru_touch ffff8801171e30b0 ffff880117201d80 'owncloud.log' (offset 53)
[ 230.941826] ceph: do_getattr inode ffff880117288848 mask As mode 0100644
[ 230.941827] ceph: __ceph_caps_issued_mask ffff880117288848 cap ffff8801171e2180 issued pAsLsXsFcb (mask As)
[ 230.941828] ceph: __touch_cap ffff880117288848 cap ffff8801171e2180 mds0
[ 230.941831] ceph: open inode ffff880117288848 ino 10000000072.fffffffffffffffe file ffff88011539bc00 flags 32768 (32768)
[ 230.941833] ceph: __ceph_caps_issued ffff880117288848 cap ffff8801171e2180 issued pAsLsXsFcb
[ 230.941834] ceph: open ffff880117288848 fmode 1 want pFscr issued pAsLsXsFcb using existing
[ 230.941835] ceph: init_file ffff880117288848 ffff88011539bc00 0100644 (regular)
[ 230.941838] ceph: do_getattr inode ffff880117288848 mask pAsLsXsFs mode 0100644
[ 230.941839] ceph: do_request on ffff8801197d3400
[ 230.941841] ceph: reserve caps ctx=ffff8801197d36e0 need=1
[ 230.941843] ceph: reserve caps ctx=ffff8801197d36e0 1029 = 54 used + 3 resv + 972 avail
[ 230.941844] ceph: __register_request ffff8801197d3400 tid 7
[ 230.941846] ceph: __choose_mds ffff880117288848 is_hash=0 (0) mode 0
[ 230.941847] ceph: choose_mds ffff880117288848 10000000072.fffffffffffffffe mds0 (auth cap ffff8801171e2180)
[ 230.941849] ceph: lookup_mds_session ffff880118e22800 3
[ 230.941850] ceph: mdsc get_session ffff880118e22800 3 -> 4
[ 230.941851] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 230.941852] ceph: do_request mds0 session ffff880118e22800 state open
[ 230.941854] ceph: prepare_send_request ffff8801197d3400 tid 7 getattr (attempt 1)
[ 230.941855] ceph: inode ffff880117288848 10000000072.fffffffffffffffe
[ 230.941857] ceph: r_locked_dir = (null)
[ 230.941859] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 230.941859] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 230.941861] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 230.941862] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 230.941866] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 230.941867] ceph: do_request waiting
[ 230.941895] ceph: mdsc con_put ffff880118e22800 (5)
[ 230.941897] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 231.147282] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 231.147290] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 231.147318] ceph: mdsc con_put ffff880118e22800 (5)
[ 231.147321] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 231.147325] ceph: mdsc con_put ffff880118e22800 (4)
[ 231.147327] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 234.203046] ceph: do_request waited, got -512
[ 234.203050] ceph: aborted request 7 with -512
[ 234.203051] ceph: do_request ffff8801197d3400 done, result -512
[ 234.203053] ceph: do_getattr result=-512
[ 234.203119] ceph: release inode ffff880117288848 file ffff88011539bc00
[ 234.203120] ceph: put_fmode ffff880117288848 fmode 1 2 -> 1
[ 234.832063] ceph: mdsc delayed_work
[ 234.832068] ceph: check_delayed_caps
[ 234.832078] ceph: check_delayed_caps on ffff880117288848
[ 234.832083] ceph: __ceph_caps_issued ffff880117288848 cap ffff8801171e2180 issued pAsLsXsFcb
[ 234.832087] ceph: check_caps ffff880117288848 file_want pFscr used p dirty - flushing - issued pAsLsXsFcb revoking - retain pAsxLsxXsxFsxcrwbl NODELAY
[ 234.832089] ceph: mds0 cap ffff8801171e2180 issued pAsLsXsFcb implemented pAsLsXsFcb revoking -
[ 234.832092] ceph: lookup_mds_session ffff880118e22800 4
[ 234.832094] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 234.832097] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 234.832099] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 234.832102] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 234.832104] ceph: send_cap_releases mds0
[ 234.832106] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 234.832147] ceph: mdsc con_put ffff880118e22800 (4)
[ 234.832149] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 239.824090] ceph: mdsc delayed_work
[ 239.824096] ceph: check_delayed_caps
[ 239.824101] ceph: lookup_mds_session ffff880118e22800 4
[ 239.824103] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 239.824107] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 239.824109] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 239.824114] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 239.824116] ceph: send_cap_releases mds0
[ 239.824118] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 239.824169] ceph: mdsc con_put ffff880118e22800 (4)
[ 239.824173] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 243.829481] ceph: do_getattr inode ffff880117218308 mask pAsLsXsFs mode 040755
[ 243.829489] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask pAsLsXsFs)
[ 243.829492] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 244.737501] ceph: do_getattr inode ffff880117218308 mask pAsLsXsFs mode 040755
[ 244.737505] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask pAsLsXsFs)
[ 244.737507] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 244.738791] ceph: do_getattr inode ffff880117218308 mask pAsLsXsFs mode 040755
[ 244.738794] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask pAsLsXsFs)
[ 244.738795] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 244.832046] ceph: mdsc delayed_work
[ 244.832049] ceph: check_delayed_caps
[ 244.832052] ceph: lookup_mds_session ffff880118e22800 4
[ 244.832053] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 244.832055] ceph: send_renew_caps to mds0 (up:active)
[ 244.832058] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 244.832059] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 244.832060] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 244.832060] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 244.832063] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 244.832064] ceph: send_cap_releases mds0
[ 244.832065] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 244.832108] ceph: mdsc con_put ffff880118e22800 (5)
[ 244.832117] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 244.832727] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 244.832729] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 244.832755] ceph: mdsc con_put ffff880118e22800 (5)
[ 244.832757] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 244.832762] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 244.832763] ceph: mdsc con_get ffff880118e22800 ok (6)
[ 244.832767] ceph: mdsc con_put ffff880118e22800 (5)
[ 244.832769] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 244.832772] ceph: handle_session mds0 renewcaps ffff880118e22800 state open seq 12
[ 244.832773] ceph: renewed_caps mds0 ttl now 4294968504, was fresh, now stale
[ 244.832778] ceph: mdsc con_put ffff880118e22800 (4)
[ 244.832779] ceph: mdsc put_session ffff880118e22800 5 -> 4
[ 246.312593] ceph: do_getattr inode ffff880117218308 mask As mode 040755
[ 246.312598] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask As)
[ 246.312600] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 246.312602] ceph: d_revalidate ffff880117201e40 'data' inode ffff880117288308 offset 0
[ 246.312604] ceph: dentry_lease_is_valid - dentry ffff880117201e40 = 0
[ 246.312605] ceph: __ceph_caps_issued_mask ffff880117218308 cap ffff8801171e2080 issued pAsLsXsFs (mask Fs)
[ 246.312606] ceph: __touch_cap ffff880117218308 cap ffff8801171e2080 mds0
[ 246.312607] ceph: dir_lease_is_valid dir ffff880117218308 v1 dentry ffff880117201e40 v1 = 1
[ 246.312608] ceph: d_revalidate ffff880117201e40 valid
[ 246.312609] ceph: dentry_lru_touch ffff8801171e3058 ffff880117201e40 'data' (offset 0)
[ 246.312611] ceph: do_getattr inode ffff880117288308 mask As mode 040750
[ 246.312612] ceph: __ceph_caps_issued_mask ffff880117288308 cap ffff8801171e2100 issued pAsLsXsFs (mask As)
[ 246.312613] ceph: __touch_cap ffff880117288308 cap ffff8801171e2100 mds0
[ 246.312615] ceph: d_revalidate ffff880117201d80 'owncloud.log' inode ffff880117288848 offset 53
[ 246.312616] ceph: dentry_lease_is_valid - dentry ffff880117201d80 = 0
[ 246.312618] ceph: __ceph_caps_issued_mask ffff880117288308 cap ffff8801171e2100 issued pAsLsXsFs (mask Fs)
[ 246.312619] ceph: __touch_cap ffff880117288308 cap ffff8801171e2100 mds0
[ 246.312620] ceph: dir_lease_is_valid dir ffff880117288308 v1 dentry ffff880117201d80 v1 = 1
[ 246.312621] ceph: d_revalidate ffff880117201d80 valid
[ 246.312622] ceph: dentry_lru_touch ffff8801171e30b0 ffff880117201d80 'owncloud.log' (offset 53)
[ 246.312623] ceph: do_getattr inode ffff880117288848 mask pAsLsXsFs mode 0100644
[ 246.312626] ceph: do_request on ffff88011532cc00
[ 246.312628] ceph: reserve caps ctx=ffff88011532cee0 need=1
[ 246.312629] ceph: reserve caps ctx=ffff88011532cee0 1029 = 54 used + 4 resv + 971 avail
[ 246.312630] ceph: __register_request ffff88011532cc00 tid 8
[ 246.312632] ceph: __choose_mds ffff880117288848 is_hash=0 (0) mode 0
[ 246.312634] ceph: choose_mds ffff880117288848 10000000072.fffffffffffffffe mds0 (auth cap ffff8801171e2180)
[ 246.312636] ceph: lookup_mds_session ffff880118e22800 4
[ 246.312637] ceph: mdsc get_session ffff880118e22800 4 -> 5
[ 246.312638] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 246.312639] ceph: do_request mds0 session ffff880118e22800 state open
[ 246.312641] ceph: prepare_send_request ffff88011532cc00 tid 8 getattr (attempt 1)
[ 246.312642] ceph: inode ffff880117288848 10000000072.fffffffffffffffe
[ 246.312644] ceph: r_locked_dir = (null)
[ 246.312646] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 246.312647] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 246.312648] ceph: mdsc get_session ffff880118e22800 7 -> 8
[ 246.312649] ceph: mdsc con_get ffff880118e22800 ok (8)
[ 246.312654] ceph: mdsc put_session ffff880118e22800 8 -> 7
[ 246.312655] ceph: do_request waiting
[ 246.312690] ceph: mdsc con_put ffff880118e22800 (6)
[ 246.312691] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 246.519252] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 246.519264] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 246.519291] ceph: mdsc con_put ffff880118e22800 (6)
[ 246.519293] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 246.519295] ceph: mdsc con_put ffff880118e22800 (5)
[ 246.519296] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 249.824059] ceph: mdsc delayed_work
[ 249.824063] ceph: check_delayed_caps
[ 249.824066] ceph: lookup_mds_session ffff880118e22800 5
[ 249.824067] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 249.824069] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 249.824070] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 249.824073] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 249.824074] ceph: send_cap_releases mds0
[ 249.824075] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 249.824127] ceph: mdsc con_put ffff880118e22800 (5)
[ 249.824128] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 254.832060] ceph: mdsc delayed_work
[ 254.832064] ceph: check_delayed_caps
[ 254.832066] ceph: lookup_mds_session ffff880118e22800 5
[ 254.832068] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 254.832069] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 254.832070] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 254.832073] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 254.832074] ceph: send_cap_releases mds0
[ 254.832075] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 254.832112] ceph: mdsc con_put ffff880118e22800 (5)
[ 254.832113] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 259.824090] ceph: mdsc delayed_work
[ 259.824095] ceph: check_delayed_caps
[ 259.824100] ceph: lookup_mds_session ffff880118e22800 5
[ 259.824102] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 259.824106] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 259.824108] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 259.824113] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 259.824115] ceph: send_cap_releases mds0
[ 259.824117] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 259.824172] ceph: mdsc con_put ffff880118e22800 (5)
[ 259.824175] ceph: mdsc put_session ffff880118e22800 6 -> 5
[ 264.832072] ceph: mdsc delayed_work
[ 264.832078] ceph: check_delayed_caps
[ 264.832082] ceph: lookup_mds_session ffff880118e22800 5
[ 264.832085] ceph: mdsc get_session ffff880118e22800 5 -> 6
[ 264.832088] ceph: send_renew_caps to mds0 (up:active)
[ 264.832094] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 264.832096] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 264.832098] ceph: mdsc get_session ffff880118e22800 7 -> 8
[ 264.832100] ceph: mdsc con_get ffff880118e22800 ok (8)
[ 264.832104] ceph: add_cap_releases ffff880118e22800 mds0 extra 680
[ 264.832106] ceph: send_cap_releases mds0
[ 264.832109] ceph: mdsc put_session ffff880118e22800 8 -> 7
[ 264.832166] ceph: mdsc con_put ffff880118e22800 (6)
[ 264.832168] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 264.832744] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 264.832749] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 264.832797] ceph: mdsc con_put ffff880118e22800 (6)
[ 264.832800] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 264.832806] ceph: mdsc get_session ffff880118e22800 6 -> 7
[ 264.832808] ceph: mdsc con_get ffff880118e22800 ok (7)
[ 264.832813] ceph: mdsc con_put ffff880118e22800 (6)
[ 264.832815] ceph: mdsc put_session ffff880118e22800 7 -> 6
[ 264.832820] ceph: handle_session mds0 renewcaps ffff880118e22800 state open seq 13
[ 264.832823] ceph: renewed_caps mds0 ttl now 4294973504, was fresh, now stale
[ 264.832832] ceph: mdsc con_put ffff880118e22800 (5)
[ 264.832834] ceph: mdsc put_session ffff880118e22800 6 -> 5

Zheng Yan wrote:

looks like client's fault. try following command on client.5898 and upload debug.txt:

  1. echo module ceph +p >/sys/kernel/debug/dynamic_debug/control
  2. dmesg -c > /dev/null
  3. cat data/owncloud.log
    ctrl^c
  4. ls -l data/owncloud.log
    ctrl^c
  5. dmesg > debug.txt
Actions
Copy link
 #3

Updated by Zheng Yan almost 11 years ago

ceph: check_caps ffff880117288848 file_want pFscr used p dirty - flushing - issued pAsLsXsFcb revoking - retain pAsxLsxXsxFsxcrwbl NODELAY

Client has released the caps, but the MDS thinks it hasn't. No idea what was wrong, but restarting the MDS should solve your issue.
If you enabled mds logging from the beginning, please grep 'inode 10000000072' from the mds log and upload the result.

Actions
Copy link
 #4

Updated by joe huang almost 11 years ago

I tried restart all ceph services by issuing # /etc/init.d/ceph -a restart but didn't solve the problem. However I did this again and it worked. But I didn't see any msg by grep 'inode 10000000072' from the mds log.

Actions
Copy link
 #5

Updated by Anonymous almost 11 years ago

  • Priority changed from Urgent to High
Actions
Copy link
 #6

Updated by Sage Weil over 10 years ago

  • Status changed from New to Can't reproduce
Actions
Copy link
 #7

Updated by Greg Farnum almost 8 years ago

  • Component(FS) libcephfs added
Actions
Copy link

Also available in: Atom PDF