Re: ProtonJ2 Initial connection failure, reconnect logic

Tue, 12 Mar 2024 12:13:30 -0700 

On 3/12/24 04:08, Ciaran wrote:

On Mon, Mar 11, 2024 at 9:33 PM Timothy Bish <tabish...@gmail.com> wrote:



The client re-connection logic treats a SASL authentication error as a
terminal state and will not continue reconnect attempts if it receives a
SASL outcome that indicates anything other than a temporary failure
state so it should be stopping the reconnect if it was actually failing
to authenticate.  This is true on the first attempt as well as on
subsequent attempts to other hosts if you add more than one and it has
failed to reach any of the preceding hosts while attempt to recover the
connection.

  From the error logs attached it doesn't appear as though SASL
authentication is your issue though, at least in so much as it isn't
logging anything indicating SASL authentication as the error. Instead
the connection appears to be failing because the remote has sent a
response to the Receiver attach that does not include the initial
delivery count value as required by the specification.

You can capture more information about the AMQP frames being sent and
received by enabling frame tracing, see the docs for how to do that.


https://github.com/apache/qpid-protonj2/blob/main/protonj2-client-docs/Configuration.md#logging



Thanks for getting back to me so quickly Tim, please find below the frames
for a successful
connection and an unsuccessful connection. My test has actually been to
specify an invalid user if
that's relevant.

I can see in both cases that the SASL challenge completes successfully,
which I appreciate is
strange, but I would imagine Azure Service Bus is a common enough broker
target for the library?
So looking at the frame trace it is clear the connection is being established as the SASL outcome is returned as 'OK' and then a normal Open exchange occurs so from the client point of view a connection was successfully made so any initial reconnect attempts option won't apply here as the connection "succeeded".  For the connection to fail with bad credentials the SASL outcome would need to indicate a failure.
The connection breaks at the point the attach response arrives and is lacking the mandatory initial-delivery-count field as per the AMQP 1.0 specification. 

http://docs.oasis-open.org/amqp/core/v1.0/os/amqp-core-transport-v1.0-os.html#type-attach
It could be that the user you logged in as does not have read permission and the server is trying to tell the client that the link will be closed with an error condition in the Detach indicating that as the returned response does not carry a source or target value (both are null) whereas the sent Attach has an appropriate source and target value.  If that is what it is doing it gets it wrong as it omits the 'initial-delivery-count' which is required for an Attach with the Role of Sender (as per referenced spec above) regardless of the outcome of the attach. 


When the username is invalid:

