qemu-e2k/tests/qemu-iotests/219.out
Sergio Lopez 2288ccfac9 blockdev: unify qmp_drive_backup and drive-backup transaction paths
Issuing a drive-backup from qmp_drive_backup takes a slightly
different path than when it's issued from a transaction. In the code,
this is manifested as some redundancy between do_drive_backup() and
drive_backup_prepare().

This change unifies both paths, merging do_drive_backup() and
drive_backup_prepare(), and changing qmp_drive_backup() to create a
transaction instead of calling do_backup_common() direcly.

As a side-effect, now qmp_drive_backup() is executed inside a drained
section, as it happens when creating a drive-backup transaction. This
change is visible from the user's perspective, as the job gets paused
and immediately resumed before starting the actual work.

Also fix tests 141, 185 and 219 to cope with the extra
JOB_STATUS_CHANGE lines.

Signed-off-by: Sergio Lopez <slp@redhat.com>
Reviewed-by: Kevin Wolf <kwolf@redhat.com>
Signed-off-by: Kevin Wolf <kwolf@redhat.com>
2020-01-27 17:19:53 +01:00

336 lines
28 KiB
Plaintext

Launching VM...
Starting block job: drive-mirror (auto-finalize: True; auto-dismiss: True)
{"return": {}}
{"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "mirror"}]}
{"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
Pause/resume in RUNNING
=== Testing block-job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
=== Testing block-job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
=== Testing job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
=== Testing job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "mirror"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"return": {}}
Waiting for READY state...
{"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
Pause/resume in READY
=== Testing block-job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
=== Testing block-job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
=== Testing job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
=== Testing job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "standby"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "standby", "total-progress": 4194304, "type": "mirror"}]}
{"return": {}}
{"data": {"id": "job0", "status": "ready"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "ready", "total-progress": 4194304, "type": "mirror"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'ready' cannot accept command verb 'dismiss'"}}
{"return": {}}
Waiting for PENDING state...
{"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": []}
Starting block job: drive-backup (auto-finalize: True; auto-dismiss: True)
{"return": {}}
{"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
{"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
Pause/resume in RUNNING
=== Testing block-job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing block-job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"return": {}}
Waiting for PENDING state...
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": []}
Starting block job: drive-backup (auto-finalize: True; auto-dismiss: False)
{"return": {}}
{"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
{"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
Pause/resume in RUNNING
=== Testing block-job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing block-job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"return": {}}
Waiting for PENDING state...
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "concluded", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
{"return": {}}
{"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": []}
Starting block job: drive-backup (auto-finalize: False; auto-dismiss: True)
{"return": {}}
{"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
{"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
Pause/resume in RUNNING
=== Testing block-job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing block-job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"return": {}}
Waiting for PENDING state...
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "pending", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
{"return": {}}
{"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": []}
Starting block job: drive-backup (auto-finalize: False; auto-dismiss: False)
{"return": {}}
{"return": [{"current-progress": "FILTERED", "id": "job0", "status": "running", "total-progress": "FILTERED", "type": "backup"}]}
{"data": {"id": "job0", "status": "created"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
Pause/resume in RUNNING
=== Testing block-job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 65536, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing block-job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 131072, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/block-job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 196608, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
=== Testing job-pause/job-resume ===
{"return": {}}
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 262144, "id": "job0", "status": "paused", "total-progress": 4194304, "type": "backup"}]}
{"return": {}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 327680, "id": "job0", "status": "running", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'running' cannot accept command verb 'dismiss'"}}
{"return": {}}
Waiting for PENDING state...
{"data": {"id": "job0", "status": "paused"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "running"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "waiting"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"data": {"id": "job0", "status": "pending"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "pending", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'pending' cannot accept command verb 'dismiss'"}}
{"return": {}}
{"data": {"id": "job0", "status": "concluded"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": [{"current-progress": 4194304, "id": "job0", "status": "concluded", "total-progress": 4194304, "type": "backup"}]}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'pause'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'complete'"}}
{"error": {"class": "GenericError", "desc": "Job 'job0' in state 'concluded' cannot accept command verb 'finalize'"}}
{"return": {}}
{"data": {"id": "job0", "status": "null"}, "event": "JOB_STATUS_CHANGE", "timestamp": {"microseconds": "USECS", "seconds": "SECS"}}
{"return": []}