tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestJSON.test_list_servers_by_changes_since fails sporadically

[Peter Portante]

See: http://logs.openstack.org/69/49169/2/check/check-tempest-devstack-vm-full/473539f/console.html

2013-10-07 18:57:09.859 | ======================================================================
2013-10-07 18:57:09.859 | FAIL: tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestJSON.test_list_servers_by_changes_since[gate]
2013-10-07 18:57:09.860 | tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestJSON.test_list_servers_by_changes_since[gate]
2013-10-07 18:57:09.860 | ----------------------------------------------------------------------
2013-10-07 18:57:09.860 | _StringException: Empty attachments:
2013-10-07 18:57:09.861 | stderr
2013-10-07 18:57:09.861 | stdout
2013-10-07 18:57:09.861 |
2013-10-07 18:57:09.862 | pythonlogging:'': {{{
2013-10-07 18:57:09.862 | 2013-10-07 18:38:33,059 Request: GET http://127.0.0.1:8774/v2/3b02395d4eec44958ffcc10ac2673fd2/servers?changes-since=2013-10-07T18%3A38%3A31.034080
2013-10-07 18:57:09.862 | 2013-10-07 18:38:33,490 Response Status: 200
2013-10-07 18:57:09.863 | 2013-10-07 18:38:33,490 Nova request id: req-906f2cf2-6508-4cd2-bf62-3595b18d223a
2013-10-07 18:57:09.863 | }}}
2013-10-07 18:57:09.863 |
2013-10-07 18:57:09.863 | Traceback (most recent call last):
2013-10-07 18:57:09.864 | File "tempest/api/compute/servers/test_list_servers_negative.py", line 191, in test_list_servers_by_changes_since
2013-10-07 18:57:09.864 | self.assertEqual(num_expected, len(body['servers']))
2013-10-07 18:57:09.864 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 322, in assertEqual
2013-10-07 18:57:09.865 | self.assertThat(observed, matcher, message)
2013-10-07 18:57:09.865 | File "/usr/local/lib/python2.7/dist-packages/testtools/testcase.py", line 417, in assertThat
2013-10-07 18:57:09.865 | raise MismatchError(matchee, matcher, mismatch, verbose)
2013-10-07 18:57:09.865 | MismatchError: 3 != 2

