OpenFlow longevity does not launch
Description
Environment
None
Activity
Show:
Luis Gomez Palacios January 12, 2021 at 7:20 PM
BTW this bug only shows in Silicon.
Luis Gomez Palacios January 12, 2021 at 7:17 PMEdited
The test does not progress because it detects an NPE exception in the log. The ERROR is thrown after this:
2021-01-11T10:38:16,125 | INFO | epollEventLoopGroup-9-1 | SystemNotificationsListenerImpl | 302 - org.opendaylight.openflowplugin.impl - 0.12.0.SNAPSHOT | ConnectionEvent: Connection closed by device, Device:/10.30.170.59:45900, NodeId:nullThe above happens every time mininet is started and it is the result of a mininet controller check (telnet to the controller OFP port) as shown in the mininet log:
vagrant@mininet-vm-ubuntu-25:~\> sudo mn --controller=remote,ip=192.168.0.254 --topo linear,3 --switch=ovsk,protocols=OpenFlow13 -v debug
*** errRun: ['grep', '-c', 'processor', '/proc/cpuinfo']
4
0*** Setting resource limits
*** Creating network
*** Adding controller
*** errRun: ['which', 'mnexec']
/usr/bin/mnexec
0*** errRun: ['which', 'ifconfig']
/sbin/ifconfig
0*** c0 : ('unset HISTFILE; stty -echo; set +m',)
unset HISTFILE; stty -echo; set +m
*** c0 : ('echo A | telnet -e A 192.168.0.254 6653',)
Telnet escape character is 'A'.
Trying 192.168.0.254...
Connected to 192.168.0.254.
Escape character is 'A'.
telnet> Connection closed.The issue therefore is easy to reproduce by just doing a telnet to controller IP and OFP port and then exiting the connection:
vagrant@mininet-vm-ubuntu-25:~\> telnet 192.168.0.254 6653
Trying 192.168.0.254...
Connected to 192.168.0.254.
Escape character is '^]'.
^]
Connection closed by foreign host.Done
Details
Details
Assignee
Former user
Former user(Deactivated)Reporter
Robert Varga
Robert VargaComponents
Fix versions
Affects versions
Priority
HighCreated January 12, 2021 at 2:14 AM
Updated February 6, 2025 at 2:14 PM
Resolved January 22, 2021 at 9:52 AM
After fixing the obvious problems with flow/group handling, longevity suite fails very quickly on:
2021-01-11T10:38:06,599 | INFO | SystemReadyService-0 | OpenFlowPluginProviderImpl | 302 - org.opendaylight.openflowplugin.impl - 0.12.0.SNAPSHOT | onSystemBootReady() received, starting the switch connections 2021-01-11T10:38:06,728 | INFO | OFP-SwitchConnectionProvider-Udp/TcpHandler_6653-0 | TcpHandler | 309 - org.opendaylight.openflowplugin.openflowjava.openflow-protocol-impl - 0.12.0.SNAPSHOT | Switch listener started and ready to accept incoming tcp/tls connections on port: 6653 2021-01-11T10:38:06,728 | INFO | OFP-SwitchConnectionProvider-Udp/TcpHandler_6633-0 | TcpHandler | 309 - org.opendaylight.openflowplugin.openflowjava.openflow-protocol-impl - 0.12.0.SNAPSHOT | Switch listener started and ready to accept incoming tcp/tls connections on port: 6633 2021-01-11T10:38:06,730 | INFO | OFP-SwitchConnectionProvider-Udp/TcpHandler_6633-0 | OpenflowDiagStatusProviderImpl | 309 - org.opendaylight.openflowplugin.openflowjava.openflow-protocol-impl - 0.12.0.SNAPSHOT | The report status is OPERATIONAL for OPENFLOW_SERVER_6633 2021-01-11T10:38:06,730 | INFO | OFP-SwitchConnectionProvider-Udp/TcpHandler_6653-0 | OpenflowDiagStatusProviderImpl | 309 - org.opendaylight.openflowplugin.openflowjava.openflow-protocol-impl - 0.12.0.SNAPSHOT | The report status is OPERATIONAL for OPENFLOW_SERVER_6653 2021-01-11T10:38:06,731 | INFO | OFP-SwitchConnectionProvider-Udp/TcpHandler_6633-0 | OpenFlowPluginProviderImpl | 302 - org.opendaylight.openflowplugin.impl - 0.12.0.SNAPSHOT | All switchConnectionProviders are up and running (2). 2021-01-11T10:38:06,731 | INFO | OFP-SwitchConnectionProvider-Udp/TcpHandler_6633-0 | OpenflowDiagStatusProviderImpl | 309 - org.opendaylight.openflowplugin.openflowjava.openflow-protocol-impl - 0.12.0.SNAPSHOT | The report status is OPERATIONAL for OPENFLOW 2021-01-11T10:38:13,918 | INFO | sshd-SshServer[1a04469](port=8101)-nio2-thread-1 | OpenSSHKeyPairProvider | 113 - org.apache.karaf.shell.ssh - 4.2.10 | Creating ssh server private key at /tmp/karaf-0.14.0-SNAPSHOT/etc/host.key 2021-01-11T10:38:13,922 | INFO | sshd-SshServer[1a04469](port=8101)-nio2-thread-1 | OpenSSHKeyPairGenerator | 113 - org.apache.karaf.shell.ssh - 4.2.10 | generateKeyPair(RSA) generating host key - size=2048 2021-01-11T10:38:14,553 | INFO | sshd-SshServer[1a04469](port=8101)-nio2-thread-1 | ServerSessionImpl | 121 - org.apache.sshd.osgi - 2.5.1 | Session karaf@/10.30.170.241:41624 authenticated 2021-01-11T10:38:14,982 | INFO | CM Configuration Updater (Update: pid=org.ops4j.pax.logging) | EventAdminConfigurationNotifier | 4 - org.ops4j.pax.logging.pax-logging-log4j2 - 1.11.7 | Logging configuration changed. (Event Admin service unavailable - no notification sent). 2021-01-11T10:38:15,089 | INFO | pipe-logout | LogoutAction | 110 - org.apache.karaf.shell.commands - 4.2.10 | Disconnecting from current session... 2021-01-11T10:38:15,139 | WARN | sshd-SshServer[1a04469](port=8101)-nio2-thread-2 | ServerSessionImpl | 121 - org.apache.sshd.osgi - 2.5.1 | exceptionCaught(ServerSessionImpl[karaf@/10.30.170.241:41624])[state=Opened] IOException: Connection reset by peer 2021-01-11T10:38:16,125 | INFO | epollEventLoopGroup-9-1 | SystemNotificationsListenerImpl | 302 - org.opendaylight.openflowplugin.impl - 0.12.0.SNAPSHOT | ConnectionEvent: Connection closed by device, Device:/10.30.170.59:45900, NodeId:null 2021-01-11T10:38:16,127 | WARN | epollEventLoopGroup-9-1 | DefaultChannelPipeline | 47 - io.netty.common - 4.1.56.Final | An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception. java.lang.NullPointerException: null at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?] at org.opendaylight.openflowplugin.impl.lifecycle.ContextChainHolderImpl.onDeviceDisconnected(ContextChainHolderImpl.java:271) ~[?:?] at org.opendaylight.openflowplugin.impl.connection.ConnectionContextImpl.propagateDeviceDisconnectedEvent(ConnectionContextImpl.java:178) ~[?:?] at org.opendaylight.openflowplugin.impl.connection.ConnectionContextImpl.disconnectDevice(ConnectionContextImpl.java:167) ~[?:?] at org.opendaylight.openflowplugin.impl.connection.ConnectionContextImpl.onConnectionClosed(ConnectionContextImpl.java:125) ~[?:?] at org.opendaylight.openflowplugin.impl.connection.listener.SystemNotificationsListenerImpl.onDisconnectEvent(SystemNotificationsListenerImpl.java:69) ~[?:?] at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consumeDeviceMessage(ConnectionAdapterImpl.java:126) ~[?:?] at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractConnectionAdapterStatistics.consume(AbstractConnectionAdapterStatistics.java:68) ~[?:?] at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consume(ConnectionAdapterImpl.java:65) ~[?:?] at org.opendaylight.openflowjava.protocol.impl.core.DelegatingInboundHandler.channelInactive(DelegatingInboundHandler.java:53) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.56.Final] at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) [bundleFile:4.1.56.Final] at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.56.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389) [bundleFile:4.1.56.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.56.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:389) [bundleFile:4.1.56.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:354) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.56.Final] at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) [bundleFile:4.1.56.Final] at org.opendaylight.openflowjava.protocol.impl.core.connection.ChannelOutboundQueue.channelInactive(ChannelOutboundQueue.java:254) [bundleFile:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.56.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) [bundleFile:4.1.56.Final] at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:819) [bundleFile:4.1.56.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.56.Final] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [bundleFile:4.1.56.Final] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384) [bundleFile:4.1.56.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [bundleFile:4.1.56.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.56.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.56.Final] at java.lang.Thread.run(Thread.java:834) [?:?]This looks like a mixup with initialization – this points towards DeviceInfo being null.