Ceph » CephFS

2020-03-07 05:20:17,820.820 INFO:__main__:Ready to start LocalFuseMount...
2020-03-07 05:20:17,820.820 INFO:tasks.cephfs.mount:Setting the 'ceph-ns--tmp-tmpR3YAOm-mnt.1' netns for '/tmp/tmpR3YAOm/mnt.1'
2020-03-07 05:20:17,821.821 INFO:__main__:Running ['ip', 'addr']
2020-03-07 05:20:17,832.832 INFO:__main__:Running ['ip', 'netns', 'list']
2020-03-07 05:20:17,840.840 INFO:__main__:Running ['ip', 'netns', 'list-id']
2020-03-07 05:20:17,846.846 INFO:__main__:Running ['ip', 'netns', 'list-id']
2020-03-07 05:20:17,850.850 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns add ceph-ns--tmp-tmpR3YAOm-mnt.1']
2020-03-07 05:20:17,904.904 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns set ceph-ns--tmp-tmpR3YAOm-mnt.1 1']
2020-03-07 05:20:17,966.966 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns exec ceph-ns--tmp-tmpR3YAOm-mnt.0 ip addr']
2020-03-07 05:20:18,026.026 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns exec ceph-ns--tmp-tmpR3YAOm-mnt.0 ip addr']
2020-03-07 05:20:18,091.091 INFO:tasks.cephfs.mount:Setuping the netns 'ceph-ns--tmp-tmpR3YAOm-mnt.1' with 192.168.0.2/16
2020-03-07 05:20:18,092.092 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link add veth0 netns ceph-ns--tmp-tmpR3YAOm-mnt.1 type veth peer name brx.1']
2020-03-07 05:20:18,160.160 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns exec ceph-ns--tmp-tmpR3YAOm-mnt.1 ip addr add 192.168.0.2/16 brd 192.168.255.255 dev veth0']
2020-03-07 05:20:18,216.216 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns exec ceph-ns--tmp-tmpR3YAOm-mnt.1 ip link set veth0 up']
2020-03-07 05:20:18,276.276 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns exec ceph-ns--tmp-tmpR3YAOm-mnt.1 ip link set lo up']
2020-03-07 05:20:18,336.336 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns exec ceph-ns--tmp-tmpR3YAOm-mnt.1 ip route add default via 192.168.255.254']
2020-03-07 05:20:18,403.403 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link set brx.1 up']
2020-03-07 05:20:18,463.463 INFO:__main__:Running ['sudo', 'bash', '-c', 'brctl addif ceph-brx brx.1']
2020-03-07 05:20:18,520.520 INFO:__main__:Running ['mkdir', '-p', '/tmp/tmpR3YAOm/mnt.1']
2020-03-07 05:20:18,530.530 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
mount: /sys/fs/fuse/connections is already mounted or /sys/fs/fuse/connections busy
2020-03-07 05:20:18,538.538 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2020-03-07 05:20:18,543.543 INFO:__main__:Pre-mount connections: [43]
2020-03-07 05:20:18,543.543 INFO:__main__:Running ['nsenter', '--net=/var/run/netns/ceph-ns--tmp-tmpR3YAOm-mnt.1', './bin/ceph-fuse', '-f', '--name', 'client.1', '/tmp/tmpR3YAOm/mnt.1']
2020-03-07 05:20:18,547.547 INFO:__main__:Mounting client.1 with pid 17505
2020-03-07 05:20:18,547.547 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
mount: /sys/fs/fuse/connections is already mounted or /sys/fs/fuse/connections busy
2020-03-07 05:20:18,558.558 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2020-03-07 05:20:19,567.567 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
mount: /sys/fs/fuse/connections is already mounted or /sys/fs/fuse/connections busy
2020-03-07 05:20:19,584.584 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2020-03-07 05:20:19,595.595 INFO:__main__:Post-mount connections: [43, 46]
2020-03-07 05:20:19,596.596 INFO:__main__:I think my launching pid was 17505
2020-03-07 05:20:19,597.597 INFO:__main__:Running ['sudo', 'python3', '-c', '\nimport glob\nimport re\nimport os\nimport subprocess\n\ndef find_socket(client_name):\n        asok_path = "/tmp/ceph-asok.3P2UZQ//client.1.17505.asok"\n        files = glob.glob(asok_path)\n\n        # Given a non-glob path, it better be there\n        if "*" not in asok_path:\n            assert(len(files) == 1)\n            return files[0]\n\n        for f in files:\n                pid = re.match(".*\\.(\\d+)\\.asok$", f).group(1)\n                if os.path.exists("/proc/{0}".format(pid)):\n                        return f\n        raise RuntimeError("Client socket {0} not found".format(client_name))\n\nprint(find_socket("client.1"))\n']
2020-03-07 05:20:19,703.703 INFO:tasks.cephfs.fuse_mount:Found client admin socket at /tmp/ceph-asok.3P2UZQ//client.1.17505.asok
2020-03-07 05:20:19,705.705 INFO:__main__:Running ['sudo', './bin/ceph', '--admin-daemon', '/tmp/ceph-asok.3P2UZQ//client.1.17505.asok', 'status']
2020-03-07 05:20:19,939.939 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpR3YAOm/mnt.1']
2020-03-07 05:20:19,953.953 INFO:tasks.cephfs.fuse_mount:ceph-fuse is mounted on /tmp/tmpR3YAOm/mnt.1
2020-03-07 05:20:19,953.953 INFO:__main__:Running ['sudo', 'chmod', '1777', '/tmp/tmpR3YAOm/mnt.1']
2020-03-07 05:20:20,010.010 INFO:__main__:Running ['./bin/ceph', 'daemon', 'mds.a', 'config', 'get', 'mds_reconnect_timeout']
2020-03-07 05:20:20,290.290 INFO:tasks.cephfs.filesystem:_json_asok output: {
    "mds_reconnect_timeout": "45.000000" 
}

2020-03-07 05:20:20,291.291 INFO:__main__:Running ['./bin/ceph', 'daemon', 'mds.a', 'config', 'get', 'ms_max_backoff']
2020-03-07 05:20:20,549.549 INFO:tasks.cephfs.filesystem:_json_asok output: {
    "ms_max_backoff": "15.000000" 
}

2020-03-07 05:20:20,550.550 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2020-03-07 05:20:21,090.090 INFO:__main__:Running ['./bin/ceph', 'daemon', 'mds.a', 'config', 'set', 'mds_defer_session_stale', 'false']
2020-03-07 05:20:21,349.349 INFO:tasks.cephfs.filesystem:_json_asok output: {
    "success": "mds_defer_session_stale = 'false' (not observed, change may require restart) " 
}

2020-03-07 05:20:21,350.350 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2020-03-07 05:20:21,879.879 INFO:__main__:I think my launching pid was 17325
2020-03-07 05:20:21,881.881 INFO:__main__:Running ['sudo', 'python3', '-c', '\nimport glob\nimport re\nimport os\nimport subprocess\n\ndef find_socket(client_name):\n        asok_path = "/tmp/ceph-asok.3P2UZQ//client.0.17325.asok"\n        files = glob.glob(asok_path)\n\n        # Given a non-glob path, it better be there\n        if "*" not in asok_path:\n            assert(len(files) == 1)\n            return files[0]\n\n        for f in files:\n                pid = re.match(".*\\.(\\d+)\\.asok$", f).group(1)\n                if os.path.exists("/proc/{0}".format(pid)):\n                        return f\n        raise RuntimeError("Client socket {0} not found".format(client_name))\n\nprint(find_socket("client.0"))\n']
2020-03-07 05:20:21,981.981 INFO:tasks.cephfs.fuse_mount:Found client admin socket at /tmp/ceph-asok.3P2UZQ//client.0.17325.asok
2020-03-07 05:20:21,982.982 INFO:__main__:Running ['sudo', './bin/ceph', '--admin-daemon', '/tmp/ceph-asok.3P2UZQ//client.0.17325.asok', 'mds_sessions']
2020-03-07 05:20:22,194.194 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2020-03-07 05:20:22,731.731 INFO:__main__:Running ['./bin/ceph', 'daemon', 'mds.a', 'session', 'config', '82784', '120']
2020-03-07 05:20:22,986.986 INFO:tasks.cephfs.filesystem:_json_asok output: ERROR: (22) Invalid argument
Invalid config option: 120

2020-03-07 05:20:22,991.991 INFO:__main__:test_config_session_timeout (tasks.cephfs.test_client_recovery.TestClientRecovery) ... ERROR
2020-03-07 05:20:22,991.991 INFO:tasks.cephfs.fuse_mount:Running fusermount -u on local...
2020-03-07 05:20:22,992.992 INFO:__main__:Running ['sudo', 'fusermount', '-u', '/tmp/tmpR3YAOm/mnt.0']
2020-03-07 05:20:23,059.059 INFO:__main__:kill 
2020-03-07 05:20:23,060.060 INFO:__main__:kill: killing pid 17325 (['nsenter', '--net=/var/run/netns/ceph-ns--tmp-tmpR3YAOm-mnt.0', './bin/ceph-fuse', '-f', '--name', 'client.0', '/tmp/tmpR3YAOm/mnt.0'])
2020-03-07T05:20:15.629-0500 7fc894ad5f80 -1 WARNING: all dangerous and experimental features are enabled.
2020-03-07T05:20:15.643-0500 7fc894ad5f80 -1 WARNING: all dangerous and experimental features are enabled.
2020-03-07T05:20:15.654-0500 7fc894ad5f80 -1 WARNING: all dangerous and experimental features are enabled.
ceph-fuse[17325]: starting ceph client
2020-03-07T05:20:15.657-0500 7fc894ad5f80 -1 init, newargv = 0x558b9edec720 newargc=7
ceph-fuse[17325]: starting fuse
ceph-fuse[17325]: fuse finished with error 0 and tester_r 0
2020-03-07 05:20:23,065.065 INFO:tasks.cephfs.mount:Cleaning the 'ceph-ns--tmp-tmpR3YAOm-mnt.0' netns for '/tmp/tmpR3YAOm/mnt.0'
2020-03-07 05:20:23,065.065 INFO:tasks.cephfs.mount:Removing the netns 'ceph-ns--tmp-tmpR3YAOm-mnt.0'
2020-03-07 05:20:23,065.065 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link set brx.0 down']
2020-03-07 05:20:23,132.132 INFO:__main__:Running ['sudo', 'bash', '-c', 'brctl delif ceph-brx brx.0']
2020-03-07 05:20:23,203.203 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link delete brx.0']
2020-03-07 05:20:23,285.285 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns delete ceph-ns--tmp-tmpR3YAOm-mnt.0']
2020-03-07 05:20:23,350.350 INFO:__main__:Running ['ip', 'addr']
2020-03-07 05:20:23,362.362 INFO:__main__:Running ['brctl', 'show', 'ceph-brx']
2020-03-07 05:20:23,370.370 INFO:__main__:Running ['rm', '-rf', '/tmp/tmpR3YAOm/mnt.0']
2020-03-07 05:20:23,376.376 INFO:tasks.cephfs.fuse_mount:Running fusermount -u on local...
2020-03-07 05:20:23,377.377 INFO:__main__:Running ['sudo', 'fusermount', '-u', '/tmp/tmpR3YAOm/mnt.1']
2020-03-07 05:20:23,422.422 INFO:__main__:kill 
2020-03-07 05:20:23,423.423 INFO:__main__:kill: killing pid 17505 (['nsenter', '--net=/var/run/netns/ceph-ns--tmp-tmpR3YAOm-mnt.1', './bin/ceph-fuse', '-f', '--name', 'client.1', '/tmp/tmpR3YAOm/mnt.1'])
2020-03-07T05:20:18.610-0500 7f0f0e690f80 -1 WARNING: all dangerous and experimental features are enabled.
2020-03-07T05:20:18.626-0500 7f0f0e690f80 -1 WARNING: all dangerous and experimental features are enabled.
2020-03-07T05:20:18.637-0500 7f0f0e690f80 -1 WARNING: all dangerous and experimental features are enabled.
2020-03-07T05:20:18.639-0500 7f0f0e690f80 -1 init, newargv = 0x55ef280cc720 newargc=7
ceph-fuse[17505]: starting ceph client
ceph-fuse[17505]: starting fuse
ceph-fuse[17505]: fuse finished with error 0 and tester_r 0
2020-03-07 05:20:23,427.427 INFO:tasks.cephfs.mount:Cleaning the 'ceph-ns--tmp-tmpR3YAOm-mnt.1' netns for '/tmp/tmpR3YAOm/mnt.1'
2020-03-07 05:20:23,427.427 INFO:tasks.cephfs.mount:Removing the netns 'ceph-ns--tmp-tmpR3YAOm-mnt.1'
2020-03-07 05:20:23,428.428 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link set brx.1 down']
2020-03-07 05:20:23,491.491 INFO:__main__:Running ['sudo', 'bash', '-c', 'brctl delif ceph-brx brx.1']
2020-03-07 05:20:23,557.557 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link delete brx.1']
2020-03-07 05:20:23,634.634 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip netns delete ceph-ns--tmp-tmpR3YAOm-mnt.1']
2020-03-07 05:20:23,694.694 INFO:__main__:Running ['ip', 'addr']
2020-03-07 05:20:23,707.707 INFO:__main__:Running ['brctl', 'show', 'ceph-brx']
2020-03-07 05:20:23,715.715 INFO:__main__:Running ['sudo', 'bash', '-c', 'ip link set ceph-brx down']
2020-03-07 05:20:23,773.773 INFO:__main__:Running ['sudo', 'bash', '-c', 'brctl delbr ceph-brx']
2020-03-07 05:20:23,852.852 INFO:tasks.cephfs.mount:Removing the 'ceph-brx'
2020-03-07 05:20:23,854.854 INFO:__main__:Running ['route']
2020-03-07 05:20:23,872.872 INFO:__main__:Running ['sudo', 'bash', '-c', 'iptables -D FORWARD -o eth0 -i ceph-brx -j ACCEPT']
2020-03-07 05:20:23,930.930 INFO:__main__:Running ['sudo', 'bash', '-c', 'iptables -D FORWARD -i eth0 -o ceph-brx -j ACCEPT']
2020-03-07 05:20:23,978.978 INFO:__main__:Running ['sudo', 'bash', '-c', 'iptables -t nat -D POSTROUTING -s 192.168.255.254/16 -o eth0 -j MASQUERADE']
2020-03-07 05:20:24,030.030 INFO:__main__:Running ['cat', '/tmp/python-ceph-brx']
2020-03-07 05:20:24,041.041 INFO:__main__:Running ['sudo', 'bash', '-c', 'echo 1 > /proc/sys/net/ipv4/ip_forward']
2020-03-07 05:20:24,106.106 INFO:__main__:Running ['rm', '-f', '/tmp/python-ceph-brx']
2020-03-07 05:20:24,118.118 INFO:__main__:Running ['rm', '-rf', '/tmp/tmpR3YAOm/mnt.1']
2020-03-07 05:20:24,126.126 INFO:__main__:Running ['./bin/ceph', 'log', 'Ended test tasks.cephfs.test_client_recovery.TestClientRecovery.test_config_session_timeout']
2020-03-07 05:20:24,862.862 INFO:__main__:Stopped test: test_config_session_timeout (tasks.cephfs.test_client_recovery.TestClientRecovery) in 33.101744s
2020-03-07 05:20:24,864.864 INFO:__main__:
2020-03-07 05:20:24,864.864 INFO:__main__:======================================================================
2020-03-07 05:20:24,864.864 INFO:__main__:ERROR: test_config_session_timeout (tasks.cephfs.test_client_recovery.TestClientRecovery)
2020-03-07 05:20:24,865.865 INFO:__main__:----------------------------------------------------------------------
2020-03-07 05:20:24,865.865 INFO:__main__:Traceback (most recent call last):
2020-03-07 05:20:24,865.865 INFO:__main__:  File "/data/ceph/qa/tasks/cephfs/test_client_recovery.py", line 620, in test_config_session_timeout
2020-03-07 05:20:24,866.866 INFO:__main__:    self.fs.mds_asok(['session', 'config', '%s' % mount_a_gid, 'timeout', '%s' % (session_timeout * 2)])
2020-03-07 05:20:24,866.866 INFO:__main__:  File "/data/ceph/qa/tasks/cephfs/filesystem.py", line 1001, in mds_asok
2020-03-07 05:20:24,866.866 INFO:__main__:    return self.json_asok(command, 'mds', mds_id, timeout=timeout)
2020-03-07 05:20:24,867.867 INFO:__main__:  File "/data/ceph/qa/tasks/cephfs/filesystem.py", line 227, in json_asok
2020-03-07 05:20:24,867.867 INFO:__main__:    return json.loads(response_data)
2020-03-07 05:20:24,867.867 INFO:__main__:  File "/usr/lib64/python2.7/json/__init__.py", line 338, in loads
2020-03-07 05:20:24,867.867 INFO:__main__:    return _default_decoder.decode(s)
2020-03-07 05:20:24,868.868 INFO:__main__:  File "/usr/lib64/python2.7/json/decoder.py", line 366, in decode
2020-03-07 05:20:24,868.868 INFO:__main__:    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2020-03-07 05:20:24,868.868 INFO:__main__:  File "/usr/lib64/python2.7/json/decoder.py", line 384, in raw_decode
2020-03-07 05:20:24,868.868 INFO:__main__:    raise ValueError("No JSON object could be decoded")
2020-03-07 05:20:24,869.869 INFO:__main__:ValueError: No JSON object could be decoded
2020-03-07 05:20:24,869.869 INFO:__main__:
2020-03-07 05:20:24,869.869 INFO:__main__:----------------------------------------------------------------------
2020-03-07 05:20:24,870.870 INFO:__main__:Ran 3 tests in 207.981s
2020-03-07 05:20:24,870.870 INFO:__main__:
2020-03-07 05:20:24,870.870 INFO:__main__:FAILED (errors=1)
2020-03-07 05:20:24,871.871 INFO:__main__:
2020-03-07 05:20:24,871.871 INFO:__main__:======================================================================
2020-03-07 05:20:24,871.871 INFO:__main__:ERROR: test_config_session_timeout (tasks.cephfs.test_client_recovery.TestClientRecovery)
2020-03-07 05:20:24,872.872 INFO:__main__:----------------------------------------------------------------------
2020-03-07 05:20:24,872.872 INFO:__main__:Traceback (most recent call last):
2020-03-07 05:20:24,872.872 INFO:__main__:  File "/data/ceph/qa/tasks/cephfs/test_client_recovery.py", line 620, in test_config_session_timeout
2020-03-07 05:20:24,872.872 INFO:__main__:    self.fs.mds_asok(['session', 'config', '%s' % mount_a_gid, 'timeout', '%s' % (session_timeout * 2)])
2020-03-07 05:20:24,873.873 INFO:__main__:  File "/data/ceph/qa/tasks/cephfs/filesystem.py", line 1001, in mds_asok
2020-03-07 05:20:24,873.873 INFO:__main__:    return self.json_asok(command, 'mds', mds_id, timeout=timeout)
2020-03-07 05:20:24,873.873 INFO:__main__:  File "/data/ceph/qa/tasks/cephfs/filesystem.py", line 227, in json_asok
2020-03-07 05:20:24,873.873 INFO:__main__:    return json.loads(response_data)
2020-03-07 05:20:24,874.874 INFO:__main__:  File "/usr/lib64/python2.7/json/__init__.py", line 338, in loads
2020-03-07 05:20:24,874.874 INFO:__main__:    return _default_decoder.decode(s)
2020-03-07 05:20:24,874.874 INFO:__main__:  File "/usr/lib64/python2.7/json/decoder.py", line 366, in decode
2020-03-07 05:20:24,874.874 INFO:__main__:    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2020-03-07 05:20:24,875.875 INFO:__main__:  File "/usr/lib64/python2.7/json/decoder.py", line 384, in raw_decode
2020-03-07 05:20:24,875.875 INFO:__main__:    raise ValueError("No JSON object could be decoded")
2020-03-07 05:20:24,875.875 INFO:__main__:ValueError: No JSON object could be decoded
2020-03-07 05:20:24,875.875 INFO:__main__: