tests/qemu-iotests/219.out

   1 Launching VM...
   2
   3
   4 Starting block job: drive-mirror (auto-finalize: True; auto-dismiss: True)
   5 {"return": {}}
   6 {"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "mirror"}]}
   7 {"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
   8 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
   9
  10 Pause/resume in RUNNING
  11 === Testing block-job-pause/block-job-resume ===
  12 {"return": {}}
  13 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  14 {"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
  15 {"return": {}}
  16 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  17 {"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
  18 === Testing block-job-pause/job-resume ===
  19 {"return": {}}
  20 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  21 {"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
  22 {"return": {}}
  23 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  24 {"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
  25 === Testing job-pause/block-job-resume ===
  26 {"return": {}}
  27 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  28 {"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
  29 {"return": {}}
  30 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  31 {"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
  32 === Testing job-pause/job-resume ===
  33 {"return": {}}
  34 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  35 {"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
  36 {"return": {}}
  37 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  38 {"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
  39 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
  40 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
  41 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
  42 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
  43 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
  44 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
  45 {"return": {}}
  46
  47 Waiting for READY state...
  48 {"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  49 {"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
  50
  51 Pause/resume in READY
  52 === Testing block-job-pause/block-job-resume ===
  53 {"return": {}}
  54 {"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  55 {"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
  56 {"return": {}}
  57 {"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  58 {"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
  59 === Testing block-job-pause/job-resume ===
  60 {"return": {}}
  61 {"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  62 {"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
  63 {"return": {}}
  64 {"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  65 {"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
  66 === Testing job-pause/block-job-resume ===
  67 {"return": {}}
  68 {"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  69 {"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
  70 {"return": {}}
  71 {"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  72 {"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
  73 === Testing job-pause/job-resume ===
  74 {"return": {}}
  75 {"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  76 {"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
  77 {"return": {}}
  78 {"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  79 {"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
  80 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'finalize'"}}
  81 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'dismiss'"}}
  82 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'finalize'"}}
  83 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'dismiss'"}}
  84 {"return": {}}
  85
  86 Waiting for PENDING state...
  87 {"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  88 {"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  89 {"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  90 {"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  91 {"return": []}
  92
  93
  94 Starting block job: drive-backup (auto-finalize: True; auto-dismiss: True)
  95 {"return": {}}
  96 {"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
  97 {"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  98 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
  99
 100 Pause/resume in RUNNING
 101 === Testing block-job-pause/block-job-resume ===
 102 {"return": {}}
 103 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 104 {"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 105 {"return": {}}
 106 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 107 {"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 108 === Testing block-job-pause/job-resume ===
 109 {"return": {}}
 110 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 111 {"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 112 {"return": {}}
 113 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 114 {"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 115 === Testing job-pause/block-job-resume ===
 116 {"return": {}}
 117 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 118 {"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 119 {"return": {}}
 120 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 121 {"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 122 === Testing job-pause/job-resume ===
 123 {"return": {}}
 124 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 125 {"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 126 {"return": {}}
 127 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 128 {"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 129 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 130 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 131 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 132 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 133 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 134 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 135 {"return": {}}
 136
 137 Waiting for PENDING state...
 138 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 139 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 140 {"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 141 {"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 142 {"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 143 {"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 144 {"return": []}
 145
 146
 147 Starting block job: drive-backup (auto-finalize: True; auto-dismiss: False)
 148 {"return": {}}
 149 {"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
 150 {"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 151 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 152
 153 Pause/resume in RUNNING
 154 === Testing block-job-pause/block-job-resume ===
 155 {"return": {}}
 156 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 157 {"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 158 {"return": {}}
 159 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 160 {"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 161 === Testing block-job-pause/job-resume ===
 162 {"return": {}}
 163 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 164 {"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 165 {"return": {}}
 166 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 167 {"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 168 === Testing job-pause/block-job-resume ===
 169 {"return": {}}
 170 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 171 {"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 172 {"return": {}}
 173 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 174 {"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 175 === Testing job-pause/job-resume ===
 176 {"return": {}}
 177 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 178 {"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 179 {"return": {}}
 180 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 181 {"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 182 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 183 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 184 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 185 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 186 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 187 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 188 {"return": {}}
 189
 190 Waiting for PENDING state...
 191 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 192 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 193 {"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 194 {"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 195 {"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 196 {"return": [{"current-progress": 4194304, "id": "job0", "status": "concluded", "total-progress": 4194304, "type": "backup"}]}
 197 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
 198 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
 199 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
 200 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
 201 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
 202 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
 203 {"return": {}}
 204 {"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 205 {"return": []}
 206
 207
 208 Starting block job: drive-backup (auto-finalize: False; auto-dismiss: True)
 209 {"return": {}}
 210 {"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
 211 {"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 212 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 213
 214 Pause/resume in RUNNING
 215 === Testing block-job-pause/block-job-resume ===
 216 {"return": {}}
 217 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 218 {"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 219 {"return": {}}
 220 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 221 {"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 222 === Testing block-job-pause/job-resume ===
 223 {"return": {}}
 224 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 225 {"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 226 {"return": {}}
 227 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 228 {"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 229 === Testing job-pause/block-job-resume ===
 230 {"return": {}}
 231 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 232 {"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 233 {"return": {}}
 234 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 235 {"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 236 === Testing job-pause/job-resume ===
 237 {"return": {}}
 238 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 239 {"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 240 {"return": {}}
 241 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 242 {"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 243 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 244 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 245 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 246 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 247 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 248 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 249 {"return": {}}
 250
 251 Waiting for PENDING state...
 252 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 253 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 254 {"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 255 {"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 256 {"return": [{"current-progress": 4194304, "id": "job0", "status": "pending", "total-progress": 4194304, "type": "backup"}]}
 257 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
 258 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
 259 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
 260 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
 261 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
 262 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
 263 {"return": {}}
 264 {"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 265 {"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 266 {"return": []}
 267
 268
 269 Starting block job: drive-backup (auto-finalize: False; auto-dismiss: False)
 270 {"return": {}}
 271 {"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
 272 {"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 273 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 274
 275 Pause/resume in RUNNING
 276 === Testing block-job-pause/block-job-resume ===
 277 {"return": {}}
 278 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 279 {"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 280 {"return": {}}
 281 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 282 {"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 283 === Testing block-job-pause/job-resume ===
 284 {"return": {}}
 285 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 286 {"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 287 {"return": {}}
 288 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 289 {"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 290 === Testing job-pause/block-job-resume ===
 291 {"return": {}}
 292 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 293 {"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 294 {"return": {}}
 295 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 296 {"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 297 === Testing job-pause/job-resume ===
 298 {"return": {}}
 299 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 300 {"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
 301 {"return": {}}
 302 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 303 {"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
 304 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 305 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 306 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 307 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
 308 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
 309 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
 310 {"return": {}}
 311
 312 Waiting for PENDING state...
 313 {"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 314 {"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 315 {"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 316 {"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 317 {"return": [{"current-progress": 4194304, "id": "job0", "status": "pending", "total-progress": 4194304, "type": "backup"}]}
 318 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
 319 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
 320 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
 321 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
 322 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
 323 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
 324 {"return": {}}
 325 {"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 326 {"return": [{"current-progress": 4194304, "id": "job0", "status": "concluded", "total-progress": 4194304, "type": "backup"}]}
 327 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
 328 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
 329 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
 330 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
 331 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
 332 {"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
 333 {"return": {}}
 334 {"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
 335 {"return": []}