Ceph » CephFS

2018-08-05T10:51:10.004 INFO:tasks.workunit:Running workunit fs/misc/multiple_rsync.sh...
2018-08-05T10:51:10.005 INFO:teuthology.orchestra.run.smithi182:Running (workunit test fs/misc/multiple_rsync.sh): 'mkdir -p -- /home/ubuntu/cephtest/mnt.0/client.0/tmp && cd -- /home/ubuntu/cephtest/mnt.0/client.0/tmp && CEPH_CLI_TEST_DUP_COMMAND=1 CEPH_REF=wip-pdonnell-testing-20180804.001849 TESTDIR="/home/ubuntu/cephtest" CEPH_ARGS="--cluster ceph" CEPH_ID="0" PATH=$PATH:/usr/sbin CEPH_BASE=/home/ubuntu/cephtest/clone.client.0 CEPH_ROOT=/home/ubuntu/cephtest/clone.client.0 adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 6h /home/ubuntu/cephtest/clone.client.0/qa/workunits/fs/misc/multiple_rsync.sh'
2018-08-05T10:51:10.202 INFO:tasks.workunit.client.0.smithi182.stderr:+ export PAYLOAD=/tmp/multiple_rsync_payload.221736
2018-08-05T10:51:10.202 INFO:tasks.workunit.client.0.smithi182.stderr:+ PAYLOAD=/tmp/multiple_rsync_payload.221736
2018-08-05T10:51:10.203 INFO:tasks.workunit.client.0.smithi182.stderr:+ sudo cp -r /usr/lib/ /tmp/multiple_rsync_payload.221736
2018-08-05T10:51:14.658 INFO:tasks.workunit.client.0.smithi182.stderr:+ set -e
2018-08-05T10:51:14.658 INFO:tasks.workunit.client.0.smithi182.stderr:+ sudo rsync -av /tmp/multiple_rsync_payload.221736 payload.1
...
2018-08-05T10:59:59.478 INFO:tasks.workunit.client.1.smithi182.stderr:rsync: stat "/home/ubuntu/cephtest/mnt.1/client.1/tmp/payload.1/multiple_rsync_payload.208054/modules/3.10.0-862.9.1.el7.x86_64/kernel/drivers/scsi/bnx2i/.bnx2i.ko.xz.s5YUu8" failed: No such file or directory (2)
2018-08-05T10:59:59.478 INFO:tasks.workunit.client.1.smithi182.stderr:rsync: rename "/home/ubuntu/cephtest/mnt.1/client.1/tmp/payload.1/multiple_rsync_payload.208054/modules/3.10.0-862.9.1.el7.x86_64/kernel/drivers/scsi/bnx2i/.bnx2i.ko.xz.s5YUu8" -> "multiple_rsync_payload.208054/modules/3.10.0-862.9.1.el7.x86_64/kernel/drivers/scsi/bnx2i/bnx2i.ko.xz": No such file or directory (2)
...
2018-08-05T11:07:20.162 INFO:tasks.ceph.mds.b.smithi082.stderr:2018-08-05 11:07:20.171 7fee0af74700 -1 received  signal: Hangup from killall ceph-mds -1  (PID: 30089) UID: 0
2018-08-05T11:07:20.162 INFO:tasks.ceph.mds.c.smithi082.stderr:2018-08-05 11:07:20.171 7fbd861ab700 -1 received  signal: Hangup from killall ceph-mds -1  (PID: 30089) UID: 0
2018-08-05T11:07:20.163 INFO:tasks.ceph.mds.d.smithi082.stderr:2018-08-05 11:07:20.171 7faf21ab1700 -1 received  signal: Hangup from killall ceph-mds -1  (PID: 30089) UID: 0
2018-08-05T11:07:20.163 INFO:tasks.ceph.mds.a.smithi082.stderr:2018-08-05 11:07:20.171 7fb3b55af700 -1 received  signal: Hangup from killall ceph-mds -1  (PID: 30089) UID: 0
2018-08-05T11:10:12.646 INFO:tasks.workunit.client.0.smithi182.stderr:+ sudo rsync -av /tmp/multiple_rsync_payload.221736 payload.2
2018-08-05T11:10:29.073 INFO:tasks.workunit.client.1.smithi182.stderr:rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1052) [sender=3.0.9]
2018-08-05T11:10:29.079 INFO:tasks.workunit:Stopping ['fs/misc'] on client.1...
2018-08-05T11:10:29.080 INFO:teuthology.orchestra.run.smithi182:Running: 'rm -rf -- /home/ubuntu/cephtest/workunits.list.client.1 /home/ubuntu/cephtest/clone.client.1'
2018-08-05T11:10:29.560 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/run_tasks.py", line 86, in run_tasks
    manager = run_one_task(taskname, ctx=ctx, config=config)
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/run_tasks.py", line 65, in run_one_task
    return task(**kwargs)
  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-pdonnell-testing-20180804.001849/qa/tasks/workunit.py", line 206, in task
    cleanup=cleanup)
  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-pdonnell-testing-20180804.001849/qa/tasks/workunit.py", line 356, in _spawn_on_all_clients
    timeout=timeout)
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/parallel.py", line 85, in __exit__
    for result in self:
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/parallel.py", line 99, in next
    resurrect_traceback(result)
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/parallel.py", line 22, in capture_traceback
    return func(*args, **kwargs)
  File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-pdonnell-testing-20180804.001849/qa/tasks/workunit.py", line 479, in _run_tests
    label="workunit test {workunit}".format(workunit=workunit)
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/orchestra/remote.py", line 193, in run
    r = self._runner(client=self.ssh, name=self.shortname, **kwargs)
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/orchestra/run.py", line 423, in run
    r.wait()
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/orchestra/run.py", line 155, in wait
    self._raise_for_status()
  File "/home/teuthworker/src/git.ceph.com_git_teuthology_master/teuthology/orchestra/run.py", line 177, in _raise_for_status
    node=self.hostname, label=self.label
