[OPNFLWPLUG-757] Flow installation in OVS switch causes ofplugin regression failures in jenkins Created: 26/Aug/16  Updated: 27/Sep/21  Resolved: 22/Sep/16

Status: Resolved
Project: OpenFlowPlugin
Component/s: General
Affects Version/s: None
Fix Version/s: None

Type: Bug
Reporter: Sanjib Mohapatra Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All

Issue Links:
Duplicate
duplicates OPNFLWPLUG-748 Switch is still seen after owner goes... Resolved
External issue ID: 6552

 Description   

The latest regression run reports failure in normal flow installation. Flows are pushed via Bulkomatic and verified in mininet switch.

GERRIT_BRANCH: stable/boron
GERRIT_REFSPEC: refs/heads/stable/boron
BRANCH: stable/boron
CONTROLLERFEATURES: odl-jolokia,odl-openflowplugin-flow-services-ui,odl-openflowplugin-app-bulk-o-matic

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-daily-only-boron/70/robot/

This issue is seen from last 3 days consistently in regression (boron + Lithium plugin), below given the console logs, one can observe out of 3 DPN in one of the DPN 1000 flows are not installed.

==============================================================================
openflowplugin-bulkomatic-clustering-daily.txt.Cluster Reconcilliation Mult...
==============================================================================
Check Shards Status And Initialize Variables :: Check Status for a... | PASS |
------------------------------------------------------------------------------
Get Inventory Follower Before Cluster Restart :: Find a follower i... | PASS |
------------------------------------------------------------------------------
Start Mininet Connect To Follower Node1 :: Start mininet with conn... | PASS |
------------------------------------------------------------------------------
Add Bulk Flow From Follower :: 3000 Flows (1K per DPN) in 3 DPN ad... | PASS |
------------------------------------------------------------------------------
Get Bulk Flows and Verify In Cluster :: Initiate get operation and... | PASS |
------------------------------------------------------------------------------
Verify Flows In Switch Before Cluster Restart :: Verify flows are ... | FAIL |
Keyword 'MininetKeywords.Mininet Sync Status' failed after retrying for 1 minute 40 seconds. The last error was: '*** s1 ------------------------------------------------------------------------
OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=0

      • s2 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=1000
      • s3 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=1000
        mininet>' contains 'flow_count=1000' 2 times, not 3 times.
        ------------------------------------------------------------------------------

Also the same issue is observed in 2 node cluster suite, steps given as below

https://jenkins.opendaylight.org/releng/view/openflowplugin/job/openflowplugin-csit-3node-periodic-bulkomatic-clustering-daily-only-boron/70/console

==============================================================================
openflowplugin-bulkomatic-clustering-daily.txt.Cluster Reconcilliation Mult...
==============================================================================
Check Shards Status And Initialize Variables :: Check Status for a... | PASS |
------------------------------------------------------------------------------
Get Inventory Follower Before Cluster Restart :: Find a follower i... | PASS |
------------------------------------------------------------------------------
Start Mininet Connect To Follower Node1 :: Start mininet with conn... | PASS |
------------------------------------------------------------------------------
Add Bulk Flow From Follower :: 3000 Flows (1K per DPN) in 3 DPN ad... | PASS |
------------------------------------------------------------------------------
Get Bulk Flows and Verify In Cluster :: Initiate get operation and... | PASS |
------------------------------------------------------------------------------
Verify Flows In Switch Before Cluster Restart :: Verify flows are ... | FAIL |
Keyword 'MininetKeywords.Mininet Sync Status' failed after retrying for 1 minute 40 seconds. The last error was: '*** s1 ------------------------------------------------------------------------
OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=0

      • s2 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=1000
      • s3 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=1000
        mininet>' contains 'flow_count=1000' 2 times, not 3 times.
        ------------------------------------------------------------------------------

Thanks
Sanjib

 Comments   
Comment by Sanjib Mohapatra [ 27/Aug/16 ]

Hi Shuva

As discussed, I did the manual installation of latest boron build (distribution-karaf-0.5.0-20160827.064516-4640.zip),

Scenario1
=========

  • It’s a 3 node cluster ( leader , follower1, follower2)
  • Start Mininet Connect To Follower Node1, connect 3 DPNs to it
  • 9000 Flows (3K per DPN) in 3 DPN added via Follower Node1 and verify it gets applied in all instances.
  • Initiate (Bulkomatic) get operation and check flow count across cluster nodes in config DS
  • Verify flows are installed in switches , the test passes manually as opposed to regression ( in regression it is failing sporadically)
  • However all the reconciliation cases are failing manually as well as in regression,

Basic flow installation when connected to follower node1

      • s1 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=3000
      • s2 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=3000
      • s3 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=3000

Reconciliation when connected to follower node2

mininet> dpctl dump-aggregate -O OpenFlow13

      • s1 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=0
      • s2 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=3000
      • s3 ------------------------------------------------------------------------
        OFPST_AGGREGATE reply (OF1.3) (xid=0x2): packet_count=0 byte_count=0 flow_count=0
        mininet>

Logs captured from follower node2 during reconciliation, error and exceptions are highlighted

2016-08-27 01:25:05,693 | INFO | entLoopGroup-5-1 | SystemNotificationsListenerImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | ConnectionEvent: Connection closed by device, Device:/10.183.181.54:56777, NodeId:null
2016-08-27 01:25:05,704 | INFO | entLoopGroup-5-1 | ConnectionContextImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Unregister outbound queue successful.
2016-08-27 01:25:06,035 | INFO | entLoopGroup-5-2 | ConnectionAdapterImpl | 170 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.8.0.SNAPSHOT | Hello received / branch
2016-08-27 01:25:06,089 | INFO | entLoopGroup-5-2 | DeviceManagerImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | ConnectionEvent: Device connected to controller, Device:/10.183.181.54:56778, NodeId:Uri [_value=openflow:1]
2016-08-27 01:25:06,152 | INFO | entLoopGroup-5-2 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | SetRole called with input:SetRoleInput [_controllerRole=BECOMESLAVE, _node=NodeRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:1]]]]}

], augmentation=[]]
2016-08-27 01:25:06,159 | INFO | entLoopGroup-5-2 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Requesting state change to BECOMESLAVE
2016-08-27 01:25:06,160 | INFO | entLoopGroup-5-2 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | RoleChangeTask called on device:openflow:1 OFPRole:BECOMESLAVE
2016-08-27 01:25:06,161 | INFO | entLoopGroup-5-2 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | getGenerationIdFromDevice called for device: openflow:1
2016-08-27 01:25:06,256 | INFO | entLoopGroup-5-3 | ConnectionAdapterImpl | 170 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.8.0.SNAPSHOT | Hello received / branch
2016-08-27 01:25:06,259 | INFO | entLoopGroup-5-2 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange called for device:Uri [_value=openflow:1], role:BECOMESLAVE
2016-08-27 01:25:06,281 | INFO | entLoopGroup-5-2 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange onSuccess for device:Uri [_value=openflow:1], role:BECOMESLAVE
2016-08-27 01:25:06,293 | INFO | entLoopGroup-5-3 | DeviceManagerImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | ConnectionEvent: Device connected to controller, Device:/10.183.181.54:56779, NodeId:Uri [_value=openflow:2]
2016-08-27 01:25:06,303 | INFO | entLoopGroup-5-3 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | SetRole called with input:SetRoleInput [_controllerRole=BECOMESLAVE, _node=NodeRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:2]]]]}

], augmentation=[]]
2016-08-27 01:25:06,303 | INFO | entLoopGroup-5-3 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Requesting state change to BECOMESLAVE
2016-08-27 01:25:06,303 | INFO | entLoopGroup-5-3 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | RoleChangeTask called on device:openflow:2 OFPRole:BECOMESLAVE
2016-08-27 01:25:06,303 | INFO | entLoopGroup-5-3 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | getGenerationIdFromDevice called for device: openflow:2
2016-08-27 01:25:06,360 | INFO | entLoopGroup-5-3 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange called for device:Uri [_value=openflow:2], role:BECOMESLAVE
2016-08-27 01:25:06,389 | INFO | entLoopGroup-5-3 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange onSuccess for device:Uri [_value=openflow:2], role:BECOMESLAVE
2016-08-27 01:25:06,427 | INFO | entLoopGroup-5-4 | ConnectionAdapterImpl | 170 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.8.0.SNAPSHOT | Hello received / branch
2016-08-27 01:25:06,434 | INFO | entLoopGroup-5-4 | DeviceManagerImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | ConnectionEvent: Device connected to controller, Device:/10.183.181.54:56780, NodeId:Uri [_value=openflow:3]
2016-08-27 01:25:06,444 | INFO | entLoopGroup-5-4 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | SetRole called with input:SetRoleInput [_controllerRole=BECOMESLAVE, _node=NodeRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:3]]]]}

], augmentation=[]]
2016-08-27 01:25:06,444 | INFO | entLoopGroup-5-4 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Requesting state change to BECOMESLAVE
2016-08-27 01:25:06,446 | INFO | entLoopGroup-5-4 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | RoleChangeTask called on device:openflow:3 OFPRole:BECOMESLAVE
2016-08-27 01:25:06,446 | INFO | entLoopGroup-5-4 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | getGenerationIdFromDevice called for device: openflow:3
2016-08-27 01:25:06,452 | INFO | entLoopGroup-5-4 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange called for device:Uri [_value=openflow:3], role:BECOMESLAVE
2016-08-27 01:25:06,452 | INFO | entLoopGroup-5-4 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange onSuccess for device:Uri [_value=openflow:3], role:BECOMESLAVE
2016-08-27 01:25:06,610 | INFO | entLoopGroup-5-2 | StringValueObjectFactory | 46 - org.opendaylight.mdsal.yang-binding - 0.9.0.SNAPSHOT | Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.yang.types.rev130715.MacAddress
2016-08-27 01:25:06,626 | WARN | entLoopGroup-5-2 | DeviceContextImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Error processing port status message:
org.opendaylight.controller.md.sal.common.api.data.TransactionChainClosedException: Cannot write into transaction.
at org.opendaylight.openflowplugin.impl.device.TransactionChainManager.writeToTransaction(TransactionChainManager.java:233)[180:org.opendaylight.openflowplugin.impl:0.3.0.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.device.DeviceContextImpl.writeToTransaction(DeviceContextImpl.java:223)[180:org.opendaylight.openflowplugin.impl:0.3.0.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.device.DeviceContextImpl.processPortStatusMessage(DeviceContextImpl.java:331)[180:org.opendaylight.openflowplugin.impl:0.3.0.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.device.listener.OpenflowProtocolListenerFullImpl.onPortStatusMessage(OpenflowProtocolListenerFullImpl.java:94)[180:org.opendaylight.openflowplugin.impl:0.3.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consumeDeviceMessage(ConnectionAdapterImpl.java:129)[170:org.opendaylight.openflowjava.openflow-protocol-impl:0.8.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractConnectionAdapterStatistics.consume(AbstractConnectionAdapterStatistics.java:66)[170:org.opendaylight.openflowjava.openflow-protocol-impl:0.8.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consume(ConnectionAdapterImpl.java:43)[170:org.opendaylight.openflowjava.openflow-protocol-impl:0.8.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.DelegatingInboundHandler.channelRead(DelegatingInboundHandler.java:46)[170:org.opendaylight.openflowjava.openflow-protocol-impl:0.8.0.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)[113:io.netty.transport:4.0.37.Final]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractOutboundQueueManager.channelRead(AbstractOutboundQueueManager.java:195)[170:org.opendaylight.openflowjava.openflow-protocol-impl:0.8.0.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321)[113:io.netty.transport:4.0.37.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)[114:io.netty.codec:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321)[113:io.netty.transport:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)[114:io.netty.codec:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)[114:io.netty.codec:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321)[113:io.netty.transport:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)[114:io.netty.codec:4.0.37.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)[114:io.netty.codec:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321)[113:io.netty.transport:4.0.37.Final]
at io.netty.handler.timeout.ReadTimeoutHandler.channelRead(ReadTimeoutHandler.java:152)[116:io.netty.handler:4.0.37.Final]
at org.opendaylight.openflowjava.protocol.impl.core.IdleHandler.channelRead(IdleHandler.java:39)[170:org.opendaylight.openflowjava.openflow-protocol-impl:0.8.0.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:321)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1280)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:328)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:890)[113:io.netty.transport:4.0.37.Final]
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:879)[117:io.netty.transport-native-epoll:4.0.37.Final]
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:387)[117:io.netty.transport-native-epoll:4.0.37.Final]
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:296)[117:io.netty.transport-native-epoll:4.0.37.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[112:io.netty.common:4.0.37.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)[112:io.netty.common:4.0.37.Final]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_102]
2016-08-27 01:25:07,879 | INFO | ult-dispatcher-6 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | ========== Starting clustering MASTER services for node openflow:2 ==========
2016-08-27 01:25:07,879 | INFO | ult-dispatcher-6 | DeviceContextImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Starting device context cluster services for node openflow:2
2016-08-27 01:25:07,911 | INFO | entLoopGroup-5-3 | DeviceInitializationUtils | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | IP address of switch is: /10.183.181.54:56779
2016-08-27 01:25:07,916 | INFO | entLoopGroup-5-3 | StringValueObjectFactory | 46 - org.opendaylight.mdsal.yang-binding - 0.9.0.SNAPSHOT | Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv4Address
2016-08-27 01:25:07,916 | INFO | entLoopGroup-5-3 | StringValueObjectFactory | 46 - org.opendaylight.mdsal.yang-binding - 0.9.0.SNAPSHOT | Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv4Prefix
2016-08-27 01:25:07,917 | INFO | entLoopGroup-5-3 | StringValueObjectFactory | 46 - org.opendaylight.mdsal.yang-binding - 0.9.0.SNAPSHOT | Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv6Address
2016-08-27 01:25:07,917 | INFO | entLoopGroup-5-3 | StringValueObjectFactory | 46 - org.opendaylight.mdsal.yang-binding - 0.9.0.SNAPSHOT | Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv6Prefix
2016-08-27 01:25:08,840 | INFO | entLoopGroup-5-3 | DeviceInitializationUtils | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Static node Uri [_value=openflow:2] info: OFPMPMETERFEATURES collected
2016-08-27 01:25:08,904 | INFO | entLoopGroup-5-3 | DeviceInitializationUtils | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Static node Uri [_value=openflow:2] info: OFPMPGROUPFEATURES collected
2016-08-27 01:25:09,021 | INFO | entLoopGroup-5-3 | DeviceInitializationUtils | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Static node Uri [_value=openflow:2] info: OFPMPPORTDESC collected
2016-08-27 01:25:09,233 | INFO | ult-dispatcher-6 | StatisticsContextImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Starting statistics context cluster services for node openflow:2
2016-08-27 01:25:09,297 | INFO | ult-dispatcher-6 | StatisticsManagerImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Scheduling statistics poll for device: Uri [_value=openflow:2]
2016-08-27 01:25:09,407 | INFO | ult-dispatcher-6 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | SetRole called with input:SetRoleInput [_controllerRole=BECOMEMASTER, _node=NodeRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:2]]]]}

], augmentation=[]]
2016-08-27 01:25:09,408 | INFO | ult-dispatcher-6 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Requesting state change to BECOMEMASTER
2016-08-27 01:25:09,408 | INFO | ult-dispatcher-6 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | RoleChangeTask called on device:openflow:2 OFPRole:BECOMEMASTER
2016-08-27 01:25:09,408 | INFO | ult-dispatcher-6 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | getGenerationIdFromDevice called for device: openflow:2
2016-08-27 01:25:09,408 | INFO | ult-dispatcher-6 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Caching flows IDs ...
2016-08-27 01:25:09,427 | INFO | ult-dispatcher-6 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | ========== Start-up clustering MASTER services for node openflow:2 was SUCCESSFUL ==========
2016-08-27 01:25:09,622 | INFO | entLoopGroup-5-3 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange called for device:Uri [_value=openflow:2], role:BECOMEMASTER
2016-08-27 01:25:09,754 | INFO | entLoopGroup-5-3 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | submitRoleChange onSuccess for device:Uri [_value=openflow:2], role:BECOMEMASTER
2016-08-27 01:25:35,738 | WARN | ult-dispatcher-6 | OperationLimiter | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | Failed to acquire operation permit for transaction member-3-datastore-operational-fe-0-chn-3-txn-19
2016-08-27 01:25:35,738 | WARN | entLoopGroup-5-3 | OperationLimiter | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | Failed to acquire operation permit for transaction member-3-datastore-operational-fe-0-chn-3-txn-19
2016-08-27 01:26:23,833 | WARN | lt-dispatcher-52 | ReliableDeliverySupervisor | 150 - com.typesafe.akka.slf4j - 2.4.7 | Association with remote system [akka.tcp://opendaylight-cluster-data@10.183.181.51:2550] has failed, address is now gated for [5000] ms. Reason: [Failed to write message to the transport] Caused by: [null]
2016-08-27 01:26:23,834 | ERROR | lt-dispatcher-44 | Remoting | 150 - com.typesafe.akka.slf4j - 2.4.7 | Failed to write message to the transport
akka.remote.EndpointException: Failed to write message to the transport
Caused by: java.lang.NullPointerException
at org.opendaylight.controller.cluster.datastore.modification.MutableCompositeModification.writeExternal(MutableCompositeModification.java:120)[166:org.opendaylight.controller.sal-distributed-datastore:1.4.0.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.messages.BatchedModifications.writeExternal(BatchedModifications.java:78)[166:org.opendaylight.controller.sal-distributed-datastore:1.4.0.SNAPSHOT]
at java.io.ObjectOutputStream.writeExternalData(ObjectOutputStream.java:1459)[:1.8.0_102]
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1430)[:1.8.0_102]
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)[:1.8.0_102]
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)[:1.8.0_102]
at akka.serialization.JavaSerializer$$anonfun$toBinary$1.apply$mcV$sp(Serializer.scala:235)[149:com.typesafe.akka.actor:2.4.7]
at akka.serialization.JavaSerializer$$anonfun$toBinary$1.apply(Serializer.scala:235)[149:com.typesafe.akka.actor:2.4.7]
at akka.serialization.JavaSerializer$$anonfun$toBinary$1.apply(Serializer.scala:235)[149:com.typesafe.akka.actor:2.4.7]
at scala.util.DynamicVariable.withValue(DynamicVariable.scala:58)[145:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at akka.serialization.JavaSerializer.toBinary(Serializer.scala:235)[149:com.typesafe.akka.actor:2.4.7]
at akka.remote.serialization.MessageContainerSerializer.serializeSelection(MessageContainerSerializer.scala:45)[159:com.typesafe.akka.remote:2.4.7]
at akka.remote.serialization.MessageContainerSerializer.toBinary(MessageContainerSerializer.scala:34)[159:com.typesafe.akka.remote:2.4.7]
at akka.remote.MessageSerializer$.serialize(MessageSerializer.scala:37)[159:com.typesafe.akka.remote:2.4.7]
at akka.remote.EndpointWriter$$anonfun$serializeMessage$1.apply(Endpoint.scala:886)[159:com.typesafe.akka.remote:2.4.7]
at akka.remote.EndpointWriter$$anonfun$serializeMessage$1.apply(Endpoint.scala:886)[159:com.typesafe.akka.remote:2.4.7]
at scala.util.DynamicVariable.withValue(DynamicVariable.scala:58)[145:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at akka.remote.EndpointWriter.serializeMessage(Endpoint.scala:885)[159:com.typesafe.akka.remote:2.4.7]
at akka.remote.EndpointWriter.writeSend(Endpoint.scala:780)[159:com.typesafe.akka.remote:2.4.7]
at akka.remote.EndpointWriter$$anonfun$4.applyOrElse(Endpoint.scala:755)[159:com.typesafe.akka.remote:2.4.7]
at akka.actor.Actor$class.aroundReceive(Actor.scala:484)[149:com.typesafe.akka.actor:2.4.7]
at akka.remote.EndpointActor.aroundReceive(Endpoint.scala:447)[159:com.typesafe.akka.remote:2.4.7]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)[149:com.typesafe.akka.actor:2.4.7]
at akka.actor.ActorCell.invoke(ActorCell.scala:495)[149:com.typesafe.akka.actor:2.4.7]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)[149:com.typesafe.akka.actor:2.4.7]
at akka.dispatch.Mailbox.run(Mailbox.scala:224)[149:com.typesafe.akka.actor:2.4.7]
at akka.dispatch.Mailbox.exec(Mailbox.scala:234)[149:com.typesafe.akka.actor:2.4.7]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)[145:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)[145:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)[145:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[145:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
2016-08-27 01:26:28,491 | WARN | lt-dispatcher-24 | ClusterCoreDaemon | 150 - com.typesafe.akka.slf4j - 2.4.7 | Cluster Node [akka.tcp://opendaylight-cluster-data@10.183.181.53:2550] - Marking node(s) as UNREACHABLE [Member(address = akka.tcp://opendaylight-cluster-data@10.183.181.51:2550, status = Up)]. Node roles [member-3]
2016-08-27 01:26:28,491 | INFO | lt-dispatcher-36 | ShardManager | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | Received UnreachableMember: memberName MemberName

{name=member-1}, address: akka.tcp://opendaylight-cluster-data@10.183.181.51:2550
2016-08-27 01:26:28,492 | INFO | lt-dispatcher-16 | EntityOwnershipShard | 162 - org.opendaylight.controller.sal-akka-raft - 1.4.0.SNAPSHOT | member-3-shard-entity-ownership-operational: onPeerDown: PeerDown [memberName=member-1, peerId=member-1-shard-entity-ownership-operational]
2016-08-27 01:26:28,492 | INFO | lt-dispatcher-20 | ShardManager | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | Received UnreachableMember: memberName MemberName{name=member-1}

, address: akka.tcp://opendaylight-cluster-data@10.183.181.51:2550
2016-08-27 01:26:28,952 | INFO | lt-dispatcher-21 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Stopping role context cluster services for node ServiceGroupIdentifier

{value=openflow:2}

2016-08-27 01:26:28,953 | INFO | lt-dispatcher-21 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | SetRole called with input:SetRoleInput [_controllerRole=BECOMESLAVE, _node=NodeRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:2]]]]}

], augmentation=[]]
2016-08-27 01:26:28,953 | INFO | lt-dispatcher-21 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Requesting state change to BECOMESLAVE
2016-08-27 01:26:28,953 | INFO | lt-dispatcher-21 | SalRoleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | RoleChangeTask called on device:openflow:2 OFPRole:BECOMESLAVE
2016-08-27 01:26:28,953 | INFO | lt-dispatcher-21 | RoleService | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | getGenerationIdFromDevice called for device: openflow:2
2016-08-27 01:26:28,954 | INFO | lt-dispatcher-21 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Stopping statistics context cluster services for node ServiceGroupIdentifier

{value=openflow:2}

2016-08-27 01:26:28,954 | INFO | lt-dispatcher-21 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Stopping rpc context cluster services for node ServiceGroupIdentifier

{value=openflow:2}

2016-08-27 01:26:28,984 | INFO | lt-dispatcher-21 | LifecycleServiceImpl | 180 - org.opendaylight.openflowplugin.impl - 0.3.0.SNAPSHOT | Stopping device context cluster services for node ServiceGroupIdentifier

{value=openflow:2}

2016-08-27 01:26:28,999 | WARN | lt-dispatcher-45 | ClusterSingletonServiceGroupImpl | 131 - org.opendaylight.mdsal.singleton-dom-impl - 2.1.0.SNAPSHOT | Unexpected lost doubleCandidate DOMEntity [type=org.opendaylight.mdsal.AsyncServiceCloseEntityType, id=/(urn:opendaylight:params:xml:ns:yang:mdsal:core:general-entity?revision=2015-09-30)entity/entity[

{(urn:opendaylight:params:xml:ns:yang:mdsal:core:general-entity?revision=2015-09-30)name=openflow:2}

]] leadership. Close service instance openflow:2
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | kka://opendaylight-cluster-data) | 150 - com.typesafe.akka.slf4j - 2.4.7 | Cluster Node [akka.tcp://opendaylight-cluster-data@10.183.181.53:2550] - Marking node(s) as REACHABLE [Member(address = akka.tcp://opendaylight-cluster-data@10.183.181.51:2550, status = Up)]. Node roles [member-3]
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | ShardManager | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | Received ReachableMember: memberName MemberName