-> SASL:[1793436274:0] AMQP,3,1,0,0
<- SASL:[1793436274:0] AMQP,3,1,0,0
<- SASL:[1793436274:0] SaslMechanisms{saslServerMechanisms=[MSSBCBS, PLAIN,
ANONYMOUS, EXTERNAL]}
-> SASL:[1793436274:0] SaslInit{mechanism=PLAIN,
initialResponse="\x00INVALID_USERNAME\x00VALID_PASSWORD"...(truncated),
hostname='MY_HOST.servicebus.windows.net'}
<- SASL:[1793436274:0] SaslOutcome{code=OK, additionalData="Welcome!"}
-> AMQP:[1793436274:0] AMQP,0,1,0,0
<- AMQP:[1793436274:0] AMQP,0,1,0,0
-> AMQP:[1793436274:0] Open{
containerId='ID:c07c99d2-692b-4c77-bbbb-b56bfeb2e2e0:1:1', hostname='
cjtestmq.servicebus.windows.net', maxFrameSize=65536, channelMax=65535,
idleTimeOut=60000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=[ANONYMOUS-RELAY],
properties=null}
-> AMQP:[1793436274:0] Begin{remoteChannel=null, nextOutgoingId=0,
incomingWindow=1600, outgoingWindow=2147483647, handleMax=null,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
-> AMQP:[1793436274:0]
Attach{name='receiver-ID:c07c99d2-692b-4c77-bbbb-b56bfeb2e2e0:1:1:1:1',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testq', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=false,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testq', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=null, initialDeliveryCount=null,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
-> AMQP:[1793436274:0] Flow{nextIncomingId=null, incomingWindow=1600,
nextOutgoingId=0, outgoingWindow=2147483647, handle=0, deliveryCount=null,
linkCredit=10, available=null, drain=false, echo=null, properties=null}
<- AMQP:[1793436274:0] Open{
containerId='5ffc5786e5b94e6da195e4e1c4660dd8_G4', hostname='null',
maxFrameSize=65536, channelMax=4999, idleTimeOut=120000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
<- AMQP:[1793436274:0] Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=5000, outgoingWindow=1600, handleMax=255,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
<- AMQP:[1793436274:0]
Attach{name='receiver-ID:c07c99d2-692b-4c77-bbbb-b56bfeb2e2e0:1:1:1:1',
handle=0, role=SENDER, sndSettleMode=null, rcvSettleMode=null, source=null,
target=null, unsettled=null, incompleteUnsettled=null,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
-> AMQP:[1793436274:0] Close{error=Error{condition=null,
description='Sending peer attach had no initial delivery count', info=null}}
07:53:20,966  WARN ClientTransportListener:63 - Caught problem during
incoming data processing: Sending peer attach had no initial delivery count
For reference, when the username is valid:

-> SASL:[1793436274:0] AMQP,3,1,0,0
<- SASL:[1793436274:0] AMQP,3,1,0,0
<- SASL:[1793436274:0] SaslMechanisms{saslServerMechanisms=[MSSBCBS, PLAIN,
ANONYMOUS, EXTERNAL]}
-> SASL:[1793436274:0] SaslInit{mechanism=PLAIN,
initialResponse="\x00VALID_USERNAME\x00VALID_PASSWORD"...(truncated),
hostname='MY_HOST.servicebus.windows.net'}
<- SASL:[1793436274:0] SaslOutcome{code=OK, additionalData="Welcome!"}
-> AMQP:[1793436274:0] AMQP,0,1,0,0
<- AMQP:[1793436274:0] AMQP,0,1,0,0
-> AMQP:[1793436274:0] Open{
containerId='ID:412bf09f-70cc-44b2-a914-d3d40013b4e1:1:1', hostname='
cjtestmq.servicebus.windows.net', maxFrameSize=65536, channelMax=65535,
idleTimeOut=60000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=[ANONYMOUS-RELAY],
properties=null}
-> AMQP:[1793436274:0] Begin{remoteChannel=null, nextOutgoingId=0,
incomingWindow=1600, outgoingWindow=2147483647, handleMax=null,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
-> AMQP:[1793436274:0]
Attach{name='receiver-ID:412bf09f-70cc-44b2-a914-d3d40013b4e1:1:1:1:1',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testq', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=false,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testq', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=null, initialDeliveryCount=null,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}
-> AMQP:[1793436274:0] Flow{nextIncomingId=null, incomingWindow=1600,
nextOutgoingId=0, outgoingWindow=2147483647, handle=0, deliveryCount=null,
linkCredit=10, available=null, drain=false, echo=null, properties=null}
<- AMQP:[1793436274:0] Open{
containerId='e49f84f276a6432fb2ec8bcceebc993e_G28', hostname='null',
maxFrameSize=65536, channelMax=4999, idleTimeOut=120000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
<- AMQP:[1793436274:0] Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=5000, outgoingWindow=1600, handleMax=255,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
<- AMQP:[1793436274:0]
Attach{name='receiver-ID:412bf09f-70cc-44b2-a914-d3d40013b4e1:1:1:1:1',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testq', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=false,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testq', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=null, initialDeliveryCount=0,
maxMessageSize=18446744073709551615, offeredCapabilities=[SHARED-SUBS],
desiredCapabilities=null, properties=null}

Thank you.



--
Tim Bish


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@qpid.apache.org
For additional commands, e-mail: users-h...@qpid.apache.org

Reply via email to