Lots of NPE exceptions seen from the ONOS vtn app in the ONOS logs

Lots of NullPointerExceptions are seen from the ONOS vtn app. This makes viewing the ONOS logs very difficult. This happens due to a bug in the vtn code.For e.g. in the below case when an ARP comes for 144.60.34.59 we see the exception as below:

2017-09-17 19:26:38,266 | WARN | ew I/O worker #2 | PacketManager | 127 - org.onosproject.onos-core-net - 1.10.6 | Packet processor org.opencord.cordvtn.impl.CordVtnArpProxy$InternalPacketProcessor@633994ca threw an exception
java.lang.NullPointerException
at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:782)[94:com.google.guava:22.0.0]
at org.opencord.cordvtn.api.core.Instance.of(Instance.java:69)[185:org.opencord.vtn:1.3.0]
at org.opencord.cordvtn.impl.CordVtnArpProxy.forwardArpRequest(CordVtnArpProxy.java:319)[185:org.opencord.vtn:1.3.0]
at org.opencord.cordvtn.impl.CordVtnArpProxy.processArpRequest(CordVtnArpProxy.java:264)[185:org.opencord.vtn:1.3.0]
at org.opencord.cordvtn.impl.CordVtnArpProxy.access$300(CordVtnArpProxy.java:87)[185:org.opencord.vtn:1.3.0]
at org.opencord.cordvtn.impl.CordVtnArpProxy$InternalPacketProcessor.process(CordVtnArpProxy.java:472)[185:org.opencord.vtn:1.3.0]
at org.onosproject.net.packet.impl.PacketManager$InternalPacketProviderService.processPacket(PacketManager.java:389)[127:org.onosproject.onos-core-net:1.10.6]
at org.onosproject.provider.of.packet.impl.OpenFlowPacketProvider$InternalPacketProvider.handlePacket(OpenFlowPacketProvider.java:171)[164:org.onosproject.onos-providers-openflow-packet:1.10.6]
at org.onosproject.openflow.controller.impl.OpenFlowControllerImpl.processPacket(OpenFlowControllerImpl.java:335)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.onosproject.openflow.controller.impl.OpenFlowControllerImpl$OpenFlowSwitchAgent.processMessage(OpenFlowControllerImpl.java:746)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.onosproject.openflow.controller.driver.AbstractOpenFlowSwitch.handleMessage(AbstractOpenFlowSwitch.java:267)[161:org.onosproject.onos-protocols-openflow-api:1.10.6]
at org.onosproject.openflow.controller.impl.OFChannelHandler.dispatchMessage(OFChannelHandler.java:1321)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.onosproject.openflow.controller.impl.OFChannelHandler.access$2100(OFChannelHandler.java:85)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.onosproject.openflow.controller.impl.OFChannelHandler$ChannelState$9.processOFPacketIn(OFChannelHandler.java:761)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.onosproject.openflow.controller.impl.OFChannelHandler$ChannelState.processOFMessage(OFChannelHandler.java:1014)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.onosproject.openflow.controller.impl.OFChannelHandler.messageReceived(OFChannelHandler.java:1302)[162:org.onosproject.onos-protocols-openflow-ctl:1.10.6]
at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.timeout.IdleStateAwareChannelHandler.handleUpstream(IdleStateAwareChannelHandler.java:36)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.messageReceived(SimpleChannelUpstreamHandler.java:124)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.timeout.ReadTimeoutHandler.messageReceived(ReadTimeoutHandler.java:184)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.timeout.IdleStateHandler.messageReceived(IdleStateHandler.java:294)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)[95:org.jboss.netty:3.10.5.Final]
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)[95:org.jboss.netty:3.10.5.Final]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]

If we look into the hosts output we see that ONOS does not know this IP address:

onos> hosts
id=00:00:5E:00:01:03/4093, mac=00:00:5E:00:01:03, location=of:00000000000000b1/1, vlan=4093, ip(s)=[144.60.34.1], configured=false
id=00:0E:86:00:E9:75/4093, mac=00:0E:86:00:E9:75, location=of:00000000000000b1/1, vlan=4093, ip(s)=[144.60.34.35], configured=false
id=00:13:F7:09:F6:E0/4093, mac=00:13:F7:09:F6:E0, location=of:00000000000000b1/1, vlan=4093, ip(s)=[], configured=false
id=00:13:F7:09:F7:E0/4093, mac=00:13:F7:09:F7:E0, location=of:00000000000000b1/1, vlan=4093, ip(s)=[], configured=false
id=0C:A4:02:41:34:01/4093, mac=0C:A4:02:41:34:01, location=of:00000000000000b1/1, vlan=4093, ip(s)=[144.60.34.2], configured=false
id=34:64:A9:0F:C2:33/4093, mac=34:64:A9:0F:C2:33, location=of:00000000000000b1/1, vlan=4093, ip(s)=[144.60.34.75], configured=false
id=54:A6:19:B8:D6:DA/4093, mac=54:A6:19:B8:D6:DA, location=of:00000000000000b1/1, vlan=4093, ip(s)=[144.60.34.55], configured=false
id=B8:AC:6F:87:57:21/4093, mac=B8:AC:6F:87:57:21, location=of:00000000000000b1/1, vlan=4093, ip(s)=[144.60.34.80], configured=false
id=B8:AC:6F:87:57:23/4093, mac=B8:AC:6F:87:57:23, location=of:00000000000000b1/1, vlan=4093, ip(s)=[192.168.0.120], configured=false
id=DC:45:17:D6:7A:C1/13, mac=DC:45:17:D6:7A:C1, location=of:00000000000000b1/1, vlan=13, ip(s)=[], configured=false
id=DC:45:17:D6:7A:C1/362, mac=DC:45:17:D6:7A:C1, location=of:00000000000000b1/1, vlan=362, ip(s)=[10.1.33.37], configured=false
id=DC:45:17:D6:7C:61/16, mac=DC:45:17:D6:7C:61, location=of:00000000000000b1/1, vlan=16, ip(s)=[], configured=false
id=DC:45:17:D6:7C:61/482, mac=DC:45:17:D6:7C:61, location=of:00000000000000b1/1, vlan=482, ip(s)=[10.1.33.38], configured=false

From the source code of vtn (CordVtnArpProxy.java, function forwardArpRequest() )

Host host = hostService.getHost(HostId.hostId(ethPacket.getSourceMAC()));
NetworkType networkType = Instance.of(host).netType();
if (host == null || (networkType != MANAGEMENT_HOST &&
networkType != FLAT))

{ context.block(); log.trace("Failed to handle ARP request"); return; }

– The check for host being null is done after using it and so the exception