yahoo-eng-team team mailing list archive

[Salvatore Orlando <1357055@xxxxxxxxxxxxxxxxxx>]

I came to the same conclusions as Alex: the servers are not deleted
hence the error.

However, the logging which Alex is claiming for is already there.
Indeed here are the delete operations on teardown for a failing test:

salvatore@trustillo:~$ cat tempest.txt.gz | grep -i ServerRescueNegativeTestJSON.*tearDownClass.*DELETE
2014-10-07 17:49:04.444 25908 INFO tempest.common.rest_client [req-75c758b3-d8cb-48d6-9cb6-3670147aca41 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 202 DELETE http://127.0.0.1:8774/v2/829473406bb545c895a5cd0320624812/os-volumes/ffc44446-ba25-413d-8ff1-839d3643299d 0.135s
2014-10-07 17:49:04.444 25908 DEBUG tempest.common.rest_client [req-75c758b3-d8cb-48d6-9cb6-3670147aca41 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 202 DELETE http://127.0.0.1:8774/v2/829473406bb545c895a5cd0320624812/os-volumes/ffc44446-ba25-413d-8ff1-839d3643299d 0.135s
2014-10-07 17:52:21.452 25908 INFO tempest.common.rest_client [req-d0fa5615-9e64-4faa-bd8d-2ad1ac6afb53 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:9696/v2.0/routers/0ecd1539-70af-4500-aa4d-9e131fa1fffc 0.238s
2014-10-07 17:52:21.452 25908 DEBUG tempest.common.rest_client [req-d0fa5615-9e64-4faa-bd8d-2ad1ac6afb53 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:9696/v2.0/routers/0ecd1539-70af-4500-aa4d-9e131fa1fffc 0.238s
2014-10-07 17:52:21.513 25908 INFO tempest.common.rest_client [req-89562c45-7448-41bb-8e3e-0beec8460aab None] Request (ServerRescueNegativeTestJSON:tearDownClass): 409 DELETE http://127.0.0.1:9696/v2.0/subnets/9614d778-66b3-4b81-83fc-f7a47602ceb2 0.060s
2014-10-07 17:52:21.514 25908 DEBUG tempest.common.rest_client [req-89562c45-7448-41bb-8e3e-0beec8460aab None] Request (ServerRescueNegativeTestJSON:tearDownClass): 409 DELETE http://127.0.0.1:9696/v2.0/subnets/9614d778-66b3-4b81-83fc-f7a47602ceb2 0.060s


No DELETE server command is specified.
Instead for a successful test the two servers are deleted.

2014-09-26 11:48:05.532 7755 INFO tempest.common.rest_client [req-6d9072aa-dbcb-4398-b4c4-46aeb2140e4b None] Request (ServerRescueNegativeTestJSON:tearDownClass): 202 DELETE http://127.0.0.1:8774/v2/0cdef32ce1b746fa957a013a3638b3ec/os-volumes/a24f4dc2-bfb5-4a60-be05-9051f08cc447 0.086s
2014-09-26 11:50:06.733 7755 INFO tempest.common.rest_client [req-f3752c9f-8de5-4bde-98c9-879c5a37ff44 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:8774/v2/0cdef32ce1b746fa957a013a3638b3ec/servers/1d754b6e-128f-4b42-88ab-9dbefedd887f 0.155s
2014-09-26 11:50:06.882 7755 INFO tempest.common.rest_client [req-dcb05efc-229a-4f40-ac67-2e95a80373c0 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:8774/v2/0cdef32ce1b746fa957a013a3638b3ec/servers/d26d1144-58d2-4900-93af-bf7fecdd7a60 0.148s
2014-09-26 11:50:09.531 7755 INFO tempest.common.rest_client [req-73246abe-5e0e-4d16-88dc-75ca05593b2c None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:9696/v2.0/routers/755eeb0d-6eb8-4acd-b36d-91bd4787cf4e 0.180s
2014-09-26 11:50:09.583 7755 INFO tempest.common.rest_client [req-549a5b98-dbb1-43ae-b4ce-f8182ebc10e2 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:9696/v2.0/subnets/999c8033-7684-4fc0-a09e-1ccb70196278 0.051s
2014-09-26 11:50:09.662 7755 INFO tempest.common.rest_client [req-c74637c0-f985-42c4-b5b0-f980bc431858 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:9696/v2.0/networks/ef773f01-7b53-4207-bc75-120563f36d7f 0.078s
2014-09-26 11:50:09.809 7755 INFO tempest.common.rest_client [-] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:35357/v2.0/users/fe26c8cb709644e1862d1b69c63b802b 0.146s
2014-09-26 11:50:09.877 7755 INFO tempest.common.rest_client [req-ea281fc3-70e2-487d-977b-7aa65db86722 None] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:9696/v2.0/security-groups/10b16895-5b18-48c5-88e4-9c384eb9d1b8 0.043s
2014-09-26 11:50:10.016 7755 INFO tempest.common.rest_client [-] Request (ServerRescueNegativeTestJSON:tearDownClass): 204 DELETE http://127.0.0.1:35357/v2.0/tenants/0cdef32ce1b746fa957a013a3638b3ec 0.137s

This happens consistently.
Also note that in the case of the failing tests the same events are logged both at DEBUG and INFO level. This might indicate that some concurrency problem among test runners is probably installing an additional log handler, but I have no idea whether this is even possible.
What is probably happening is that the servers class variable gets resetted, and therefore the servers are not removed on resource_cleanup.

However, this still has to be proved. Further logging might be added to
this aim, which might be helpful to validate this hypothesis (I could
not find any clue through static code and log analysis).

Finally, I reckon I have enough elements to declare this is NOT a
neutron bug, and I'm removing neutron from affected projects. I'd do the
same for nova, but I don't have the rights to do that.


** No longer affects: neutron

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1357055

Title:
  Race to delete shared subnet in Tempest neutron full jobs

Status in OpenStack Compute (Nova):
  Fix Released
Status in Tempest:
  New

Bug description:
  This seems to show up in several different tests, basically anything
  using neutron.  I noticed it here:

  http://logs.openstack.org/89/112889/1/gate/check-tempest-dsvm-neutron-
  full/21fcf50/console.html#_2014-08-14_17_03_10_330

  That's on a stable/icehouse change, but logstash shows this on master
  mostly.

  I see this in the neutron server logs:

  http://logs.openstack.org/89/112889/1/gate/check-tempest-dsvm-neutron-
  full/21fcf50/logs/screen-q-svc.txt.gz#_2014-08-14_16_45_02_101

  This query shows 82 hits in 10 days:

  message:"delete failed \(client error\)\: Unable to complete operation
  on subnet" AND message:"One or more ports have an IP allocation from
  this subnet" AND tags:"screen-q-svc.txt"

  http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiZGVsZXRlIGZhaWxlZCBcXChjbGllbnQgZXJyb3JcXClcXDogVW5hYmxlIHRvIGNvbXBsZXRlIG9wZXJhdGlvbiBvbiBzdWJuZXRcIiBBTkQgbWVzc2FnZTpcIk9uZSBvciBtb3JlIHBvcnRzIGhhdmUgYW4gSVAgYWxsb2NhdGlvbiBmcm9tIHRoaXMgc3VibmV0XCIgQU5EIHRhZ3M6XCJzY3JlZW4tcS1zdmMudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6ImN1c3RvbSIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJmcm9tIjoiMjAxNC0wNy0zMVQxOTo0Mzo0NSswMDowMCIsInRvIjoiMjAxNC0wOC0xNFQxOTo0Mzo0NSswMDowMCIsInVzZXJfaW50ZXJ2YWwiOiIwIn0sInN0YW1wIjoxNDA4MDQ1NDY1OTU2fQ==

  Logstash doesn't show this in the gate queue but it does show up in
  the uncategorized bugs list which is in the gate queue.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1357055/+subscriptions