OVS-agent: AttributeError: 'NoneType' object has no attribute 'update'

[YAMAMOTO Takashi]

change I90b4d2485e3e491f496dfb7bdee03d57f393be35 seems failing to handle cases where db_get_val returns None gracefully.

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOiBcIkF0dHJpYnV0ZUVycm9yOiAnTm9uZVR5cGUnIG9iamVjdCBoYXMgbm8gYXR0cmlidXRlICd1cGRhdGUnXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MzE2NjIyOTg1NDZ9

[req-e235481e-8981-4f15-bf62-0c47b97505dd None None] Error while processing VIF ports
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Traceback (most recent call last):
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1643, in rpc_loop
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent ovs_restarted)
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1412, in process_network_ports
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent devices_added_updated, ovs_restarted))
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1318, in treat_devices_added_or_updated
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1220, in treat_vif_port
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent fixed_ips, device_owner, ovs_restarted)
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 730, in port_bound
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent port_other_config.update(vlan_mapping)
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent AttributeError: 'NoneType' object has no attribute 'update'
2015-05-15 03:36:33.954 4996 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent

[OpenStack Infra (hudson-openstack)]

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

[Matt Riedemann (mriedem)]

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

[Armando Migliaccio (armando-migliaccio)]

This is annoying and we should bump it

[Matt Riedemann (mriedem)]

We see this nearly 2000 times in 7 days in the CI system, it shouldn't take 6+ months to fix an AttributeError on NoneType in the CI system:

http://goo.gl/YlrYFj

[Armando Migliaccio (armando-migliaccio)]

This isn't High ([1]): this is nothing else but log noise, it shouldn't have fallen through the cracks, but I see no critical loss of feature here that warrants this severity. Surely we'll get it addressed asap, but I think LP Importance hints are misleading.

https://wiki.openstack.org/wiki/Bugs#Importance

[Armando Migliaccio (armando-migliaccio)]

From what I can tell this happens because of a concurrent delete. As shown in [1,2], port_update and port_delete happens in the span of half a second; they may interleave causing the former to fail because of the latter.

[1] http://logs.openstack.org/77/232077/1/check/gate-tempest-dsvm-neutron-full/0b26eff/logs/screen-q-agt.txt.gz?#_2015-10-07_17_54_58_226
[2] http://logs.openstack.org/77/232077/1/check/gate-tempest-dsvm-neutron-full/0b26eff/logs/screen-q-agt.txt.gz?#_2015-10-07_17_55_00_355

[Armando Migliaccio (armando-migliaccio)]

Confirmed initial analysis as done in [1]

[1] https://review.openstack.org/#/c/183443/8/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Elena Ezhova (<email address hidden>) on branch: master
Review: https://review.openstack.org/183443
Reason: Abandoned in favor of https://review.openstack.org/#/c/234989/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/234989
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=a8d20e05079903a3fb2e952b7ec2c4cf27b208e9
Submitter: Jenkins
Branch: master

commit a8d20e05079903a3fb2e952b7ec2c4cf27b208e9
Author: armando-migliaccio <email address hidden>
Date: Wed Oct 14 14:27:09 2015 -0700

    Fix AttributeError on port_bound for missing ports

    If the port is concurrently deleted, db_get_val returns None, and
    that causes the Exception to be raised. However, the exception is just
    log noise if the port has been deleted concurrently and it does not
    lead to failures.

    This can happen if port_update and port_delete operations occur
    in short sequence and interleave. To prevent this trace from
    occurring, this patch checks that the port is being eliminated and
    emits an error trace only if the port is indeed to be expected
    amongst the list of ports to be updated.

    We do not raise an exception to avoid disrupting the agent sync
    process, and leave to the admin the investigation of the issue
    (should that be cronic rather than transient).

    Under normal circumstances, if the port is expected it should
    be there, and if it isn't this should be treated as a bug to be
    investigated further.

    Closes-bug: #1455320

    Change-Id: Ic609af0ef6a09b536c882c58c23167c0a469b155

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/237836

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/238296

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/238296
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f50e59caf3f9b1bde107b2ca47c5fb7e26587e56
Submitter: Jenkins
Branch: master

commit f50e59caf3f9b1bde107b2ca47c5fb7e26587e56
Author: armando-migliaccio <email address hidden>
Date: Wed Oct 21 17:47:47 2015 -0700

    Minor improvement in port_bound operation

    By returning the need for binding, the (no-op) port processing
    is skipped in the main sync loop. In fact, the port is already
    detected as deleted and avoiding going over it again will save
    us one log message, and thus many, many, many, many bytes over
    time in logs.openstack.org.

    If this is not an improvement, I don't what is.

    Related-bug: 1455320

    Change-Id: I4ef30bed6a1619f5980c3e61ee23ffb808c2c4f0

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/237836
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=5d7c34e77022f725a7d9711526aca83534b84332
Submitter: Jenkins
Branch: stable/liberty

commit 5d7c34e77022f725a7d9711526aca83534b84332
Author: armando-migliaccio <email address hidden>
Date: Wed Oct 14 14:27:09 2015 -0700

    Fix AttributeError on port_bound for missing ports

    If the port is concurrently deleted, db_get_val returns None, and
    that causes the Exception to be raised. However, the exception is just
    log noise if the port has been deleted concurrently and it does not
    lead to failures.

    This can happen if port_update and port_delete operations occur
    in short sequence and interleave. To prevent this trace from
    occurring, this patch checks that the port is being eliminated and
    emits an error trace only if the port is indeed to be expected
    amongst the list of ports to be updated.

    We do not raise an exception to avoid disrupting the agent sync
    process, and leave to the admin the investigation of the issue
    (should that be cronic rather than transient).

    Under normal circumstances, if the port is expected it should
    be there, and if it isn't this should be treated as a bug to be
    investigated further.

    Closes-bug: #1455320

    Change-Id: Ic609af0ef6a09b536c882c58c23167c0a469b155
    (cherry picked from commit a8d20e05079903a3fb2e952b7ec2c4cf27b208e9)

[Matt Riedemann (mriedem)]

logstash looks much happier now. Thanks for getting this resolved.