Ceph » CephFS

We have a symlink in our filesystem that we cannot remove.

Ceph MDS version: 10.2.2
Kernel version: 4.4.0-34-generic #53~14.04.1-Ubuntu, 4.4.0-24-generic #43~14.04.1-Ubuntu (running ubuntu trusty with xenial backport kernels)
ceph-fuse version: 10.2.2-1trusty

cephfs (kernel):

1. ls -al save/
   ls: cannot access save/stdout.json: Invalid argument
   total 0
   drwxrwxr-x 1 XYZ students 0 Sep 5 14:33 .
   drwxr-xr-x 1 root root 0 Sep 5 14:34 ..
   l????????? ? ? ? ? ? stdout.json

kernel log:

[Mon Sep 5 14:46:39 2016] ceph: fill_inode badness on ffff88025f049f88
[Mon Sep 5 14:46:39 2016] ------------[ cut here ]------------
[Mon Sep 5 14:46:39 2016] WARNING: CPU: 3 PID: 32673 at /build/linux-lts-xenial-D8Bcmp/linux-lts-xenial-4.4.0/fs/ceph/inode.c:811 fill_inode.isra.16+0xb2a/0xc00 [ceph]()
[Mon Sep 5 14:46:39 2016] Modules linked in: ufs qnx4 hfsplus hfs minix ntfs msdos jfs xfs ceph libceph cts 8021q garp mrp stp llc openvswitch nf_defrag_ipv6 nf_conntrack libcrc32c ipmi_ssif intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper serio_raw cryptd sb_edac lpc_ich hpilo edac_core wmi 8250_fintek shpchp ipmi_si ipmi_msghandler ioatdma acpi_power_meter mac_hid parport_pc ppdev rpcsec_gss_krb5 nfsd auth_rpcgss nfs_acl nfs lp lockd grace sunrpc fscache parport btrfs xor raid6_pq ixgbe dca vxlan psmouse ip6_udp_tunnel tg3 udp_tunnel ptp hpsa pps_core scsi_transport_sas mdio fjes
[Mon Sep 5 14:46:39 2016] CPU: 3 PID: 32673 Comm: kworker/3:2 Tainted: G W 4.4.0-24-generic #43~14.04.1-Ubuntu
[Mon Sep 5 14:46:39 2016] Hardware name: HP ProLiant DL380 Gen9, BIOS P89 07/20/2015
[Mon Sep 5 14:46:39 2016] Workqueue: ceph-msgr ceph_con_workfn [libceph]
[Mon Sep 5 14:46:39 2016] 0000000000000000 ffff881fb8943a50 ffffffff813ce10c 0000000000000000
[Mon Sep 5 14:46:39 2016] ffffffffc05ff3b0 ffff881fb8943a88 ffffffff8107d736 00000000ffffffea
[Mon Sep 5 14:46:39 2016] 0000000000000000 0000000000000000 ffff88025f04a528 ffff881febe4d931
[Mon Sep 5 14:46:39 2016] Call Trace:
[Mon Sep 5 14:46:39 2016] [<ffffffff813ce10c>] dump_stack+0x63/0x87
[Mon Sep 5 14:46:39 2016] [<ffffffff8107d736>] warn_slowpath_common+0x86/0xc0
[Mon Sep 5 14:46:39 2016] [<ffffffff8107d82a>] warn_slowpath_null+0x1a/0x20
[Mon Sep 5 14:46:39 2016] [<ffffffffc05d799a>] fill_inode.isra.16+0xb2a/0xc00 [ceph]
[Mon Sep 5 14:46:39 2016] [<ffffffff81216275>] ? inode_init_always+0x105/0x1b0
[Mon Sep 5 14:46:39 2016] [<ffffffffc05d7b87>] ceph_fill_trace+0x117/0x970 [ceph]
[Mon Sep 5 14:46:39 2016] [<ffffffffc05f5d19>] handle_reply+0x429/0xca0 [ceph]
[Mon Sep 5 14:46:39 2016] [<ffffffffc05f816e>] dispatch+0xae/0xaf0 [ceph]
[Mon Sep 5 14:46:39 2016] [<ffffffffc059cad3>] try_read+0x443/0x1120 [libceph]
[Mon Sep 5 14:46:39 2016] [<ffffffff810963a0>] ? try_to_grab_pending+0xb0/0x150
[Mon Sep 5 14:46:39 2016] [<ffffffff810b2f75>] ? put_prev_entity+0x35/0x670
[Mon Sep 5 14:46:39 2016] [<ffffffff8102c666>] ? __switch_to+0x1d6/0x570
[Mon Sep 5 14:46:39 2016] [<ffffffffc059d862>] ceph_con_workfn+0xb2/0x5d0 [libceph]
[Mon Sep 5 14:46:39 2016] [<ffffffff81095820>] process_one_work+0x150/0x3f0
[Mon Sep 5 14:46:39 2016] [<ffffffff81095f9a>] worker_thread+0x11a/0x470
[Mon Sep 5 14:46:39 2016] [<ffffffff817eb829>] ? __schedule+0x359/0x980
[Mon Sep 5 14:46:39 2016] [<ffffffff81095e80>] ? rescuer_thread+0x310/0x310
[Mon Sep 5 14:46:39 2016] [<ffffffff8109b6d9>] kthread+0xc9/0xe0
[Mon Sep 5 14:46:39 2016] [<ffffffff810804fb>] ? do_exit+0x65b/0xae0
[Mon Sep 5 14:46:39 2016] [<ffffffff8109b610>] ? kthread_park+0x60/0x60
[Mon Sep 5 14:46:39 2016] [<ffffffff817efa4f>] ret_from_fork+0x3f/0x70
[Mon Sep 5 14:46:39 2016] [<ffffffff8109b610>] ? kthread_park+0x60/0x60
[Mon Sep 5 14:46:39 2016] ---[ end trace 03e9b82c2c95e5ab ]---