CommandFailedError: Command failed (workunit test fs/misc/multiple_rsync.sh) on smithi182 with status 23: 'mkdir -p -- /home/ubuntu/cephtest/mnt.1/client.1/tmp && cd -- /home/ubuntu/cephtest/mnt.1/client.1/tmp && CEPH_CLI_TEST_DUP_COMMAND=1 CEPH_REF=wip-pdonnell-testing-20180804.001849 TESTDIR="/home/ubuntu/cephtest" CEPH_ARGS="--cluster ceph" CEPH_ID="1" PATH=$PATH:/usr/sbin CEPH_BASE=/home/ubuntu/cephtest/clone.client.1 CEPH_ROOT=/home/ubuntu/cephtest/clone.client.1 adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 6h /home/ubuntu/cephtest/clone.client.1/qa/workunits/fs/misc/multiple_rsync.sh'

Seems related to migration:

2018-08-05 10:59:40.020 7fe892ffd700  5 client.4438 handle_cap_import ino 0x40000001c81 mseq 1 IMPORT from mds.4
2018-08-05 10:59:40.020 7fe892ffd700 10 client.4438 update_snap_trace len 48
2018-08-05 10:59:40.020 7fe892ffd700 20 client.4438 get_snap_realm 0x1 0x7fe88c00a890 9728 -> 9729
2018-08-05 10:59:40.020 7fe892ffd700 10 client.4438 update_snap_trace snaprealm(0x1 nref=9729 c=0 seq=1 parent=0x0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
2018-08-05 10:59:40.020 7fe892ffd700 10 client.4438 add_update_cap issued pAsxLsXsxFsxcrwb -> pAsxLsXsxFsxcrwb from mds.4 on 0x40000001c81.head(faked_ino=0 ref=3 ll_ref=1 cap_refs={4=0,1024=0,4096=0,8192=0} open={3=0} mode=100600 size=26408/4194304 nlink=1 btime=2018-08-05 10:59:39.473058 mtime=2018-08-05 10:59:39.819958 ctime=2018-08-05 10:59:39.815701 caps=pAsxLsXsxFsxcrwb(4=pAsxLsXsxFsxcrwb) dirty_caps=AxFw objectset[0x40000001c81 ts 0/0 objects 1 dirty_or_tx 0] parents=0x50000002fb4.head[".bnx2i.ko.xz.s5YUu8"] 0x7fe88c1c2d10)
...
2018-08-05 10:59:40.177 7fe892ffd700  1 -- 172.21.15.182:57960/477284704 <== mds.4 172.21.15.162:6818/3776954104 87413 ==== client_reply(???:232439 = 0 (0) Success) v1 ==== 692+0+0 (1849136875 0 0) 0x7fe8a400da90 con 0x7fe88d122040
2018-08-05 10:59:40.177 7fe892ffd700 20 client.4438 handle_client_reply got a reply. Safe:1 tid 232439
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438 insert_trace from 2018-08-05 10:59:39.823366 mds.4 is_target=1 is_dentry=1
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438  features 0x3ffddff8ffa4ffff
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438 update_snap_trace len 48
2018-08-05 10:59:40.177 7fe892ffd700 20 client.4438 get_snap_realm 0x1 0x7fe88c00a890 9728 -> 9729
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438 update_snap_trace snaprealm(0x1 nref=9729 c=0 seq=1 parent=0x0 my_snaps=[] cached_snapc=1=[]) seq 1 <= 1 and same parent, SKIPPING
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438  hrm  is_target=1 is_dentry=1
2018-08-05 10:59:40.177 7fe892ffd700 12 client.4438 add_update_inode had 0x50000002fb4.head(faked_ino=0 ref=3 ll_ref=7 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=0.000000 mtime=2018-08-05 10:49:59.000000 ctime=2018-08-05 10:59:25.565316 caps=pAsLsXs(3=pAsLsXs) COMPLETE parents=0x200000037c5.head["bnx2i"] 0x7fe88d1cf430) caps pAsLsXsFs
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438 update_inode_file_time 0x50000002fb4.head(faked_ino=0 ref=3 ll_ref=7 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=0.000000 mtime=2018-08-05 10:49:59.000000 ctime=2018-08-05 10:59:25.565316 caps=pAsLsXs(3=pAsLsXs) COMPLETE parents=0x200000037c5.head["bnx2i"] 0x7fe88d1cf430) pAsLsXs ctime 2018-08-05 10:59:25.565316 mtime 2018-08-05 10:49:59.000000
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438  clearing (I_COMPLETE|I_DIR_ORDERED) on 0x50000002fb4.head(faked_ino=0 ref=3 ll_ref=7 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=0.000000 mtime=2018-08-05 10:49:59.000000 ctime=2018-08-05 10:59:25.565316 caps=pAsLsXs(3=pAsLsXs,4=-) COMPLETE parents=0x200000037c5.head["bnx2i"] 0x7fe88d1cf430)
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438 add_update_cap issued - -> pAsLsXsFs from mds.4 on 0x50000002fb4.head(faked_ino=0 ref=3 ll_ref=7 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=0.000000 mtime=2018-08-05 10:49:59.000000 ctime=2018-08-05 10:59:25.565316 caps=pAsLsXsFs(3=pAsLsXs,4=pAsLsXsFs) parents=0x200000037c5.head["bnx2i"] 0x7fe88d1cf430)
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438  marking (I_COMPLETE|I_DIR_ORDERED) on empty dir 0x50000002fb4.head(faked_ino=0 ref=3 ll_ref=7 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=0.000000 mtime=2018-08-05 10:49:59.000000 ctime=2018-08-05 10:59:25.565316 caps=pAsLsXsFs(3=pAsLsXs,4=pAsLsXsFs) parents=0x200000037c5.head["bnx2i"] 0x7fe88d1cf430)
2018-08-05 10:59:40.177 7fe892ffd700 10 client.4438  dir is open on empty dir 0x50000002fb4 with 1 entries, marking all dentries null
2018-08-05 10:59:40.177 7fe892ffd700 15 inode.get on 0x7fe88c1c2d10 0x40000001c81.head now 4
018-08-05 10:59:40.177 7fe892ffd700 15 client.4438 unlink dir 0x7fe88d1cf430 '.bnx2i.ko.xz.s5YUu8' dn 0x7fe84c8af9e0 inode 0x7fe88c1c2d10
...
2018-08-05 10:59:40.178 7fe847fff700  3 client.4438 may_lookup 0x7fe88d1cf430 = 0
2018-08-05 10:59:40.178 7fe847fff700 20 client.4438 _lookup have dn .bnx2i.ko.xz.s5YUu8 mds.-1 ttl 2018-08-05 11:00:09.646374 seq 14046
2018-08-05 10:59:40.178 7fe847fff700 10 client.4438 _lookup concluded ENOENT locally for 0x50000002fb4.head(faked_ino=0 ref=3 ll_ref=9 cap_refs={} open={} mode=40755 size=0/0 nlink=1 btime=0.000000 mtime=2018-08-05 10:49:59.000000 ctime=2018-08-05 10:59:25.565316 caps=pAsLsXsFs(3=pAsLsXs,4=pAsLsXsFs) COMPLETE parents=0x200000037c5.head["bnx2i"] 0x7fe88d1cf430) dn '.bnx2i.ko.xz.s5YUu8'
2018-08-05 10:59:40.178 7fe847fff700  3 client.4438 ll_lookup 0x50000002fb4.head .bnx2i.ko.xz.s5YUu8 -> -2 (0)

May be caused by: https://github.com/ceph/ceph/pull/23088/files