[NETVIRT-1274] Direct Exception:... java.lang.IllegalArgumentException: Invalid range: -1, expected: [[0..18446744073709551615]]. Created: 21/May/18  Updated: 07/Jul/18  Resolved: 07/Jul/18

Status: Resolved
Project: netvirt
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Medium
Reporter: Sam Hague Assignee: Akash Sahu
Resolution: Cannot Reproduce Votes: 0
Labels: csit:exception, csit:failures
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File odl1_karaf.487.log.tar.xz    
Issue Links:
Relates
relates to NETVIRT-1270 Conflicting modification for path... ... Resolved

 Description   

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/netvirt-csit-1node-openstack-queens-upstream-stateful-fluorine/487/odl_1/odl1_karaf.log.gz

2018-05-21T14:09:38,370 | ERROR | ForkJoinPool-1-worker-1 | JobCoordinatorImpl               | 296 - org.opendaylight.infrautils.jobcoordinator-impl - 1.4.0.SNAPSHOT | Direct Exception (not failed Future) when executing job, won't even retry: JobEntry{key='9d1364fd-3f30-4554-bf57-d106956d8845', mainWorker=org.opendaylight.netvirt.vpnmanager.VpnUtil$$Lambda$1937/988088372@1dc6d890, rollbackWorker=null, retryCount=0/5, futures=null}
java.lang.IllegalArgumentException: Invalid range: -1, expected: [[0..18446744073709551615]].
	at org.opendaylight.yangtools.yang.binding.CodeHelpers.throwInvalidRange(CodeHelpers.java:183) ~[?:?]
	at org.opendaylight.yangtools.yang.binding.CodeHelpers.throwInvalidRange(CodeHelpers.java:194) ~[?:?]
	at org.opendaylight.yang.gen.v1.urn.opendaylight.openflowplugin.extension.nicira.action.rev140714.nx.action.reg.load.grouping.NxRegLoadBuilder.checkValueRange(NxRegLoadBuilder.java:89) ~[?:?]
	at org.opendaylight.yang.gen.v1.urn.opendaylight.openflowplugin.extension.nicira.action.rev140714.nx.action.reg.load.grouping.NxRegLoadBuilder.setValue(NxRegLoadBuilder.java:94) ~[?:?]
	at org.opendaylight.genius.mdsalutil.actions.ActionRegLoad.buildAction(ActionRegLoad.java:55) ~[?:?]
	at org.opendaylight.genius.mdsalutil.actions.ActionRegLoad.buildAction(ActionRegLoad.java:46) ~[?:?]
	at org.opendaylight.netvirt.vpnmanager.VpnUtil.getBoundServicesForVpnInterface(VpnUtil.java:1727) ~[?:?]
	at org.opendaylight.netvirt.vpnmanager.VpnUtil.lambda$bindService$3(VpnUtil.java:1714) ~[?:?]
	at org.opendaylight.infrautils.jobcoordinator.internal.JobCoordinatorImpl$MainTask.runWithUncheckedExceptionLogging(JobCoordinatorImpl.java:401) [296:org.opendaylight.infrautils.jobcoordinator-impl:1.4.0.SNAPSHOT]
	at org.opendaylight.infrautils.utils.concurrent.LoggingUncaughtThreadDeathContextRunnable.run(LoggingUncaughtThreadDeathContextRunnable.java:60) [301:org.opendaylight.infrautils.util:1.4.0.SNAPSHOT]
	at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402) [?:?]
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289) [?:?]
	at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056) [?:?]
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692) [?:?]
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157) [?:?]


 Comments   
Comment by Kiran Upadhyaya [ 29/May/18 ]

There is almost a 12s delay between the time a neutron port is added and the time a vpn interface for that port is being processed, which is abnormal.

Here's a collection of log statements that describe this:

karaf.log:2018-05-21T14:09:19,613 | INFO | ForkJoinPool-1-worker-3 | VpnInstanceListener | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | VPN-ADD: addVpnInstance: VpnInstanceOpData populated successfully for vpn d02f8bec-d7b4-4063-9924-5a69df2f5f3b rd d02f8bec-d7b4-4063-9924-5a69df2f5f3b

karaf.log:2018-05-21T14:09:22,130 | INFO | ForkJoinPool-1-worker-2 | NeutronPortChangeListener | 378 - org.opendaylight.netvirt.neutronvpn-impl - 0.7.0.SNAPSHOT | Of-port-interface creation for port 9d1364fd-3f30-4554-bf57-d106956d8845

karaf.log:2018-05-21T14:09:24,034 | INFO | org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.interfaces.rev140508.interfaces.state.Interface_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | InterfaceStateChangeListener | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | VPN Interface add event - intfName 9d1364fd-3f30-4554-bf57-d106956d8845 from InterfaceStateChangeListener

karaf.log:2018-05-21T14:09:28,807 | INFO | ForkJoinPool-1-worker-4 | NeutronvpnManager | 378 - org.opendaylight.netvirt.neutronvpn-impl - 0.7.0.SNAPSHOT | Creating vpn interface VpnInterface{_key=VpnInterfaceKey{_name=9d1364fd-3f30-4554-bf57-d106956d8845}, _name=9d1364fd-3f30-4554-bf57-d106956d8845, _vpnInstanceNames=[VpnInstanceNames{_associatedSubnetType=V4AndV6Subnets, _key=VpnInstanceNamesKey{_vpnName=d02f8bec-d7b4-4063-9924-5a69df2f5f3b}, _vpnName=d02f8bec-d7b4-4063-9924-5a69df2f5f3b, augmentation=[]}], _routerInterface=false, augmentation=[Adjacencies{_adjacency=[Adjacency{_adjacencyType=PrimaryAdjacency, _ipAddress=2003::2/128, _key=AdjacencyKey{_ipAddress=2003::2/128}, _macAddress=fa:16:3e:8c:23:bb, _subnetId=Uuid{_value=c737f1dc-6bec-4c49-aceb-d98be3bdc82b}, augmentation=[]}]}]}

2018-05-21T14:09:34,523 | INFO | org.opendaylight.yang.gen.v1.urn.huawei.params.xml.ns.yang.l3vpn.rev140815.vpn.interfaces.VpnInterface_AsyncDataTreeChangeListenerBase-DataTreeChangeHandler-0 | VpnInterfaceManager | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | add: intfName 9d1364fd-3f30-4554-bf57-d106956d8845 onto vpnName [d02f8bec-d7b4-4063-9924-5a69df2f5f3b]

karaf.log:2018-05-21T14:09:34,524 | INFO | ForkJoinPool-1-worker-5 | VpnInstanceListener | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | VPN-REMOVE: call: Operational status set to PENDING_DELETE for vpn d02f8bec-d7b4-4063-9924-5a69df2f5f3b with rd d02f8bec-d7b4-4063-9924-5a69df2f5f3b
karaf.log:2018-05-21T14:09:37,422 | INFO | ForkJoinPool-1-worker-2 | VpnOpStatusListener | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | Removed vpn data for vpnname d02f8bec-d7b4-4063-9924-5a69df2f5f3b

karaf.log:2018-05-21T14:09:38,365 | INFO | ForkJoinPool-1-worker-6 | VpnFootprintService$DpnEnterExitVpnWorker | 386 - org.opendaylight.netvirt.vpnmanager-impl - 0.7.0.SNAPSHOT | onSuccess: FootPrint established for vpn d02f8bec-d7b4-4063-9924-5a69df2f5f3b rd d02f8bec-d7b4-4063-9924-5a69df2f5f3b on dpn 136839111744430

 

Whats interesting is that, OF port creation and VPN Interface creation for a port is within the same job that is submitted to the Job-Coordinator. However, this job seems to  be handed over in between from one Fork-Join worker to another (ForkJoinPool-1-worker-2 to ForkJoinPoo1-1-worker-4), and the execution of the second worker is triggered/completed with a delay of 6 seconds (14:09:22 to 14:09:28).

The other 6 seconds delay is observed between the vpn interface creation and the next job that is submitted to process the vpn interface via the VpnInterfaceManager add event(ForkJoinPool-1-worker-5), between 14:09:28 and 14:09:34.

This is leading to the vpn interface processing to get executed after the vpn instance is deleted (at 14:09:37), leading to the Exceptions and stale entries (and possible functionality failures.)

The single non-recursive JC job jumping across FJ Workers in between is strange. In addition to this, due to the parallel execution of tempest cases, looks like its taking a long time to allocate a FJ worker to the JC jobs.

Generated at Wed Feb 07 20:23:39 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.