TestHelpers.StartFullTest fails on Value of: state_values["percent-done"].toFloat() > 1.0

[Charles Kerr]

https://jenkins.canonical.com/unity-api-1/job/build-2-binpkg/arch=i386,release=xenial+overlay/258/console

18:00:53 Retrieving connection
18:00:53 Is valid: true
18:00:53 [debug] Helper::StartBackup(n_bytes=512) (src/service/keeper.cpp:413)
18:00:53 [debug] id: "/tmp/helpers-test-failure-YyB4bc/storage-framework" (src/storage-framework/storage_framework_client.cpp:54)
18:00:53 [debug] time: QDateTime(2016-08-18 18:00:52.847 UTC Qt::TimeSpec(LocalTime)) (src/storage-framework/storage_framework_client.cpp:55)
18:00:53 [debug] waiting for worker thread to initialize (:0)
18:00:53 [debug] worker thread ready (:0)
18:00:53 [debug] getNewFileForBackup() returned socket 16 (src/service/keeper.cpp:420)
18:00:53 [debug] calling helper.set_storage_framework_socket(n_bytes=512 socket=16) (src/service/keeper.cpp:421)
18:00:53 [debug] changing state of helper 0x8350490 from "complete" to "started" (src/helper/helper.cpp:155)
18:00:53 [debug] Backup helper started (src/service/keeper.cpp:160)
18:00:53 wrote 513 bytes
18:00:53 [debug] upload_buffer_.size() is 513 after reading 513 from helper (src/helper/backup-helper.cpp:178)
18:00:53 [debug] upload_buffer_.size() is 0 after writing 513 to cloud (src/helper/backup-helper.cpp:191)
18:00:53 [debug] emitting percent-done-changed 1.00195 (src/helper/helper.cpp:212)
18:00:53 [CRITICAL] no task data for "" (src/service/keeper.cpp:263)
18:00:53 [debug] n_read 513 n_uploaded 513 (newly uploaded 513) (src/helper/backup-helper.cpp:162)
18:00:53 (process:7298): libdbustest-DEBUG: Waiting on name from DBusMock
18:00:53 (process:7298): libdbustest-DEBUG: Add object (org.linuxcontainers.cgmanager0_0) on '/org/linuxcontainers/cgmanager'
18:00:53 DBusMock : 1471543252.839 GetJobByName "untrusted-helper"
18:00:53 DBusMock : 1471543252.840 Start ["APP_ID=dekko.dekkoproject_dekko_0.6.20", "HELPER_TYPE=backup-helper", "APP_URIS='/��BUILDDIR��/keeper-0.0.1+xenial328bzr99/obj-i686-linux-gnu/tests/fakes/fake-backup-helper-failure' '/tmp/helpers-test-failure-2mqZg7/Music'", "INSTANCE_ID=1471543252838573"] True
18:00:53 DBusMock : 1471543252.843 emit com.ubuntu.Upstart0_6.EventEmitted "stopped" ["JOB=untrusted-helper", "INSTANCE=backup-helper::dekko.dekkoproject_dekko_0.6.20"]
18:00:53 [debug] storage framework directory is "/tmp/helpers-test-failure-YyB4bc/storage-framework" (tests/integration/helpers/test-helpers-base.cpp:354)
18:00:53 /��BUILDDIR��/keeper-0.0.1+xenial328bzr99/tests/integration/helpers/helpers-test-failure.cpp:86: Failure
18:00:53 Value of: ([]() -> QString { enum { Size = sizeof(u"" "failed")/2 - 1 }; static const QStaticStringData<Size> qstring_literal = { { { { (-1) } }, Size, 0, 0, sizeof(QStringData) }, u"" "failed" }; QStringDataPtr holder = { qstring_literal.data_ptr() }; const QString qstring_literal_temp(holder); return qstring_literal_temp; }())
18:00:53 Actual: { 2-byte object <66-00>, 2-byte object <61-00>, 2-byte object <69-00>, 2-byte object <6C-00>, 2-byte object <65-00>, 2-byte object <64-00> }
18:00:53 Expected: state_values["action"].toString()
18:00:53 Which is: { 2-byte object <63-00>, 2-byte object <6F-00>, 2-byte object <6D-00>, 2-byte object <70-00>, 2-byte object <6C-00>, 2-byte object <65-00>, 2-byte object <74-00>, 2-byte object <65-00> }
18:00:53 /��BUILDDIR��/keeper-0.0.1+xenial328bzr99/tests/integration/helpers/helpers-test-failure.cpp:89: Failure
18:00:53 Value of: state_values["percent-done"].toFloat() > 1.0
18:00:53 Actual: false
18:00:53 Expected: true
18:00:53 Keeper: Shutting down

[Charles Kerr (charlesk)]

Looks like the problem is the new state-keeping in the Keeper class is working too well. This test is trying to confirm we get a progress of > 1.0 for a task when we send an extra byte, but the state-keeping code has already marked the task as complete and erased the current_task variable.

So we probably need to update this test to exercise failure in some different way.

This is also revealing a related second bug though: what would happen if there was another task queued such that current_task was changed not to "" but to the next uuid? We'd be marking /its/ percent-done as > 1.0 and prematurely interrupting it.