ceph-fuse:

1. ls -al save/
   total 1
   drwxrwxr-x 1 XYZ students 0 Sep 5 14:33 .
   drwxr-xr-x 1 root root 0 Sep 5 14:34 ..
   lrwxrwxrwx 1 XYZ students 0 Sep 5 13:20 stdout.json -> /dev/stdout

(the file is already moved to a save location)

We had a number of messages in the MDS logs over the weekend:

2016-09-03 07:41:17.419313 7fc7fffff700 0 log_channel(cluster) log [WRN] : slow request 122911.110094 seconds old, received at 2016-09-01 21:32:46.309124: client_request(client.3810003:4637318 lo
okup #100072025ce/BlastParser.groovy 2016-09-01 21:32:46.307463) currently failed to rdlock, waiting

and

2016-09-03 14:19:25.750649 7fc803468700 0 log_channel(cluster) log [WRN] : client.4031546 does not advance its oldest_client_tid (3341229), 100002 completed requests recorded in session

Finally today there was a problem with the session map, resulting in the first MDS restart:

2016-09-05 13:18:12.151833 7fc7fdffb700 -1 mds/SessionMap.cc: In function 'virtual void C_IO_SM_Save::finish(int)' thread 7fc7fdffb700 time 2016-09-05 13:18:11.755592
mds/SessionMap.cc: 319: FAILED assert(r == 0)

ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0x7fc80b032915]
 2: (()+0x45efc1) [0x7fc80ae96fc1]
 3: (MDSIOContextBase::complete(int)+0xa4) [0x7fc80ae98334]
 4: (Finisher::finisher_thread_entry()+0x27d) [0x7fc80af61e9d]
 5: (()+0x7dc5) [0x7fc809bf4dc5]
 6: (clone()+0x6d) [0x7fc8086bfced]

I don't know when the symlink was created, but the next crash semms to be related to it:

5> 2016-09-05 13:47:29.823859 7f3ad7aa6700  5 - op tracker -- seq: 449313, time: 2016-09-05 13:47:29.823859, event: killing request, op: client_request(client.4010513:1442135 create #10006da65c1/stdout.json 2016-09-05 13:22:09.431415)
    4> 2016-09-05 13:47:29.823912 7f3ad07fe700  5 mds.0.log _submit_thread 4425743152308~230 : ESession client.4010513 134.176.31.195:0/3840219 close cmapv 154523073 (630 inos, v12770540)
    -3> 2016-09-05 13:47:29.823941 7f3ad7aa6700  5 - op tracker -- seq: 449313, time: 2016-09-05 13:47:29.823941, event: cleaned up request, op: client_request(client.4010513:1442135 create #10006da65c1/stdout.json 2016-09-05 13:22:09.431415)
    2> 2016-09-05 13:47:29.823976 7f3ad07fe700  1 - 192.168.6.129:6801/43283 --> 192.168.6.134:6816/31271 -- osd_op(mds.0.197986:376340 8.3ee7dd50 300.001019cb [write 1651892~250 [fadvise_dontneed]] snapc 0=[] ondisk+write+known_if_redirected+full_force e421445) v7 -- ?+0 0x7f3b217bb440 con 0x7f3ae9da6100
    1> 2016-09-05 13:47:29.826297 7f3ac33ff700  1 - 192.168.6.129:6801/43283 <== osd.88 192.168.6.134:6816/31271 2584 ==== osd_op_reply(376340 300.001019cb [write 1651892~250 [fadvise_dontneed]] v421445'361223 uv361223 ondisk = 0) v7 ==== 132+0+0 (3052469259 0 0) 0x7f3b2654c580 con 0x7f3ae9da6100
     0> 2016-09-05 13:47:29.856106 7f3ad23fb700 1 mds/Locker.cc: In function 'bool Locker::check_inode_max_size(CInode*, bool, bool, uint64_t, bool, uint64_t, utime_t)' thread 7f3ad23fb700 time 2016-09-05 13:47:29.853913
mds/Locker.cc: 2190: FAILED assert(in>is_file())

ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0x7f3adf6a0915]
 2: (Locker::check_inode_max_size(CInode*, bool, bool, unsigned long, bool, unsigned long, utime_t)+0x15fd) [0x7f3adf43bafd]
 3: (Locker::remove_client_cap(CInode*, client_t)+0xb1) [0x7f3adf43c051]
 4: (Server::_session_logged(Session*, unsigned long, bool, unsigned long, interval_set<inodeno_t>&, unsigned long)+0x515) [0x7f3adf2f5cc5]
 5: (C_MDS_session_finish::finish(int)+0x35) [0x7f3adf34d855]
 6: (MDSInternalContextBase::complete(int)+0x1eb) [0x7f3adf50600b]
 7: (C_MDL_Flushed::finish(int)+0x13) [0x7f3adf51add3]
 8: (MDSIOContextBase::complete(int)+0xa4) [0x7f3adf506334]
 9: (Finisher::finisher_thread_entry()+0x216) [0x7f3adf5cfe36]
 10: (()+0x7dc5) [0x7f3ade262dc5]
 11: (clone()+0x6d) [0x7f3adcd2dced]

Further attempts to delete the file results in further MDS crashes. I know how to remove the symlink (removing the omap entry), but
I'll keep it around in case you want more debug output to track down the root of the problem.

Ceph MDS log available on request.