Uploaded image for project: 'Qpid JMS'
  1. Qpid JMS
  2. QPIDJMS-535

Looping failure after SASL negotiation with Artemis v2.16

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Not A Bug
    • Affects Version/s: 0.58.0
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      This is not a production issue for us so tagging it as minor. Encountered during some destructive testing, killing brokers, clients, seeing that connections re-establish ok.

      It sometimes happens when re-establishing a connection to an artemis broker hosted in kubernetes which has been recycled by deleting the pod.

      2021-04-09 11:48:13.940 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[28] : Flow{nextIncomingId=1, incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=14000, linkCredit=0, available=null, drain=true, echo=false, properties=null}
      2021-04-09 11:48:14.278  INFO 11152 --- [.84.10.4:30672]] o.a.qpid.jms.provider.amqp.AmqpProvider  : Transport failed: An existing connection was forcibly closed by the remote host
      2021-04-09 11:48:14.324 DEBUG 11152 --- [.84.10.4:30672]] io.netty.buffer.PoolThreadCache          : Freed 18 thread-local buffer(s) from thread: AmqpProvider :(1):[amqp://10.84.10.4:30672]
      2021-04-09 11:48:36.778 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.jms.sasl.SaslMechanismFinder    : Best match for SASL auth was: SASL-PLAIN
      2021-04-09 11:48:36.862 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.proton.engine.impl.SaslImpl     : Handled outcome: SaslImpl [_outcome=PN_SASL_OK, state=PN_SASL_PASS, done=true, role=CLIENT]
      2021-04-09 11:48:36.936 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Open{ containerId='', hostname='null', maxFrameSize=131072, channelMax=65535, idleTimeOut=null, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null, properties={amqp:connection-establishment-failed=true}}
      2021-04-09 11:48:36.937 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Close{error=Error{condition=amqp:invalid-field, description='null', info={invalid-field=container-id}}}
      2021-04-09 11:48:36.940 DEBUG 11152 --- [.84.10.4:30672]] io.netty.buffer.PoolThreadCache          : Freed 3 thread-local buffer(s) from thread: AmqpProvider :(3):[amqp://10.84.10.4:30672]
      2021-04-09 11:48:37.128 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.jms.sasl.SaslMechanismFinder    : Best match for SASL auth was: SASL-PLAIN
      2021-04-09 11:48:37.200 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.proton.engine.impl.SaslImpl     : Handled outcome: SaslImpl [_outcome=PN_SASL_OK, state=PN_SASL_PASS, done=true, role=CLIENT]
      2021-04-09 11:48:37.274 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Open{ containerId='', hostname='null', maxFrameSize=131072, channelMax=65535, idleTimeOut=null, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null, properties={amqp:connection-establishment-failed=true}}
      2021-04-09 11:48:37.274 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Close{error=Error{condition=amqp:invalid-field, description='null', info={invalid-field=container-id}}}
      2021-04-09 11:48:37.276 DEBUG 11152 --- [.84.10.4:30672]] io.netty.buffer.PoolThreadCache          : Freed 3 thread-local buffer(s) from thread: AmqpProvider :(4):[amqp://10.84.10.4:30672]
      2021-04-09 11:48:37.486 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.jms.sasl.SaslMechanismFinder    : Best match for SASL auth was: SASL-PLAIN
      2021-04-09 11:48:37.557 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.proton.engine.impl.SaslImpl     : Handled outcome: SaslImpl [_outcome=PN_SASL_OK, state=PN_SASL_PASS, done=true, role=CLIENT]
      2021-04-09 11:48:37.629 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Open{ containerId='', hostname='null', maxFrameSize=131072, channelMax=65535, idleTimeOut=null, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null, properties={amqp:connection-establishment-failed=true}}
      2021-04-09 11:48:37.629 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Close{error=Error{condition=amqp:invalid-field, description='null', info={invalid-field=container-id}}}
      2021-04-09 11:48:37.631 DEBUG 11152 --- [.84.10.4:30672]] io.netty.buffer.PoolThreadCache          : Freed 3 thread-local buffer(s) from thread: AmqpProvider :(5):[amqp://10.84.10.4:30672]
      2021-04-09 11:48:37.875 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.jms.sasl.SaslMechanismFinder    : Best match for SASL auth was: SASL-PLAIN
      2021-04-09 11:48:37.945 DEBUG 11152 --- [.84.10.4:30672]] o.a.qpid.proton.engine.impl.SaslImpl     : Handled outcome: SaslImpl [_outcome=PN_SASL_OK, state=PN_SASL_PASS, done=true, role=CLIENT]
      2021-04-09 11:48:38.015 DEBUG 11152 --- [.84.10.4:30672]] proton.trace                             : IN: CH[0] : Open{ containerId='', hostname='null', maxFrameSize=131072, channelMax=65535, idleTimeOut=null, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null, properties={amqp:connection-establishment-failed=true}}
      2021
       

      ... and so on. Only restarting the client makes it reconnect. The connection is non-SSL AMQP from a client in a pod to a broker in a pod. Using a Spring CachingConnectionFactory with resetConnectionOnException enabled. In production will go via an external load balancer with SSL and not seeing the same problem there.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              indysilver David Martin
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: