Bug #58490
Updated by Ilya Dryomov over 1 year ago
This is popped up on pacific_16.2.11_RC6.6 but the code is mostly the same in main: pacific_16.2.11_RC6.6: <pre> 2023-01-17T17:58:55.709 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule status 2023-01-17T17:58:55.709 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep rbd2/ns1/test1 2023-01-17T17:58:55.755 INFO:tasks.workunit.client.0.smithi027.stdout:2023-01-17 17:59:00 rbd2/ns1/test1 2023-01-17T17:58:55.756 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule add 1h 00:15 2023-01-17T17:58:55.810 INFO:tasks.workunit.client.0.smithi027.stderr:++ rbd mirror snapshot schedule ls 2023-01-17T17:58:55.851 INFO:tasks.workunit.client.0.smithi027.stderr:+ test 'every 1h starting at 00:15:00' = 'every 1h starting at 00:15:00' 2023-01-17T17:58:55.852 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -R 2023-01-17T17:58:55.852 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep 'every 1h starting at 00:15:00' 2023-01-17T17:58:55.898 INFO:tasks.workunit.client.0.smithi027.stdout:- - - every 1h starting at 00:15:00 2023-01-17T17:58:55.899 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -R 2023-01-17T17:58:55.899 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep 'rbd2 *ns1 *test1 *every 1m' 2023-01-17T17:58:55.943 INFO:tasks.workunit.client.0.smithi027.stdout:rbd2 ns1 test1 every 1m 2023-01-17T17:58:55.944 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail rbd mirror snapshot schedule ls -p rbd2 2023-01-17T17:58:55.944 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -p rbd2 2023-01-17T17:58:55.988 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 0 2023-01-17T17:58:55.989 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -p rbd2 -R 2023-01-17T17:58:55.989 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep 'every 1h starting at 00:15:00' 2023-01-17T17:58:56.034 INFO:tasks.workunit.client.0.smithi027.stdout:- - - every 1h starting at 00:15:00 2023-01-17T17:58:56.035 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -p rbd2 -R 2023-01-17T17:58:56.035 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep 'rbd2 *ns1 *test1 *every 1m' 2023-01-17T17:58:56.081 INFO:tasks.workunit.client.0.smithi027.stdout:rbd2 ns1 test1 every 1m 2023-01-17T17:58:56.082 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail rbd mirror snapshot schedule ls -p rbd2/ns1 2023-01-17T17:58:56.082 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -p rbd2/ns1 2023-01-17T17:58:56.129 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 0 2023-01-17T17:58:56.130 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -p rbd2/ns1 -R 2023-01-17T17:58:56.130 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep 'every 1h starting at 00:15:00' 2023-01-17T17:58:56.177 INFO:tasks.workunit.client.0.smithi027.stdout:- - - every 1h starting at 00:15:00 2023-01-17T17:58:56.178 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule ls -p rbd2/ns1 -R 2023-01-17T17:58:56.178 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep 'rbd2 *ns1 *test1 *every 1m' 2023-01-17T17:58:56.226 INFO:tasks.workunit.client.0.smithi027.stdout:rbd2 ns1 test1 every 1m 2023-01-17T17:58:56.227 INFO:tasks.workunit.client.0.smithi027.stderr:++ rbd mirror snapshot schedule ls -p rbd2/ns1 --image test1 2023-01-17T17:58:56.294 INFO:tasks.workunit.client.0.smithi027.stderr:+ test 'every 1m' = 'every 1m' 2023-01-17T17:58:56.295 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail rbd mirror snapshot schedule add dummy 2023-01-17T17:58:56.295 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule add dummy 2023-01-17T17:58:56.335 INFO:tasks.ceph.mgr.x.smithi027.stderr:2023-01-17T17:58:56.333+0000 7f198953f700 -1 mgr.server reply reply (22) Invalid argument Invalid interval (dummy) 2023-01-17T17:58:56.335 INFO:tasks.workunit.client.0.smithi027.stderr:rbd: rbd mirror snapshot schedule add failed: (22) Invalid argument: Invalid interval (dummy) 2023-01-17T17:58:56.340 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 0 2023-01-17T17:58:56.340 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail rbd mirror snapshot schedule add -p rbd2/ns1 --image test1 dummy 2023-01-17T17:58:56.340 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule add -p rbd2/ns1 --image test1 dummy 2023-01-17T17:58:56.404 INFO:tasks.ceph.mgr.x.smithi027.stderr:2023-01-17T17:58:56.401+0000 7f198953f700 -1 mgr.server reply reply (22) Invalid argument Invalid interval (dummy) 2023-01-17T17:58:56.405 INFO:tasks.workunit.client.0.smithi027.stderr:rbd: rbd mirror snapshot schedule add failed: (22) Invalid argument: Invalid interval (dummy) 2023-01-17T17:58:56.409 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 0 2023-01-17T17:58:56.410 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail rbd mirror snapshot schedule remove dummy 2023-01-17T17:58:56.410 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule remove dummy 2023-01-17T17:58:56.450 INFO:tasks.ceph.mgr.x.smithi027.stderr:2023-01-17T17:58:56.449+0000 7f198953f700 -1 mgr.server reply reply (22) Invalid argument Invalid interval (dummy) 2023-01-17T17:58:56.450 INFO:tasks.workunit.client.0.smithi027.stderr:rbd: rbd mirror snapshot schedule remove failed: (22) Invalid argument: Invalid interval (dummy) 2023-01-17T17:58:56.454 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 0 2023-01-17T17:58:56.455 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail rbd mirror snapshot schedule remove -p rbd2/ns1 --image test1 dummy 2023-01-17T17:58:56.455 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule remove -p rbd2/ns1 --image test1 dummy 2023-01-17T17:58:56.524 INFO:tasks.ceph.mgr.x.smithi027.stderr:2023-01-17T17:58:56.521+0000 7f198953f700 -1 mgr.server reply reply (22) Invalid argument Invalid interval (dummy) 2023-01-17T17:58:56.524 INFO:tasks.workunit.client.0.smithi027.stderr:rbd: rbd mirror snapshot schedule remove failed: (22) Invalid argument: Invalid interval (dummy) 2023-01-17T17:58:56.527 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 0 2023-01-17T17:58:56.528 INFO:tasks.workunit.client.0.smithi027.stderr:++ rbd mirror snapshot schedule ls 2023-01-17T17:58:56.574 INFO:tasks.workunit.client.0.smithi027.stderr:+ test 'every 1h starting at 00:15:00' = 'every 1h starting at 00:15:00' 2023-01-17T17:58:56.574 INFO:tasks.workunit.client.0.smithi027.stderr:++ rbd mirror snapshot schedule ls -p rbd2/ns1 --image test1 2023-01-17T17:58:56.646 INFO:tasks.workunit.client.0.smithi027.stderr:+ test 'every 1m' = 'every 1m' 2023-01-17T17:58:56.646 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd rm rbd2/ns1/test1 2023-01-17T17:58:58.879 INFO:tasks.workunit.client.0.smithi027.stderr:2023-01-17T17:58:58.877+0000 7f5940d3e700 0 -- 172.21.15.27:0/4279233003 >> [v2:172.21.15.27:6800/26330,v1:172.21.15.27:6801/26330] conn(0x5646a3585480 msgr2=0x5646a35974c0 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2023-01-17T17:58:59.897 INFO:tasks.workunit.client.0.smithi027.stderr:2023-01-17T17:58:59.893+0000 7f5940d3e700 0 -- 172.21.15.27:0/4279233003 >> [v2:172.21.15.27:6800/26330,v1:172.21.15.27:6801/26330] conn(0x7f59200347a0 msgr2=0x7f5920036b90 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2023-01-17T17:58:59.957 INFO:tasks.workunit.client.0.smithi027.stderr:^MRemoving image: 100% complete...done. 2023-01-17T17:58:59.963 INFO:tasks.workunit.client.0.smithi027.stderr:++ seq 12 2023-01-17T17:58:59.964 INFO:tasks.workunit.client.0.smithi027.stderr:+ for i in `seq 12` 2023-01-17T17:58:59.964 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule status 2023-01-17T17:58:59.965 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep rbd2/ns1/test1 2023-01-17T17:59:00.009 INFO:tasks.workunit.client.0.smithi027.stderr:+ break 2023-01-17T17:59:00.009 INFO:tasks.workunit.client.0.smithi027.stderr:+ rbd mirror snapshot schedule status 2023-01-17T17:59:00.010 INFO:tasks.workunit.client.0.smithi027.stderr:+ expect_fail grep rbd2/ns1/test1 2023-01-17T17:59:00.010 INFO:tasks.workunit.client.0.smithi027.stderr:+ grep rbd2/ns1/test1 2023-01-17T17:59:00.052 INFO:tasks.workunit.client.0.smithi027.stdout:2023-01-17 18:00:00 rbd2/ns1/test1 2023-01-17T17:59:00.053 INFO:tasks.workunit.client.0.smithi027.stderr:+ return 1 2023-01-17T17:59:00.054 DEBUG:teuthology.orchestra.run:got remote process result: 1 2023-01-17T17:59:00.054 INFO:tasks.workunit:Stopping ['rbd/cli_generic.sh'] on client.0... 2023-01-17T17:59:00.055 DEBUG:teuthology.orchestra.run.smithi027:> sudo rm -rf -- /home/ubuntu/cephtest/workunits.list.client.0 /home/ubuntu/cephtest/clone.client.0 2023-01-17T17:59:00.304 ERROR:teuthology.run_tasks:Saw exception from tasks. Traceback (most recent call last): File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/run_tasks.py", line 103, in run_tasks manager = run_one_task(taskname, ctx=ctx, config=config) File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/run_tasks.py", line 82, in run_one_task return task(**kwargs) File "/home/teuthworker/src/github.com_idryomov_ceph_d158d6409994693da5611f9b5747b4ca30fcbcf6/qa/tasks/workunit.py", line 129, in task p.spawn(_run_tests, ctx, refspec, role, tests, File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/parallel.py", line 84, in __exit__ for result in self: File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/parallel.py", line 98, in __next__ resurrect_traceback(result) File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/parallel.py", line 30, in resurrect_traceback raise exc.exc_info[1] File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/parallel.py", line 23, in capture_traceback return func(*args, **kwargs) File "/home/teuthworker/src/github.com_idryomov_ceph_d158d6409994693da5611f9b5747b4ca30fcbcf6/qa/tasks/workunit.py", line 423, in _run_tests remote.run( File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/orchestra/remote.py", line 525, in run r = self._runner(client=self.ssh, name=self.shortname, **kwargs) File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/orchestra/run.py", line 455, in run r.wait() File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/orchestra/run.py", line 161, in wait self._raise_for_status() File "/home/teuthworker/src/git.ceph.com_teuthology_19d18db866afdc31fd6586f558fc29b95a87ccfb/teuthology/orchestra/run.py", line 181, in _raise_for_status raise CommandFailedError( teuthology.exceptions.CommandFailedError: Command failed (workunit test rbd/cli_generic.sh) on smithi027 with status 1: '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=d158d6409994693da5611f9b5747b4ca30fcbcf6 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 CEPH_MNT=/home/ubuntu/cephtest/mnt.0 adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 3h /home/ubuntu/cephtest/clone.client.0/qa/workunits/rbd/cli_generic.sh' </pre><pre> </pre> <pre> rbd rm rbd2/ns1/test1 for i in `seq 12`; do rbd mirror snapshot schedule status | grep 'rbd2/ns1/test1' || break sleep 10 done rbd mirror snapshot schedule status | expect_fail grep 'rbd2/ns1/test1' </pre> One the first iteration "rbd mirror snapshot schedule status" unexpectedly produced no output, letting the control to break out of the loop too early. https://pulpito.ceph.com/dis-2023-01-17_16:09:39-rbd-pacific_16.2.11_RC6.6-distro-default-smithi/7143931