[Ken'ichi Ohmichi (oomichi)]

Now we have additional debug message for this problem.
The debug message is the following:

MismatchError: 3 != 2: Number of servers 3 is wrong in [{'link': {'href': '<a href='http://127.0.0.1:8774/a6f85b737f9e47e7ab7cebe30e028222/servers/6c5d0fa3-ae9a-4a94-b31f-ad3ca7d453db'>http://127.0.0.1:8774/a6f85b737f9e47e7ab7cebe30e028222/servers/6c5d0fa3-ae9a-4a94-b31f-ad3ca7d453db</a>', 'rel': 'bookmark'}, 'name': 'ListServersNegativeTestXML-instance-tempest-1601877588', 'id': '6c5d0fa3-ae9a-4a94-b31f-ad3ca7d453db'}, {'link': {'href': '<a href='http://127.0.0.1:8774/a6f85b737f9e47e7ab7cebe30e028222/servers/4c613cc8-6754-4f87-91cf-4aa2f6828a22'>http://127.0.0.1:8774/a6f85b737f9e47e7ab7cebe30e028222/servers/4c613cc8-6754-4f87-91cf-4aa2f6828a22</a>', 'rel': 'bookmark'}, 'name': 'ListServersNegativeTestXML-instance-tempest-569720341', 'id': '4c613cc8-6754-4f87-91cf-4aa2f6828a22'}]

[Ken'ichi Ohmichi (oomichi)]

This test scenario is the following steps:

1. Get a timestamp(TM01) which will be passed as "changes-since" parameter of list-server API.
2. Create 1st server(VM01).
3. Create 2nd server(VM02).
4. Create 3rd server(VM03).
5. Delete 3rd server.
6. Call list-server API with the timestamp(TM01) as "changes-since" parameter.
7. Check it is possible to get all servers(VM01, VM02, VM03).

According to http://logs.openstack.org/93/59093/1/check/check-tempest-devstack-vm-full/20c041b/ ,
we could not get VM01 and this test failed on step 7.

This problem happens if VM01 creation(step 2.) finishes in the same second as TM01.
For example, the following timestamps is not problem.

1. (20:21:19.247) Get a timestamp(TM01)
2. (20:21:20.247) Create 1st server(VM01).

However, this problem happens if the following timestamps:

1. (20:21:19.247) Get a timestamp(TM01)
2. (20:21:19.805) Create 1st server(VM01).

The above timestamps are the ones of http://logs.openstack.org/93/59093/1/check/check-tempest-devstack-vm-full/20c041b/ ,
and step 1. and step 2. are in the same second(20:21:19).

The reason is Nova implementation of list-server API.
changes-since is implemented with the following code:

nova/db/sqlalchemy/api.py
 1877 query_prefix = query_prefix.\
 1878 filter(models.Instance.updated_at > changes_since)

In addition, "updated_at" of "instances" table is defined as datetime from mysql.
 mysql> desc instances;
 +--------------------------+-----------------------+------+-----+---------+----------------+
 | Field | Type | Null | Key | Default | Extra |
 +--------------------------+-----------------------+------+-----+---------+----------------+
 | created_at | datetime | YES | | NULL | |
 | updated_at | datetime | YES | | NULL | |
 [..]
 +--------------------------+-----------------------+------+-----+---------+----------------+

The data type does not contain millisecond.
So if step 1. and step 2. are in the same second, it is impossible to know the timestamp difference
and "filter(models.Instance.updated_at > changes_since)" filters VM01.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/60158

[Ken'ichi Ohmichi (oomichi)]

The patch is in review process.

https://review.openstack.org/#/c/60157/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/60157
Committed: http://github.com/openstack/nova/commit/d87bd44d0211a633efd545dc7b2027a613897b85
Submitter: Jenkins
Branch: master

commit d87bd44d0211a633efd545dc7b2027a613897b85
Author: Ken'ichi Ohmichi <email address hidden>
Date: Thu Dec 5 23:43:32 2013 +0900

    Fix changes-since filter for list-servers API

    On list-servers API, "changes-since" parameter filters out servers
    which have been created at the same date as the specified timestamp.
    For example, the following server is filtered out with "changes-since=
    2013-12-05T15:03:25":

      mysql> select display_name, updated_at from instances;
      +--------------+---------------------+
      | display_name | updated_at |
      +--------------+---------------------+
      | vm01 | 2013-12-05 15:03:25 |
      +--------------+---------------------+

    This bug causes some Tempest test failures, if the timestamp of server
    creations are the same as the "changes-since" timestamp in second unit.
    In addition, the behavior would be wrong from the viewpoint of its name
    which includes "since".

    This patch chanegs the server list for including the ones created at
    the specified timestamp.

    Change-Id: Icc10a1363503b3553d810c6be20b86b3da7ac1a0
    Closes-Bug: #1236585

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/73231

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/73231
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=3f72ffb2109d286d9cff62dca79459b0a8036a1f
Submitter: Jenkins
Branch: stable/havana

commit 3f72ffb2109d286d9cff62dca79459b0a8036a1f
Author: Ken'ichi Ohmichi <email address hidden>
Date: Thu Dec 5 23:43:32 2013 +0900

    Fix changes-since filter for list-servers API

    On list-servers API, "changes-since" parameter filters out servers
    which have been created at the same date as the specified timestamp.
    For example, the following server is filtered out with "changes-since=
    2013-12-05T15:03:25":

      mysql> select display_name, updated_at from instances;
      +--------------+---------------------+
      | display_name | updated_at |
      +--------------+---------------------+
      | vm01 | 2013-12-05 15:03:25 |
      +--------------+---------------------+

    This bug causes some Tempest test failures, if the timestamp of server
    creations are the same as the "changes-since" timestamp in second unit.
    In addition, the behavior would be wrong from the viewpoint of its name
    which includes "since".

    This patch chanegs the server list for including the ones created at
    the specified timestamp.

    Change-Id: Icc10a1363503b3553d810c6be20b86b3da7ac1a0
    Closes-Bug: #1236585
    (cherry picked from commit d87bd44d0211a633efd545dc7b2027a613897b85)