MigrationExportSuite.TestUnits unequal results

[Curtis Hovey]

As seen in
    http://reports.vapour.ws/releases/issue/57236866749a5631dd9859a3

MigrationExportSuite.TestUnits unequal results in windows using go 1.6

migration_export_test.go:102:
    c.Check(st.Data(), jc.DeepEquals, map[string]interface{}{"index": i + 1})
... obtained map[string]interface {} = map[string]interface {}{"index":4}
... expected map[string]interface {} = map[string]interface {}{"index":1}
... mismatch at ["index"]: unequal; obtained 4; expected 1

migration_export_test.go:223:
    s.checkStatusHistory(c, history[:addedHistoryCount], status.StatusStarted)
migration_export_test.go:102:
    c.Check(st.Data(), jc.DeepEquals, map[string]interface{}{"index": i + 1})
... obtained map[string]interface {} = map[string]interface {}{"index":3}
... expected map[string]interface {} = map[string]interface {}{"index":2}
... mismatch at ["index"]: unequal; obtained 3; expected 2

migration_export_test.go:223:
    s.checkStatusHistory(c, history[:addedHistoryCount], status.StatusStarted)
migration_export_test.go:102:
    c.Check(st.Data(), jc.DeepEquals, map[string]interface{}{"index": i + 1})
... obtained map[string]interface {} = map[string]interface {}{"index":2}
... expected map[string]interface {} = map[string]interface {}{"index":3}
... mismatch at ["index"]: unequal; obtained 2; expected 3

migration_export_test.go:223:
    s.checkStatusHistory(c, history[:addedHistoryCount], status.StatusStarted)
migration_export_test.go:102:
    c.Check(st.Data(), jc.DeepEquals, map[string]interface{}{"index": i + 1})
... obtained map[string]interface {} = map[string]interface {}{"index":1}
... expected map[string]interface {} = map[string]interface {}{"index":4}
... mismatch at ["index"]: unequal; obtained 1; expected 4

The three failing tests are
    MigrationExportSuite.TestUnits
    MigrationExportSuite.TestMachines
    MigrationExportSuite.TestServices

[Eric Snow (ericsnowcurrently)]

Thus far I see a number of possibilities here:

1. the timestamps on the status entries do not align with the order with which they were originally added by the test
2. mgo's Query.Sort() is not getting the order right
3. mgo's Query.Iter() is not preserving the order correctly
4. slice iteration is not preserving order correctly

None of those seem likely, so I'm probably missing something.

[Eric Snow (ericsnowcurrently)]

This may be an issue of clock resolution on Windows (15.6 ms by default). It's very likely that some or all of the status history additions happen within the same clock tick, meaning that any sorting on the timestamp (which is what we do) is unreliably ordered.

Assuming this analysis is correct, we can resolve this through tiny sleeps or through using testing.Clock. Since we want the actual status history to have the correct order, fixing just the tests probably isn' t good enough.

[Eric Snow (ericsnowcurrently)]

Here's a patch that should fix this if it is related to Windows clock resolution.

http://reviews.vapour.ws/r/4746/

[Eric Snow (ericsnowcurrently)]

The patch merged but I'm going to wait for the Windows tests to run before marking this bug as fix-committed.

[Eric Snow (ericsnowcurrently)]

Per "run-unit-tests-win2012-amd64" on http://reports.vapour.ws/releases/3939, this has been resolved.