Uploaded image for project: 'bgpcep'
  1. bgpcep
  2. BGPCEP-328

Immediate reconnects by BGPReconnectPromise

    XMLWordPrintable

Details

    • Bug
    • Status: Resolved
    • Resolution: Cannot Reproduce
    • Bugzilla Migration
    • Bugzilla Migration
    • BGP
    • None

    • Operating System: All
      Platform: All

    • 4740

    Description

      This Beryllium bug typically happens when ODL starts with BGP peer configured (in 41-*.xml, with small holdtimer) and ready. ODL ends up in a loop rapidly reconnecting, which pollutes karaf.log and makes debugging unrelated bugs very hard.
      Eventually, connect is successful and system test passes, but karaf.log gets full before that.

      BGPProtocolSessionPromise and BGPReconnectPromise should be reworked in such a way that no failure leads to immediate reconnect.

      Here is a segment of karaf.log showing start of the loop:

      2015-12-08 12:28:00,972 | TRACE | oupCloseable-6-2 | BGPMessageToByteEncoder | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Encoding message: Notify [_errorCode=6, _errorSubcode=0, augmentation=[]]
      2015-12-08 12:28:00,973 | TRACE | oupCloseable-6-2 | BGPNotificationMessageParser | 244 - org.opendaylight.bgpcep.bgp-parser-impl - 0.5.0.SNAPSHOT | Notification message serialized to: 0600
      2015-12-08 12:28:00,973 | INFO | CommitFutures-0 | BGPSessionImpl | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Closing session: BGPSessionImpl

      {channel=[id: 0xe2c1bbe5, /10.25.2.9:45622 => /10.25.2.27:179], state=IDLE}

      2015-12-08 12:28:00,973 | TRACE | oupCloseable-6-2 | BGPMessageToByteEncoder | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Encoded message: ffffffffffffffffffffffffffffffff0015030600
      2015-12-08 12:28:00,973 | DEBUG | oupCloseable-6-2 | BGPMessageToByteEncoder | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Message sent to output: Notify [_errorCode=6, _errorSubcode=0, augmentation=[]]
      2015-12-08 12:28:00,977 | DEBUG | CommitFutures-0 | BGPPeer | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Transaction chain org.opendaylight.controller.cluster.databroker.DOMBrokerTransactionChain@5b6eb68f successfull.
      2015-12-08 12:28:00,977 | TRACE | oupCloseable-6-2 | BGPSessionImpl | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Message Notify [_errorCode=6, _errorSubcode=0, augmentation=[]] sent to socket [id: 0xe2c1bbe5, /10.25.2.9:45622 => /10.25.2.27:179]
      2015-12-08 12:28:00,982 | TRACE | oupCloseable-6-2 | BGPByteToMessageDecoder | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | No more content in incoming buffer.
      2015-12-08 12:28:00,983 | DEBUG | oupCloseable-6-2 | BGPSessionImpl | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Channel [id: 0xe2c1bbe5, /10.25.2.9:45622 :> /10.25.2.27:179] inactive.
      2015-12-08 12:28:00,983 | DEBUG | oupCloseable-6-2 | BGPReconnectPromise | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Reconnecting after connection to /10.25.2.27:179 was dropped
      2015-12-08 12:28:00,985 | DEBUG | oupCloseable-6-2 | BGPProtocolSessionPromise | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Promise BGPProtocolSessionPromise@1fbce2ac(incomplete) attempting connect for 5000ms
      2015-12-08 12:28:00,989 | DEBUG | oupCloseable-6-2 | BGPReconnectPromise | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Client created.
      2015-12-08 12:28:00,997 | DEBUG | oupCloseable-6-5 | BGPProtocolSessionPromise | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Promise BGPProtocolSessionPromise@1fbce2ac(incomplete) connection resolved
      2015-12-08 12:28:00,998 | DEBUG | oupCloseable-6-5 | BGPProtocolSessionPromise | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Promise BGPProtocolSessionPromise@1fbce2ac(incomplete) connection successful
      2015-12-08 12:28:00,999 | DEBUG | oupCloseable-6-5 | AbstractBGPSessionNegotiator | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Starting session negotiation on channel [id: 0x2ea5cd45, /10.25.2.9:45623 => /10.25.2.27:179]

      Subsequent iterations are caused like this:

      2015-12-08 12:28:01,007 | INFO | oupCloseable-6-5 | AbstractBGPSessionNegotiator | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Failed to send message Open [<snip>]
      java.io.IOException: Connection reset by peer
      at sun.nio.ch.FileDispatcherImpl.write0(Native Method)[:1.7.0_67]
      at sun.nio.ch.SocketDispatcher.write(Unknown Source)[:1.7.0_67]
      at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source)[:1.7.0_67]
      at sun.nio.ch.IOUtil.write(Unknown Source)[:1.7.0_67]
      at sun.nio.ch.SocketChannelImpl.write(Unknown Source)[:1.7.0_67]
      at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:287)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:761)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:311)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:729)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1127)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:663)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:644)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:663)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:693)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:681)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:716)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:954)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:244)[124:io.netty.transport:4.0.30.Final]
      at org.opendaylight.protocol.bgp.rib.impl.AbstractBGPSessionNegotiator.sendMessage(AbstractBGPSessionNegotiator.java:245)[252:org.opendaylight.bgpcep.bgp-rib-impl:0.5.0.SNAPSHOT]
      at org.opendaylight.protocol.bgp.rib.impl.AbstractBGPSessionNegotiator.startNegotiation(AbstractBGPSessionNegotiator.java:111)[252:org.opendaylight.bgpcep.bgp-rib-impl:0.5.0.SNAPSHOT]
      at org.opendaylight.protocol.bgp.rib.impl.AbstractBGPSessionNegotiator.channelActive(AbstractBGPSessionNegotiator.java:264)[252:org.opendaylight.bgpcep.bgp-rib-impl:0.5.0.SNAPSHOT]
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:183)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:169)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.ChannelInboundHandlerAdapter.channelActive(ChannelInboundHandlerAdapter.java:64)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:183)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:169)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.ChannelInboundHandlerAdapter.channelActive(ChannelInboundHandlerAdapter.java:64)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:183)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelActive(AbstractChannelHandlerContext.java:169)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:817)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:260)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:290)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[124:io.netty.transport:4.0.30.Final]
      at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[124:io.netty.transport:4.0.30.Final]
      at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:110)[123:io.netty.common:4.0.30.Final]
      at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[123:io.netty.common:4.0.30.Final]
      at java.lang.Thread.run(Unknown Source)[:1.7.0_67]
      2015-12-08 12:28:01,009 | DEBUG | oupCloseable-6-5 | AbstractBGPSessionNegotiator | 252 - org.opendaylight.bgpcep.bgp-rib-impl - 0.5.0.SNAPSHOT | Negotiation on channel [id: 0x2ea5cd45, /10.25.2.9:45623 :> /10.25.2.27:179] failed
      java.io.IOException: Connection reset by peer
      ... (the same stacktrace as above)

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            milos.fabian@pantheon.tech Milos Fabian
            vrpolak Vratko Polak
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: