Project

General

Profile

Bug #42252 ยป vstart_runner.log

Rishabh Dave, 11/19/2019 10:42 AM

 
2019-11-19T03:16:29.083 INFO:__main__:Executing modules: ['tasks.cephfs.test_volume_client.TestVolumeClient.test_21501']
2019-11-19T03:16:29.092 INFO:__main__:Loaded: [<unittest.suite.TestSuite tests=[<tasks.cephfs.test_volume_client.TestVolumeClient testMethod=test_21501>]>]
2019-11-19T03:16:29.092 INFO:__main__:e: <unittest.suite.TestSuite tests=[<unittest.suite.TestSuite tests=[<tasks.cephfs.test_volume_client.TestVolumeClient testMethod=test_21501>]>]>
2019-11-19T03:16:29.092 INFO:__main__:e: <unittest.suite.TestSuite tests=[<tasks.cephfs.test_volume_client.TestVolumeClient testMethod=test_21501>]>
2019-11-19T03:16:29.092 INFO:__main__:run args=['ps', '-u1196']
2019-11-19T03:16:29.093 INFO:__main__:Running ['ps', '-u1196']
2019-11-19T03:16:29.130 WARNING:__main__:Killing stray process 6514 pts/8 00:00:00 ceph-mds
2019-11-19T03:16:29.173 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:29.173 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:29.194 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:29.195 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:29.216 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:29.216 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:29.237 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:29.238 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:29.262 INFO:__main__:run args=['./bin/ceph', 'tell', 'osd.*', 'injectargs', '--osd-mon-report-interval', '5']
2019-11-19T03:16:29.263 INFO:__main__:Running ['./bin/ceph', 'tell', 'osd.*', 'injectargs', '--osd-mon-report-interval', '5']
2019-11-19T03:16:29.521 INFO:__main__:Searching for existing instance osd_mon_report_interval/osd
2019-11-19T03:16:29.523 INFO:__main__:Searching for existing instance mds log max segments/mds
2019-11-19T03:16:29.524 INFO:__main__:Searching for existing instance osd_mon_report_interval/osd
2019-11-19T03:16:29.524 INFO:__main__:Searching for existing instance mds log max segments/mds
2019-11-19T03:16:29.525 INFO:__main__:Searching for existing instance mds root ino uid/global
2019-11-19T03:16:29.526 INFO:__main__:Searching for existing instance osd_mon_report_interval/osd
2019-11-19T03:16:29.526 INFO:__main__:Searching for existing instance mds log max segments/mds
2019-11-19T03:16:29.527 INFO:__main__:Searching for existing instance mds root ino uid/global
2019-11-19T03:16:29.527 INFO:__main__:Searching for existing instance mds root ino gid/global
2019-11-19T03:16:29.528 INFO:__main__:Searching for existing instance osd_mon_report_interval/osd
2019-11-19T03:16:29.528 INFO:__main__:Executing modules: ['tasks.cephfs.test_volume_client.TestVolumeClient.test_21501']
2019-11-19T03:16:29.529 INFO:__main__:Loaded: [<unittest.suite.TestSuite tests=[<tasks.cephfs.test_volume_client.TestVolumeClient testMethod=test_21501>]>]
2019-11-19T03:16:29.529 INFO:__main__:e: <unittest.suite.TestSuite tests=[<unittest.suite.TestSuite tests=[<tasks.cephfs.test_volume_client.TestVolumeClient testMethod=test_21501>]>]>
2019-11-19T03:16:29.529 INFO:__main__:e: <unittest.suite.TestSuite tests=[<tasks.cephfs.test_volume_client.TestVolumeClient testMethod=test_21501>]>
2019-11-19T03:16:29.530 INFO:__main__:Disabling 0 tests because of is_for_teuthology or needs_trimming
2019-11-19T03:16:29.530 INFO:__main__:Starting test: test_21501 (tasks.cephfs.test_volume_client.TestVolumeClient)
2019-11-19T03:16:29.530 INFO:__main__:run args=['./bin/ceph', 'log', 'Starting test tasks.cephfs.test_volume_client.TestVolumeClient.test_21501']
2019-11-19T03:16:29.531 INFO:__main__:Running ['./bin/ceph', 'log', 'Starting test tasks.cephfs.test_volume_client.TestVolumeClient.test_21501']
2019-11-19T03:16:30.727 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:30.727 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:30.749 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:30.749 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:30.768 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:30.768 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:30.787 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:30.787 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:30.809 INFO:__main__:run args=['ps', 'ww', '-u1196']
2019-11-19T03:16:30.809 INFO:__main__:Running ['ps', 'ww', '-u1196']
2019-11-19T03:16:30.851 INFO:__main__:No match for mds a: PID TTY STAT TIME COMMAND
301 ? Ssl 0:06 /home/rishabh/repos/ceph/master/build/bin/ceph-mon -i c -c /home/rishabh/repos/ceph/master/build/ceph.conf
535 ? Ssl 0:07 /home/rishabh/repos/ceph/master/build/bin/ceph-mgr -i x -c /home/rishabh/repos/ceph/master/build/ceph.conf
913 ? Ssl 0:14 /home/rishabh/repos/ceph/master/build/bin/ceph-osd -i 0 -c /home/rishabh/repos/ceph/master/build/ceph.conf
1253 ? Ssl 0:14 /home/rishabh/repos/ceph/master/build/bin/ceph-osd -i 1 -c /home/rishabh/repos/ceph/master/build/ceph.conf
1600 ? Ssl 0:14 /home/rishabh/repos/ceph/master/build/bin/ceph-osd -i 2 -c /home/rishabh/repos/ceph/master/build/ceph.conf
4360 pts/9 S+ 0:00 vim qa/tasks/cephfs/test_volume_client.py
4406 ? S 0:00 sshd: rishabh@pts/10
4407 pts/10 Ss+ 0:00 -bash
7147 pts/8 S+ 0:01 python ../qa/tasks/vstart_runner.py --interactive tasks.cephfs.test_volume_client.TestVolumeClient.test_21501
7228 pts/8 R+ 0:00 ps ww -u1196
8440 ? Ss 0:00 /lib/systemd/systemd --user
8443 ? S 0:00 (sd-pam)
17822 ? S 0:00 sshd: rishabh@pts/8
17823 pts/8 Ss 0:00 -bash
19772 ? S 0:00 sshd: rishabh@pts/9
19773 pts/9 Ss 0:00 -bash
32687 ? Ssl 0:11 /home/rishabh/repos/ceph/master/build/bin/ceph-mon -i a -c /home/rishabh/repos/ceph/master/build/ceph.conf
32728 ? Ssl 0:08 /home/rishabh/repos/ceph/master/build/bin/ceph-mon -i b -c /home/rishabh/repos/ceph/master/build/ceph.conf
2019-11-19T03:16:30.851 ERROR:__main__:tried to stop a non-running daemon
2019-11-19T03:16:30.852 INFO:__main__:run args=['./bin/ceph', 'mds', 'fail', 'a']
2019-11-19T03:16:30.852 INFO:__main__:Running ['./bin/ceph', 'mds', 'fail', 'a']
2019-11-19T03:16:31.752 INFO:__main__:run args=['./bin/ceph', 'osd', 'dump', '--format=json-pretty']
2019-11-19T03:16:31.753 INFO:__main__:Running ['./bin/ceph', 'osd', 'dump', '--format=json-pretty']
2019-11-19T03:16:32.153 INFO:__main__:run args=['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:32.153 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:32.537 INFO:__main__:run args=['./bin/ceph', 'fs', 'set', 'cephfs', 'joinable', 'false']
2019-11-19T03:16:32.538 INFO:__main__:Running ['./bin/ceph', 'fs', 'set', 'cephfs', 'joinable', 'false']
2019-11-19T03:16:33.798 INFO:__main__:run args=['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:33.799 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:34.181 INFO:__main__:run args=['./bin/ceph', 'fs', 'rm', u'cephfs', '--yes-i-really-mean-it']
2019-11-19T03:16:34.181 INFO:__main__:Running ['./bin/ceph', 'fs', 'rm', u'cephfs', '--yes-i-really-mean-it']
2019-11-19T03:16:34.791 INFO:__main__:run args=['./bin/ceph', 'osd', 'pool', 'delete', u'cephfs_metadata', u'cephfs_metadata', '--yes-i-really-really-mean-it']
2019-11-19T03:16:34.792 INFO:__main__:Running ['./bin/ceph', 'osd', 'pool', 'delete', u'cephfs_metadata', u'cephfs_metadata', '--yes-i-really-really-mean-it']
2019-11-19T03:16:35.860 INFO:__main__:run args=['./bin/ceph', 'osd', 'pool', 'delete', u'cephfs_data', u'cephfs_data', '--yes-i-really-really-mean-it']
2019-11-19T03:16:35.861 INFO:__main__:Running ['./bin/ceph', 'osd', 'pool', 'delete', u'cephfs_data', u'cephfs_data', '--yes-i-really-really-mean-it']
2019-11-19T03:16:36.862 INFO:__main__:run args=['./bin/ceph', 'osd', 'blacklist', 'clear']
2019-11-19T03:16:36.863 INFO:__main__:Running ['./bin/ceph', 'osd', 'blacklist', 'clear']
2019-11-19T03:16:37.923 INFO:__main__:run args=['./bin/ceph', 'auth', 'ls', '--format=json-pretty']
2019-11-19T03:16:37.923 INFO:__main__:Running ['./bin/ceph', 'auth', 'ls', '--format=json-pretty']
2019-11-19T03:16:38.309 INFO:__main__:run args=['./bin/ceph', 'auth', 'del', u'client.21501']
2019-11-19T03:16:38.309 INFO:__main__:Running ['./bin/ceph', 'auth', 'del', u'client.21501']
2019-11-19T03:16:38.748 INFO:__main__:run args=['./bin/ceph', 'auth', 'del', u'client.manila']
2019-11-19T03:16:38.748 INFO:__main__:Running ['./bin/ceph', 'auth', 'del', u'client.manila']
2019-11-19T03:16:39.197 INFO:__main__:Discovered MDS IDs: ['a']
2019-11-19T03:16:39.198 INFO:__main__:run args=['./bin/ceph', '--format=json-pretty', 'osd', 'lspools']
2019-11-19T03:16:39.198 INFO:__main__:Running ['./bin/ceph', '--format=json-pretty', 'osd', 'lspools']
2019-11-19T03:16:39.609 INFO:__main__:run args=['./bin/ceph', 'daemon', 'mon.a', 'config', 'get', 'mon_pg_warn_min_per_osd']
2019-11-19T03:16:39.609 INFO:__main__:Running ['./bin/ceph', 'daemon', 'mon.a', 'config', 'get', 'mon_pg_warn_min_per_osd']
2019-11-19T03:16:39.860 INFO:__main__:run args=['./bin/ceph', 'osd', 'pool', 'create', 'cephfs_metadata', '9']
2019-11-19T03:16:39.860 INFO:__main__:Running ['./bin/ceph', 'osd', 'pool', 'create', 'cephfs_metadata', '9']
2019-11-19T03:16:41.016 INFO:__main__:run args=['./bin/ceph', 'osd', 'pool', 'create', 'cephfs_data', '9']
2019-11-19T03:16:41.016 INFO:__main__:Running ['./bin/ceph', 'osd', 'pool', 'create', 'cephfs_data', '9']
2019-11-19T03:16:42.119 INFO:__main__:run args=['./bin/ceph', 'fs', 'new', 'cephfs', 'cephfs_metadata', 'cephfs_data']
2019-11-19T03:16:42.120 INFO:__main__:Running ['./bin/ceph', 'fs', 'new', 'cephfs', 'cephfs_metadata', 'cephfs_data']
2019-11-19T03:16:42.547 INFO:__main__:run args=['./bin/ceph', 'osd', 'dump', '--format=json']
2019-11-19T03:16:42.547 INFO:__main__:Running ['./bin/ceph', 'osd', 'dump', '--format=json']
2019-11-19T03:16:42.930 INFO:__main__:run args=['./bin/ceph', 'osd', 'dump', '--format=json']
2019-11-19T03:16:42.931 INFO:__main__:Running ['./bin/ceph', 'osd', 'dump', '--format=json']
2019-11-19T03:16:43.314 INFO:__main__:run args=['./bin/ceph', 'fs', 'set', 'cephfs', 'standby_count_wanted', '0']
2019-11-19T03:16:43.314 INFO:__main__:Running ['./bin/ceph', 'fs', 'set', 'cephfs', 'standby_count_wanted', '0']
2019-11-19T03:16:44.589 INFO:__main__:run args=['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:44.589 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:44.976 INFO:__main__:run args=['./bin/ceph', 'osd', 'dump', '--format=json']
2019-11-19T03:16:44.976 INFO:__main__:Running ['./bin/ceph', 'osd', 'dump', '--format=json']
2019-11-19T03:16:45.375 INFO:__main__:run args=['ps', 'ww', '-u1196']
2019-11-19T03:16:45.375 INFO:__main__:Running ['ps', 'ww', '-u1196']
2019-11-19T03:16:45.417 INFO:__main__:No match for mds a: PID TTY STAT TIME COMMAND
301 ? Ssl 0:06 /home/rishabh/repos/ceph/master/build/bin/ceph-mon -i c -c /home/rishabh/repos/ceph/master/build/ceph.conf
535 ? Ssl 0:07 /home/rishabh/repos/ceph/master/build/bin/ceph-mgr -i x -c /home/rishabh/repos/ceph/master/build/ceph.conf
913 ? Ssl 0:14 /home/rishabh/repos/ceph/master/build/bin/ceph-osd -i 0 -c /home/rishabh/repos/ceph/master/build/ceph.conf
1253 ? Ssl 0:14 /home/rishabh/repos/ceph/master/build/bin/ceph-osd -i 1 -c /home/rishabh/repos/ceph/master/build/ceph.conf
1600 ? Ssl 0:14 /home/rishabh/repos/ceph/master/build/bin/ceph-osd -i 2 -c /home/rishabh/repos/ceph/master/build/ceph.conf
4360 pts/9 S+ 0:00 vim qa/tasks/cephfs/test_volume_client.py
4406 ? S 0:00 sshd: rishabh@pts/10
4407 pts/10 Ss+ 0:00 -bash
7147 pts/8 S+ 0:01 python ../qa/tasks/vstart_runner.py --interactive tasks.cephfs.test_volume_client.TestVolumeClient.test_21501
7828 pts/8 R+ 0:00 ps ww -u1196
8440 ? Ss 0:00 /lib/systemd/systemd --user
8443 ? S 0:00 (sd-pam)
17822 ? S 0:00 sshd: rishabh@pts/8
17823 pts/8 Ss 0:00 -bash
19772 ? S 0:00 sshd: rishabh@pts/9
19773 pts/9 Ss 0:00 -bash
32687 ? Ssl 0:12 /home/rishabh/repos/ceph/master/build/bin/ceph-mon -i a -c /home/rishabh/repos/ceph/master/build/ceph.conf
32728 ? Ssl 0:08 /home/rishabh/repos/ceph/master/build/bin/ceph-mon -i b -c /home/rishabh/repos/ceph/master/build/ceph.conf
2019-11-19T03:16:45.417 INFO:__main__:run args=['./bin/./ceph-mds', '-i', 'a']
2019-11-19T03:16:45.418 INFO:__main__:Running ['./bin/./ceph-mds', '-i', 'a']
2019-11-19T03:16:45.483 INFO:__main__:run args=['./bin/ceph', 'auth', 'caps', 'client.0', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:45.484 INFO:__main__:Running ['./bin/ceph', 'auth', 'caps', 'client.0', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:45.915 INFO:__main__:run args=['./bin/ceph', 'auth', 'caps', 'client.1', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:45.915 INFO:__main__:Running ['./bin/ceph', 'auth', 'caps', 'client.1', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:46.353 INFO:__main__:run args=['./bin/ceph', 'auth', 'caps', 'client.2', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:46.353 INFO:__main__:Running ['./bin/ceph', 'auth', 'caps', 'client.2', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:46.793 INFO:__main__:run args=['./bin/ceph', 'auth', 'caps', 'client.3', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:46.793 INFO:__main__:Running ['./bin/ceph', 'auth', 'caps', 'client.3', 'mds', 'allow', 'mon', 'allow r', 'osd', 'allow rw pool=cephfs_data']
2019-11-19T03:16:47.235 INFO:__main__:run args=['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:47.235 INFO:__main__:Running ['./bin/ceph', 'fs', 'dump', '--format=json']
2019-11-19T03:16:47.639 INFO:__main__:run args=['./bin/ceph', 'daemon', 'mds.a', 'status']
2019-11-19T03:16:47.639 INFO:__main__:Running ['./bin/ceph', 'daemon', 'mds.a', 'status']
2019-11-19T03:16:47.896 INFO:__main__:run args=['mkdir', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:47.897 INFO:__main__:Running ['mkdir', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:47.939 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:47.939 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:47.960 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:47.961 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:47.979 INFO:__main__:Pre-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62]
2019-11-19T03:16:47.979 INFO:__main__:run args=['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.0', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:47.979 INFO:__main__:Running ['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.0', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:47.998 INFO:__main__:Mounting client.0 with pid 8009
2019-11-19T03:16:47.998 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:47.998 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:48.019 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:48.020 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.041 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.041 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.063 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.064 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.086 INFO:__main__:Post-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63]
2019-11-19T03:16:49.086 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:49.086 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:49.109 INFO:__main__:run args=['sudo', 'chmod', '1777', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:49.109 INFO:__main__:Running ['chmod', '1777', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:16:49.129 INFO:__main__:run args=['mkdir', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:49.129 INFO:__main__:Running ['mkdir', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:49.223 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.223 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.244 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.244 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.262 INFO:__main__:Pre-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63]
2019-11-19T03:16:49.263 INFO:__main__:run args=['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.1', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:49.263 INFO:__main__:Running ['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.1', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:49.281 INFO:__main__:Mounting client.1 with pid 8050
2019-11-19T03:16:49.282 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.282 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.300 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:49.301 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.321 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.321 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.341 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.341 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.361 INFO:__main__:Post-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64]
2019-11-19T03:16:50.362 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:50.362 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:50.382 INFO:__main__:run args=['sudo', 'chmod', '1777', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:50.382 INFO:__main__:Running ['chmod', '1777', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:50.404 INFO:__main__:run args=['mkdir', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:50.405 INFO:__main__:Running ['mkdir', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:50.465 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.465 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.483 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.484 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.504 INFO:__main__:Pre-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64]
2019-11-19T03:16:50.504 INFO:__main__:run args=['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.2', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:50.505 INFO:__main__:Running ['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.2', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:50.523 INFO:__main__:Mounting client.2 with pid 8091
2019-11-19T03:16:50.523 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.524 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.544 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:50.544 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.564 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.565 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.586 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.586 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.606 INFO:__main__:Post-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65]
2019-11-19T03:16:51.606 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:51.607 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:51.629 INFO:__main__:run args=['sudo', 'chmod', '1777', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:51.629 INFO:__main__:Running ['chmod', '1777', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:51.650 INFO:__main__:run args=['mkdir', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:51.650 INFO:__main__:Running ['mkdir', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:51.732 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.733 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.752 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.752 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.770 INFO:__main__:Pre-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65]
2019-11-19T03:16:51.771 INFO:__main__:run args=['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.3', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:51.771 INFO:__main__:Running ['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.3', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:51.789 INFO:__main__:Mounting client.3 with pid 8132
2019-11-19T03:16:51.790 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.790 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.811 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:51.811 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:52.833 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:52.833 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:16:52.855 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:52.855 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:16:52.874 INFO:__main__:Post-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66]
2019-11-19T03:16:52.874 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:52.874 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:52.895 INFO:__main__:run args=['sudo', 'chmod', '1777', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:52.895 INFO:__main__:Running ['chmod', '1777', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:16:52.918 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.918 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.940 INFO:__main__:run args=['sudo', 'fusermount', '-u', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.941 INFO:__main__:Running ['fusermount', '-u', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.976 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.977 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.999 INFO:__main__:run args=['rmdir', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:52.999 INFO:__main__:Running ['rmdir', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:16:53.017 INFO:__main__:run args=['./bin/ceph', 'auth', 'get-or-create', 'client.manila', 'mds', 'allow *', 'osd', 'allow rw', 'mon', 'allow *']
2019-11-19T03:16:53.018 INFO:__main__:Running ['./bin/ceph', 'auth', 'get-or-create', 'client.manila', 'mds', 'allow *', 'osd', 'allow rw', 'mon', 'allow *']
2019-11-19T03:16:53.416 INFO:__main__:run args=['sudo', 'sh', '-c', 'cat > /home/rishabh/repos/ceph/master/build/client.manila.keyring']
2019-11-19T03:16:53.417 INFO:__main__:Running ['sh', '-c', 'cat > /home/rishabh/repos/ceph/master/build/client.manila.keyring']
2019-11-19T03:16:53.438 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:16:53.440 INFO:__main__:run args=['python3', '-c', '\nfrom __future__ import print_function\nfrom ceph_volume_client import CephFSVolumeClient, VolumePath\nfrom sys import version_info as sys_version_info\nfrom rados import OSError as rados_OSError\nimport logging\nlog = logging.getLogger("ceph_volume_client")\nlog.addHandler(logging.StreamHandler())\nlog.setLevel(logging.DEBUG)\nvc = CephFSVolumeClient("manila", "./ceph.conf", "ceph", None, None)\nvc.connect()\n\nvp = VolumePath("grpid", "volid")\ncreate_result = vc.create_volume(vp, 1024*1024*10)\nprint(create_result[\'mount_path\'])\n\nvc.disconnect()\n ']
2019-11-19T03:16:53.440 INFO:__main__:Running ['python3', '-c', '\nfrom __future__ import print_function\nfrom ceph_volume_client import CephFSVolumeClient, VolumePath\nfrom sys import version_info as sys_version_info\nfrom rados import OSError as rados_OSError\nimport logging\nlog = logging.getLogger("ceph_volume_client")\nlog.addHandler(logging.StreamHandler())\nlog.setLevel(logging.DEBUG)\nvc = CephFSVolumeClient("manila", "./ceph.conf", "ceph", None, None)\nvc.connect()\n\nvp = VolumePath("grpid", "volid")\ncreate_result = vc.create_volume(vp, 1024*1024*10)\nprint(create_result[\'mount_path\'])\n\nvc.disconnect()\n ']
2019-11-19T03:16:53.728 INFO:__main__:run args=['./bin/ceph', 'auth', 'get-or-create', 'client.21501']
2019-11-19T03:16:53.729 INFO:__main__:Running ['./bin/ceph', 'auth', 'get-or-create', 'client.21501']
2019-11-19T03:16:54.141 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:54.141 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:54.165 INFO:__main__:run args=['sudo', 'fusermount', '-u', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:54.166 INFO:__main__:Running ['fusermount', '-u', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:54.208 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:16:54.209 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:00.234 INFO:__main__:run args=['rmdir', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:00.234 INFO:__main__:Running ['rmdir', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:00.254 INFO:__main__:run args=['python3', '-c', '\nfrom __future__ import print_function\nfrom ceph_volume_client import CephFSVolumeClient, VolumePath\nfrom sys import version_info as sys_version_info\nfrom rados import OSError as rados_OSError\nimport logging\nlog = logging.getLogger("ceph_volume_client")\nlog.addHandler(logging.StreamHandler())\nlog.setLevel(logging.DEBUG)\nvc = CephFSVolumeClient("manila", "./ceph.conf", "ceph", "/volumes", None)\nvc.connect()\n\nvp = VolumePath("grpid", "volid")\nauth_result = vc.authorize(vp, "21501", readonly=False,\n tenant_id="None")\nprint(auth_result[\'auth_key\'])\n\nvc.disconnect()\n ']
2019-11-19T03:17:00.255 INFO:__main__:Running ['python3', '-c', '\nfrom __future__ import print_function\nfrom ceph_volume_client import CephFSVolumeClient, VolumePath\nfrom sys import version_info as sys_version_info\nfrom rados import OSError as rados_OSError\nimport logging\nlog = logging.getLogger("ceph_volume_client")\nlog.addHandler(logging.StreamHandler())\nlog.setLevel(logging.DEBUG)\nvc = CephFSVolumeClient("manila", "./ceph.conf", "ceph", "/volumes", None)\nvc.connect()\n\nvp = VolumePath("grpid", "volid")\nauth_result = vc.authorize(vp, "21501", readonly=False,\n tenant_id="None")\nprint(auth_result[\'auth_key\'])\n\nvc.disconnect()\n ']
2019-11-19T03:17:00.693 INFO:__main__:run args=['./bin/ceph', 'auth', 'get-key', 'client.21501']
2019-11-19T03:17:00.693 INFO:__main__:Running ['./bin/ceph', 'auth', 'get-key', 'client.21501']
2019-11-19T03:17:01.124 INFO:__main__:run args=['./bin/ceph', 'auth', 'ls', '--format=json-pretty']
2019-11-19T03:17:01.125 INFO:__main__:Running ['./bin/ceph', 'auth', 'ls', '--format=json-pretty']
2019-11-19T03:17:01.555 INFO:__main__:run args=['sudo', 'sh', '-c', 'cat > /home/rishabh/repos/ceph/master/build/client.21501.keyring']
2019-11-19T03:17:01.556 INFO:__main__:Running ['sh', '-c', 'cat > /home/rishabh/repos/ceph/master/build/client.21501.keyring']
2019-11-19T03:17:01.578 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:17:01.579 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:01.580 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:17:01.580 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:01.581 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:01.581 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:17:01.582 INFO:__main__:Searching for existing instance debug objecter/client.21501
2019-11-19T03:17:01.582 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:01.583 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:01.583 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:17:01.584 INFO:__main__:Searching for existing instance debug objecter/client.21501
2019-11-19T03:17:01.584 INFO:__main__:Searching for existing instance keyring/client.21501
2019-11-19T03:17:01.584 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:01.585 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:01.585 INFO:__main__:run args=['mkdir', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:01.585 INFO:__main__:Running ['mkdir', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:01.604 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.605 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.625 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.625 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.645 INFO:__main__:Pre-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 66]
2019-11-19T03:17:01.645 INFO:__main__:run args=['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '--client_mountpoint=/volumes/grpid/volid', '-f', '--name', 'client.21501', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:01.645 INFO:__main__:Running ['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '--client_mountpoint=/volumes/grpid/volid', '-f', '--name', 'client.21501', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:01.663 INFO:__main__:Mounting client.21501 with pid 8371
2019-11-19T03:17:01.664 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.664 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.685 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:17:01.686 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:17:02.704 INFO:__main__:run args=['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:17:02.705 INFO:__main__:Running ['mount', '-t', 'fusectl', '/sys/fs/fuse/connections', '/sys/fs/fuse/connections']
2019-11-19T03:17:02.725 INFO:__main__:run args=['ls', '/sys/fs/fuse/connections']
2019-11-19T03:17:02.725 INFO:__main__:Running ['ls', '/sys/fs/fuse/connections']
2019-11-19T03:17:02.746 INFO:__main__:Post-mount connections: [40, 44, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 66]
2019-11-19T03:17:02.747 INFO:__main__:run args=['./bin/ceph', 'log', 'Ended test tasks.cephfs.test_volume_client.TestVolumeClient.test_21501']
2019-11-19T03:17:02.747 INFO:__main__:Running ['./bin/ceph', 'log', 'Ended test tasks.cephfs.test_volume_client.TestVolumeClient.test_21501']
2019-11-19T03:17:03.680 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.680 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.701 INFO:__main__:run args=['sudo', 'fusermount', '-u', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.702 INFO:__main__:Running ['fusermount', '-u', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.740 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.741 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.760 INFO:__main__:kill
2019-11-19T03:17:03.760 INFO:__main__:kill: killing pid 8009 (['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.0', '/tmp/tmpqkCL57/mnt.0'])
2019-11-19T03:17:03.761 INFO:__main__:run args=['rm', '-rf', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.761 INFO:__main__:Running ['rm', '-rf', '/tmp/tmpqkCL57/mnt.0']
2019-11-19T03:17:03.781 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:17:03.781 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:17:03.801 INFO:__main__:run args=['rm', '-rf', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:17:03.801 INFO:__main__:Running ['rm', '-rf', '/tmp/tmpqkCL57/mnt.1']
2019-11-19T03:17:03.821 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.821 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.844 INFO:__main__:run args=['sudo', 'fusermount', '-u', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.845 INFO:__main__:Running ['fusermount', '-u', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.888 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.889 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.910 INFO:__main__:kill
2019-11-19T03:17:03.910 INFO:__main__:kill: killing pid 8371 (['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '--client_mountpoint=/volumes/grpid/volid', '-f', '--name', 'client.21501', '/tmp/tmpqkCL57/mnt.2'])
2019-11-19T03:17:03.912 INFO:__main__:run args=['rm', '-rf', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.912 INFO:__main__:Running ['rm', '-rf', '/tmp/tmpqkCL57/mnt.2']
2019-11-19T03:17:03.932 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:03.932 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:03.954 INFO:__main__:run args=['sudo', 'fusermount', '-u', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:03.954 INFO:__main__:Running ['fusermount', '-u', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:03.992 INFO:__main__:run args=['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:03.993 INFO:__main__:Running ['stat', '--file-system', '--printf=%T\n', '--', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:04.014 INFO:__main__:kill
2019-11-19T03:17:04.014 INFO:__main__:kill: killing pid 8132 (['./bin/ceph-fuse', '--client_die_on_failed_dentry_invalidate=false', '-f', '--name', 'client.3', '/tmp/tmpqkCL57/mnt.3'])
2019-11-19T03:17:04.016 INFO:__main__:run args=['rm', '-rf', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:04.016 INFO:__main__:Running ['rm', '-rf', '/tmp/tmpqkCL57/mnt.3']
2019-11-19T03:17:04.035 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:17:04.035 INFO:__main__:Searching for existing instance debug objecter/client.21501
2019-11-19T03:17:04.036 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:04.036 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:04.037 INFO:__main__:Searching for existing instance keyring/client.manila
2019-11-19T03:17:04.037 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:04.037 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:04.041 INFO:__main__:Searching for existing instance client quota/client.21501
2019-11-19T03:17:04.041 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:04.042 INFO:__main__:Searching for existing instance debug client/client.21501
2019-11-19T03:17:04.043 INFO:__main__:test_21501 (tasks.cephfs.test_volume_client.TestVolumeClient) ... ok
2019-11-19T03:17:04.043 INFO:__main__:Stopped test: test_21501 (tasks.cephfs.test_volume_client.TestVolumeClient) in 34.512591s
2019-11-19T03:17:04.043 INFO:__main__:
2019-11-19T03:17:04.044 INFO:__main__:----------------------------------------------------------------------
2019-11-19T03:17:04.044 INFO:__main__:Ran 1 test in 34.513s
2019-11-19T03:17:04.044 INFO:__main__:
2019-11-19T03:17:04.044 INFO:__main__:OK
    (1-1/1)