[NETVIRT-1132] NPE: StateTunnelList_ADTCL handleTunnelEventForDpn: Unable to handle the tunnel event for srcDpnId 110780754426209 srcTepIp 10.30.170.87 remoteDpnId 106567621600656 destTepIp 10.30.170.102 handleTunnelEventForDPN(TunnelInterfaceStateListener.java:340) Created: 06/Mar/18 Updated: 13/Mar/18 Resolved: 13/Mar/18 |
|
| Status: | Resolved |
| Project: | netvirt |
| Component/s: | General |
| Affects Version/s: | Oxygen |
| Fix Version/s: | Oxygen |
| Type: | Bug | Priority: | Medium |
| Reporter: | Sam Hague | Assignee: | Victor Pickard |
| Resolution: | Done | Votes: | 0 |
| Labels: | csit:exception, patch_merged | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
| Description |
|
The exception happens in the add and update paths. Add path is here and later is the update path: 2018-03-06T05:23:47,604 | INFO | org.opendaylight.yang.gen.v1.urn.opendaylight.genius.itm.op.rev160406.tunnels_state.StateTunnelList_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | TunnelInterfaceStateListener | 367 - org.opendaylight.netvirt.vpnmanager-impl - 0.6.0.SNAPSHOT | handleTunnelEventForDPN: Handle tunnel event for srcDpn 110780754426209 SrcTepIp 10.30.170.87 DestTepIp 10.30.170.102 2018-03-06T05:23:47,604 | INFO | org.opendaylight.yang.gen.v1.urn.opendaylight.genius.itm.op.rev160406.tunnels_state.StateTunnelList_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | TunnelInterfaceStateListener | 367 - org.opendaylight.netvirt.vpnmanager-impl - 0.6.0.SNAPSHOT | handleTunnelEventForDPN: Tunnel ADD event received for Dpn 110780754426209 VTEP Ip 10.30.170.87 destTepIp 2018-03-06T05:23:47,604 | INFO | ForkJoinPool-1-worker-1 | ElanTunnelInterfaceStateListener | 348 - org.opendaylight.netvirt.elanmanager-impl - 0.6.0.SNAPSHOT | Handling tunnel state event for srcDpId 110780754426209 and dstDpId 106567621600656 2018-03-06T05:23:47,605 | ERROR | org.opendaylight.yang.gen.v1.urn.opendaylight.genius.itm.op.rev160406.tunnels_state.StateTunnelList_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | TunnelInterfaceStateListener | 367 - org.opendaylight.netvirt.vpnmanager-impl - 0.6.0.SNAPSHOT | handleTunnelEventForDpn: Unable to handle the tunnel event for srcDpnId 110780754426209 srcTepIp 10.30.170.87 remoteDpnId 106567621600656 destTepIp 10.30.170.102 java.lang.NullPointerException: null at org.opendaylight.netvirt.vpnmanager.TunnelInterfaceStateListener.handleTunnelEventForDPN(TunnelInterfaceStateListener.java:340) [367:org.opendaylight.netvirt.vpnmanager-impl:0.6.0.SNAPSHOT] at org.opendaylight.netvirt.vpnmanager.TunnelInterfaceStateListener.add(TunnelInterfaceStateListener.java:217) [367:org.opendaylight.netvirt.vpnmanager-impl:0.6.0.SNAPSHOT] at org.opendaylight.netvirt.vpnmanager.TunnelInterfaceStateListener.add(TunnelInterfaceStateListener.java:76) [367:org.opendaylight.netvirt.vpnmanager-impl:0.6.0.SNAPSHOT] at org.opendaylight.genius.datastoreutils.AsyncDataTreeChangeListenerBase$DataTreeChangeHandler.run(AsyncDataTreeChangeListenerBase.java:167) [260:org.opendaylight.genius.mdsalutil-api:0.4.0.SNAPSHOT] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?] at java.lang.Thread.run(Thread.java:748) [?:?] This also happens in the update path: 2018-03-06T05:23:55,042 | INFO | org.opendaylight.yang.gen.v1.urn.opendaylight.genius.itm.op.rev160406.tunnels_state.StateTunnelList_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | TunnelInterfaceStateListener | 367 - org.opendaylight.netvirt.vpnmanager-impl - 0.6.0.SNAPSHOT | handleTunnelEventForDPN: Tunnel ADD event received for Dpn 110780754426209 VTEP Ip 10.30.170.87 destTepIp 2018-03-06T05:23:55,043 | ERROR | org.opendaylight.yang.gen.v1.urn.opendaylight.genius.itm.op.rev160406.tunnels_state.StateTunnelList_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | TunnelInterfaceStateListener | 367 - org.opendaylight.netvirt.vpnmanager-impl - 0.6.0.SNAPSHOT | handleTunnelEventForDpn: Unable to handle the tunnel event for srcDpnId 110780754426209 srcTepIp 10.30.170.87 remoteDpnId 106567621600656 destTepIp 10.30.170.102 java.lang.NullPointerException: null at org.opendaylight.netvirt.vpnmanager.TunnelInterfaceStateListener.handleTunnelEventForDPN(TunnelInterfaceStateListener.java:340) [367:org.opendaylight.netvirt.vpnmanager-impl:0.6.0.SNAPSHOT] at org.opendaylight.netvirt.vpnmanager.TunnelInterfaceStateListener.update(TunnelInterfaceStateListener.java:169) [367:org.opendaylight.netvirt.vpnmanager-impl:0.6.0.SNAPSHOT] at org.opendaylight.netvirt.vpnmanager.TunnelInterfaceStateListener.update(TunnelInterfaceStateListener.java:76) [367:org.opendaylight.netvirt.vpnmanager-impl:0.6.0.SNAPSHOT] at org.opendaylight.genius.datastoreutils.AsyncDataTreeChangeListenerBase$DataTreeChangeHandler.run(AsyncDataTreeChangeListenerBase.java:172) [260:org.opendaylight.genius.mdsalutil-api:0.4.0.SNAPSHOT] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?] at java.lang.Thread.run(Thread.java:748) [?:?] |
| Comments |
| Comment by Victor Pickard [ 08/Mar/18 ] |
|
OK, here are my observations from looking into this exception. Sam, thanks for forwarding the email thread about neutron creating initial networks being enabled. That was a good clue to help narrow down this issue. It appears that this port was never added to config d/s..... perhaps because neutron create initial networks was enabled?? So, we get a list of interfaces from genius from oper d/s, and then look for the interface (netvirt) in config d/s, and it is not there. This doesn't seem correct, should genius be returning interfaces from config d/s? I suppose a more general question, how can a port end up in oper d/s and not be in config d/s? Is it because neutron created the port before ODL was up, and did not receive the neutron port create event? Probably so..... Interface that is not found in config d/s ad7be255-1fc2-4bab-93e1-9641504c27fb 2018-03-07T20:34:26,183 | ERROR | org.opendaylight.yang.gen.v1.urn.opendaylight.genius.itm.op.rev160406.tunnels_state.StateTunnelList_AsyncDataTreeChangeListenerBase-Data 1st robot test... exception comes out even before 1st test starts... is this related to neutron creating initial networks? When is the interface ad7be255-1fc2-4bab-93e1-9641504c27fb created? 2018-03-07T20:34:05,041 | INFO | ForkJoinPool-1-worker-6 | NeutronPortChangeListener | 356 - org.opendaylight.netvirt.neutronvpn-impl - 0.7.0.SNAPSHOT | Of-port-interface creation for port ad7be255-1fc2-4bab-93e1-9641504c27fb Port created a good 6+ minutes before any robot csit tests start... 2018-03-07T20:34:06,719 | INFO | org.opendaylight.yang.gen.v1.urn.opendaylight.neutron.ports.rev150712.ports.attributes.ports.Port_AsyncClusteredDataTreeChangeListenerBa ,interfaceorg.opendaylight.yang.gen.v1.urn.opendaylight.neutron.binding.rev150712.PortBindingExtension=PortBindingExtension{getHostId=sandbox-31488-4-1-devstack-pike-0.vexxhost.net, getProfile={}, getVifDetails=[VifDetails\{getDetailsKey=support_vhost_user, getValue=false, augmentations={}}, VifDetails\{getDetailsKey=uuid, getValue=46f51f05-7822-4af1-a99d-03e0f03cdd59, augmentations={}}, VifDetails\{getDetailsKey=has_datapath_type_netdev, getValue=false, augmentations={}}], getVifTyp Robot L2 suite runs. Openstack Suite setup cleans up, and removes the port KEYWORD BuiltIn . Log ${list} Start / End / Elapsed: 20180307 15:47:06.683 / 20180307 15:47:06.684 / 00:00:00.001 ] Start / End / Elapsed: 20180307 15:47:06.708 / 20180307 15:47:08.388 / 00:00:01.680 |
| Comment by Victor Pickard [ 12/Mar/18 ] |
|
OK, the previous analysis was incorrect. Here is the latest update, thanks for helping with this Michael/Stephen/Sam!
|
| Comment by Victor Pickard [ 12/Mar/18 ] |
|
Michael/Stephen/Sam, As Sam noted in #opendaylight-netvirt, this vpnInterface.isScheduledForRemove() came in a recent patch, https://git.opendaylight.org/gerrit/#/c/68151/. I have pushed a patch [0] that makes the call to setScheduledForRemove() on the VpnInterface when it is created for all references, and also, added the extra null check as suggested by Stephen in TunnelInterfaceStateListener.java. I'll add Kiran and Phillipe to the review. |
| Comment by Sam Hague [ 13/Mar/18 ] |