Comment 4 for bug 1841865

Hi Sapna,

You are looking at the correct log. Let me give you a few pointers:

1) You can add the 'a' option (journalctl -afu <email address hidden>) and that will allow to see the log in color in real time.

2) Often, it is better to remove the 'f' option (journalctl -u <email address hidden>). In this way you are not "following" the log in real time. You start looking at the beginning of the log and you can move up and down the file with vim like commands. You can move up and down with you keyboard arrows. You can search for something with '/'. You can go to the latest record in the log with 'G'. And so on.

3) Have you watched this presentation: https://www.openstack.org/videos/summits/vancouver-2015/neutron-l2-and-l3-agents-how-they-work-and-how-kilo-improves-them? It is a bit old but still describes pretty well the overall working of the L2 agent. You can download the slides here: https://www.slideshare.net/RossellaSblendido/l2-and-l3-agent-restructure

4) Look at any patch in Gerrit, for example https://review.opendev.org/#/c/681200. Under the "Zuul check" section, click on 'neutron-tempest-plugin-scenario-openvswitch' (you could click on any other of the jobs, I'm choosing this as an example), which is the job that performs test for OVS. You will land here: https://zuul.opendev.org/t/openstack/build/3e50fa5807824100833e97c151033a64. Scroll down until you find 'log_url' and click on the url in that line (https://657640e1b74d2ccd83c5-2f55ac5fe50f14ffb2563f318bf721a9.ssl.cf5.rackcdn.com/681200/3/check/neutron-tempest-plugin-scenario-openvswitch/3e50fa5/). There you will notice that you can click on ' testr_results.html.gz' and see the lists of tests performed. You can also click on 'controller' and then on 'logs' and you will land here: https://657640e1b74d2ccd83c5-2f55ac5fe50f14ffb2563f318bf721a9.ssl.cf5.rackcdn.com/681200/3/check/neutron-tempest-plugin-scenario-openvswitch/3e50fa5/controller/logs/. Scroll down and you will find 'screen-q-agt.txt.gz'. Click on it and you will see the log file (https://657640e1b74d2ccd83c5-2f55ac5fe50f14ffb2563f318bf721a9.ssl.cf5.rackcdn.com/681200/3/check/neutron-tempest-plugin-scenario-openvswitch/3e50fa5/controller/logs/screen-q-agt.txt.gz) of the OVS agent where you can see what the OVS agent did as a result of all the tests executed in this job. You can download the log if you want and look at it with 'less' for example.

5) As the presentation in point 3 indicates, the OVS agent (and all the Neutron agents for that matter) have a big loop (method rpc_loop in the case of the OVS agent) that iterates checking if there is some work to do or a signal to respond to. The OVS agent big loop is here: https://github.com/openstack/neutron/blob/88683b76aeefde5a051d9349fac20fedebcea987/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py#L2346.

6) rpc_loop checks here https://github.com/openstack/neutron/blob/88683b76aeefde5a051d9349fac20fedebcea987/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py#L2383 if any ports were added, updated or removed from the integration bridge and if that's the case, it processes them by triggering this chain of calls:

https://github.com/openstack/neutron/blob/88683b76aeefde5a051d9349fac20fedebcea987/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py#L1948 --->

https://github.com/openstack/neutron/blob/88683b76aeefde5a051d9349fac20fedebcea987/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py#L1812

At this point we are in 'treat_devices_added_or_updated'. Note that this method logs a line for each port it processes here: https://github.com/openstack/neutron/blob/88683b76aeefde5a051d9349fac20fedebcea987/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py#L1831. The logged line contains 'Processing port:'. Searching in the OVS agent log that I pointed to in point 4 above for this string, you will notice that each port is processed twice. For example, we can see in the log file this line for port 2d4ac3e7-387d-4523-bfdf-c7d576bfaa24:

Oct 02 12:37:10.676325 ubuntu-bionic-rax-dfw-0012096583 neutron-openvswitch-agent[17459]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-75458b00-07d0-4ea4-be9b-3cfd510852d7 None None] Processing port: 2d4ac3e7-387d-4523-bfdf-c7d576bfaa24 {{(pid=17459) treat_devices_added_or_updated /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1831}}

and 2 seconds later for the same port:

Oct 02 12:37:12.677722 ubuntu-bionic-rax-dfw-0012096583 neutron-openvswitch-agent[17459]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-75458b00-07d0-4ea4-be9b-3cfd510852d7 None None] Processing port: 2d4ac3e7-387d-4523-bfdf-c7d576bfaa24 {{(pid=17459) treat_devices_added_or_updated /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1831}}

This is what this bug is all about. Is this something we should fix? If yes, how?