{name=member-1}

, address: akka.tcp://opendaylight-cluster-data@10.183.181.51:2550
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | ShardInformation | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | updatePeerAddress for peer member-1-shard-default-operational with address akka.tcp://opendaylight-cluster-data@10.183.181.51:2550/user/shardmanager-operational/member-1-shard-default-operational
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | ShardInformation | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | updatePeerAddress for peer member-1-shard-car-operational with address akka.tcp://opendaylight-cluster-data@10.183.181.51:2550/user/shardmanager-operational/member-1-shard-car-operational
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | ShardInformation | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | updatePeerAddress for peer member-1-shard-topology-operational with address akka.tcp://opendaylight-cluster-data@10.183.181.51:2550/user/shardmanager-operational/member-1-shard-topology-operational
2016-08-27 01:26:29,499 | INFO | ult-dispatcher-2 | Shard | 162 - org.opendaylight.controller.sal-akka-raft - 1.4.0.SNAPSHOT | Peer address for peer member-1-shard-default-operational set to akka.tcp://opendaylight-cluster-data@10.183.181.51:2550/user/shardmanager-operational/member-1-shard-default-operational
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | ShardInformation | 166 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | updatePeerAddress for peer member-1-shard-entity-ownership-operational with address akka.tcp://opendaylight-cluster-data@10.183.181.51:2550/user/shardmanager-operational/member-1-shard-entity-ownership-operational
2016-08-27 01:26:29,499 | INFO | lt-dispatcher-21 | ShardInformation | 166 - org.opendaylight.controller.sal-distributed-da...

Comment by Luis Gomez [ 30/Aug/16 ]

One thing I realized is that Singleton does not support restart of the device owner when switches only connect to the owner. Entity owner, inventory and topology API freeze and never leave this state after owner goes down.

Comment by Luis Gomez [ 20/Sep/16 ]

I think this issue can be closed as I do not see flows failing straight installation (no instance reboot). Instead we should work on: https://bugs.opendaylight.org/show_bug.cgi?id=6459

Comment by Luis Gomez [ 22/Sep/16 ]

This issue is a mix of:

https://bugs.opendaylight.org/show_bug.cgi?id=6459
https://bugs.opendaylight.org/show_bug.cgi?id=6755

So closing it.

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