Not logged in. · Lost password · Register
Forum: MatriX and XmppDotNet RSS
Problem connecting client
Missing or incomplete replies from server?
Avatar
Mario.d 2015-10-18, 23:13 #1
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Subject: Problem connecting client
Hi all,
I'm experiencing a strange behavior with OpenFire 3.9.3 that I'm not able to reproduce systematically: I wrote a Window service that connects multiple MatriX .NET clients, let's say 1 every 5 seconds. It occasionally happens that I get no OnLogin/OnBind events fired and so I quit for timeout after some time.

If I look at the client logs, nothing happens until my timer expires; if I look at the server, nothing is reported in Error/Warn/Info logs, but I found two different patterns in Debug:

when everything goes fine I see:

2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64881
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.NIOConnection - NIOConnection: startTLS: using c2s
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881]  doHandshake()
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881]   handshakeStatus=NEED_UNWRAP
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881]  unwrapHandshake()
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881]    inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=0 cap=16921]
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881]    appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33842 cap=33842]
2015.10.14 17:33:20 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/0:0:0:0:0:0:0:1:64881]  Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 0
2015.10.14 17:33:20 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64881

and when it doesn't I see:

2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:40 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:50 org.apache.mina.filter.executor.ExecutorFilter - Launching thread for /0:0:0:0:0:0:0:1:64890
2015.10.14 17:33:50 org.apache.mina.filter.executor.ExecutorFilter - Exiting since queue is empty for /0:0:0:0:0:0:0:1:64890

I'm not sure about that, but it seems to me that while in the first case everything happens within the same second, in the other case the thread exits without doing the doHandshake() stuff between the 40 and 50 seconds.

Can someone give me a hint?

Thank you for your replies
This post was edited on 2015-10-22, 13:59 by Alex.
Avatar
Alex 2015-10-19, 10:48 #2
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
Have you checked if Openfire has some mechanisms to throttle login attempts?
Many servers have something like that and don't allow more than X new connections fer second or minute to not overload the server.

MatriX does exactly the same for every connection. So I would say that you problem is somewhere on the server or its configuration.

I am not that familiar with Openfire logs. The programmers at the Openfire forums should be able to help there.

Alex
Avatar
Alex 2015-10-19, 10:57 #3
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
so you have a XML log of a client this happened? Then we can see where it stops, or if it connects and established the Xml stream at all.

Alex
Avatar
Mario.d 2015-10-20, 17:42 #4
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Hi Alex,
first of all, thank you for your replies.

I checked server settings, and they appear to be the same of other [working] installations; I don't know if the throttle mechanism you've mentioned is the connection manager feature, but nope, it isn't enabled.

But - after many hours of perfect working - I finally got a repro of the problem: one of the clients has started to get "timeout" errors.
I've enabled xml log as you pointed and these are the results:

one of the clients that happily connect has dumped:

  1. 2015-10-20 16:49:43,238 [7] Opening XmppClient connection
  2. 2015-10-20 16:49:43,238 [7] Adding nick 85e73261-9d8a-4aca-9a64-2542b4c9999a to list
  3. 2015-10-20 16:49:43,238 [20] SEND: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="xmpp-saf" version="1.0" >
  4. 2015-10-20 16:49:43,238 [21] RECV: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="plpswh02" id="a0e35e14" xml:lang="en" version="1.0" >
  5. 2015-10-20 16:49:43,238 [20] RECV: <stream:features xmlns:stream="http://etherx.jabber.org/streams">
  6.  <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
  7.  <mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl">
  8.     <mechanism>DIGEST-MD5</mechanism>
  9.     <mechanism>PLAIN</mechanism>
  10.     <mechanism>ANONYMOUS</mechanism>
  11.     <mechanism>CRAM-MD5</mechanism>
  12.  </mechanisms>
  13.  <compression xmlns="http://jabber.org/features/compress">
  14.     <method>zlib</method>
  15.  </compression>
  16.  <auth xmlns="http://jabber.org/features/iq-auth" />
  17. </stream:features>
  18. 2015-10-20 16:49:43,238 [20] SEND: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
  19. 2015-10-20 16:49:43,238 [20] RECV: <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
  20. 2015-10-20 16:49:43,316 [20] SEND: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="xmpp-saf" version="1.0" >
  21. 2015-10-20 16:49:43,316 [20] RECV: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="plpswh02" id="a0e35e14" xml:lang="en" version="1.0" >
  22. 2015-10-20 16:49:43,316 [20] RECV: <stream:features xmlns:stream="http://etherx.jabber.org/streams">
  23.  <mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl">
  24.     <mechanism>DIGEST-MD5</mechanism>
  25.     <mechanism>PLAIN</mechanism>
  26.     <mechanism>ANONYMOUS</mechanism>
  27.     <mechanism>CRAM-MD5</mechanism>
  28.  </mechanisms>
  29.  <compression xmlns="http://jabber.org/features/compress">
  30.     <method>zlib</method>
  31.  </compression>
  32.  <auth xmlns="http://jabber.org/features/iq-auth" />
  33. </stream:features>
  34. 2015-10-20 16:49:43,316 [20] SEND: <auth mechanism="ANONYMOUS" xmlns="urn:ietf:params:xml:ns:xmpp-sasl" />
  35. 2015-10-20 16:49:43,316 [20] RECV: <success xmlns="urn:ietf:params:xml:ns:xmpp-sasl" />
  36. 2015-10-20 16:49:43,316 [20] OnLogin event received
  37. 2015-10-20 16:49:43,316 [20] SEND: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="xmpp-saf" version="1.0" >
  38. 2015-10-20 16:49:43,316 [20] RECV: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="plpswh02" id="a0e35e14" xml:lang="en" version="1.0" >
  39. 2015-10-20 16:49:43,316 [20] RECV: <stream:features xmlns:stream="http://etherx.jabber.org/streams">
  40.  <compression xmlns="http://jabber.org/features/compress">
  41.     <method>zlib</method>
  42.  </compression>
  43.  <bind xmlns="urn:ietf:params:xml:ns:xmpp-bind" />
  44.  <session xmlns="urn:ietf:params:xml:ns:xmpp-session" />
  45. </stream:features>
  46. 2015-10-20 16:49:43,316 [20] SEND: <iq id="MX_26" type="set" xmlns="jabber:client">
  47.  <bind xmlns="urn:ietf:params:xml:ns:xmpp-bind">
  48.     <resource />
  49.  </bind>
  50. </iq>
  51. 2015-10-20 16:49:43,316 [20] RECV: <iq type="result" id="MX_26" to="plpswh02/a0e35e14" xmlns="jabber:client">
  52.  <bind xmlns="urn:ietf:params:xml:ns:xmpp-bind">
  53.     <jid>a0e35e14@plpswh02/a0e35e14</jid>
  54.  </bind>
  55. </iq>
  56. 2015-10-20 16:49:43,316 [20] OnBind event received: Jid = a0e35e14@plpswh02/a0e35e14

while the one gone in timeout has dumped:

  1. 2015-10-20 16:09:29,570 [7] Opening XmppClient connection
  2. 2015-10-20 16:09:29,570 [7] Adding nick de71116e-d40c-4681-82d5-980098be2b71 to list
  3. 2015-10-20 16:09:29,570 [8] SEND: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="xmpp-saf" version="1.0" >
  4. 2015-10-20 16:09:29,570 [10] RECV: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="plpswh02" id="a1f8e315" xml:lang="en" version="1.0" >
  5. 2015-10-20 16:09:29,570 [10] RECV: <stream:features xmlns:stream="http://etherx.jabber.org/streams">
  6.  <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
  7.  <mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl">
  8.     <mechanism>DIGEST-MD5</mechanism>
  9.     <mechanism>PLAIN</mechanism>
  10.     <mechanism>ANONYMOUS</mechanism>
  11.     <mechanism>CRAM-MD5</mechanism>
  12.  </mechanisms>
  13.  <compression xmlns="http://jabber.org/features/compress">
  14.     <method>zlib</method>
  15.  </compression>
  16.  <auth xmlns="http://jabber.org/features/iq-auth" />
  17. </stream:features>
  18. 2015-10-20 16:09:59,585 [6] Timeout waiting for OnBind event

The only difference to me is the nickname (we use guids with anonymous login); the end of the story is that after about 20 attempts, it got connected.

MatriX version is 1.6.0.6.

Thanks again
This post was edited on 2015-10-20, 18:03 by Alex.
Avatar
Alex 2015-10-20, 18:09 #5
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
I see no errors in your log.

In the log where it fails the next would be MatriX sending the startTls commands. But they don't appear in the log.
Are you also subscribed to all the OnError events in MatriX?
When MatriX gets the stream features then it always proceeds with either Tls or authentication. I cannot see from the log while it stops here for this single client only.

Alex
Avatar
Mario.d 2015-10-21, 12:03 #6
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Hi Alex, thanks again.

The OnError events says:
XmppClient_OnError - Matrix.XmppStreamException: Unable to send data. The XMPP Stream is inactive

Cheers
Avatar
Mario.d 2015-10-21, 14:35 #7
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Quote by Mario.d:
Hi Alex, thanks again.

The OnError events says:
XmppClient_OnError - Matrix.XmppStreamException: Unable to send data. The XMPP Stream is inactive

Cheers

addendum: the Open() call and following OnError() come in the same millisecond
Avatar
Alex 2015-10-21, 18:29 #8
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
Are you calling teh Open on a XmppClient instance which was connected before and then got a disconnect?
if yes, can you try to set the current XmppClient to null and recreate you new one with your properties?

Alex
Avatar
Mario.d 2015-10-21, 19:21 #9
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Nup, there's a class wrapping the XmppClient, and the program creates a new instance for each message to dispatch and releases it when the process completes successfully or by timeout.

The message dispatching, then, is controlled by a timer: every X seconds a new instance is created, and in these tests, no more than 50 connections runs simultaneously.
Avatar
Alex 2015-10-21, 20:57 #10
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
this is strange, we have seen this problem only with older builds where users were reusing XmppClients and calling Open twice.
If you don't reuse the XmppClient I have no idea whats going on. We would need  a test case then to reproduce.
Also have you tried updating to the latest 2.x version on Nuget?

Alex
Avatar
Mario.d 2015-10-22, 13:03 #11
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Hi Alex,
I think we have to find a different solution, because the only site where we are able to reproduce this behaviour is at one of our customers so we can't freely run test cases there.
Also changing the library version is not an option because the new version should be tested for weeks in our labs (where, by the way, the problem doesn't appear) and our customer cannot wait weeks for a solution.
The only thing we can do, is to install there a version of the 1.6 library instrumented with some more logs to help you to collect additional information.
Let me know your thoughts.
Avatar
Alex 2015-10-22, 14:06 #12
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
What is the exact version number of 1.6.X.X you are running there? You can also attach the dll to this thread and we can find out.

For logs it would help to log all Xml and all MatriX events with exact timestamps.
In teh Xml log you posted before I see only your timeout becasue there is not OnBind for 30 seconds. I don't see the exception logged you mentioned before:
Unable to send data. The XMPP Stream is inactive

Alex
Avatar
Mario.d 2015-10-22, 15:25 #13
Member since Oct 2015 · 7 posts
Group memberships: Members
Show profile · Link to this post
Ok, this is a portion of the log of one of the last accidents, we're having a lot today...

2015-10-22 14:54:33,110 [12] INFO: New message from gws_test
2015-10-22 14:54:33,110 [12] DEBUG: XmppConnector XmppHandler0 - PushMessage from account gws_test
2015-10-22 14:54:33,157 [7] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - Creating XmppMessagePusher object, ClientNickName = b95263aa-fad2-4a63-8503-0bda02f1f489
2015-10-22 14:54:33,157 [7] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - Creating Matrix XmppClient with SubDomain xmpp-saf
2015-10-22 14:54:33,157 [7] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - Creating Matrix MucManager
2015-10-22 14:54:33,157 [7] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - Creating Matrix PresenceManager
2015-10-22 14:54:33,157 [7] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - XmppMessagePusher created
2015-10-22 14:54:33,157 [7] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - Opening XmppClient connection
2015-10-22 14:54:33,157 [7] DEBUG: XmppConnector XmppHandler0 - Adding nick b95263aa-fad2-4a63-8503-0bda02f1f489 to list
2015-10-22 14:54:33,157 [4] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - SEND: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="xmpp-saf" version="1.0" >
2015-10-22 14:54:33,157 [3] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - RECV: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" from="plpswh02" id="3164cd12" xml:lang="en" version="1.0" >
2015-10-22 14:54:33,157 [3] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - RECV: <stream:features xmlns:stream="http://etherx.jabber.org/streams">
  <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls" />
  <mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl">
    <mechanism>DIGEST-MD5</mechanism>
    <mechanism>PLAIN</mechanism>
    <mechanism>ANONYMOUS</mechanism>
    <mechanism>CRAM-MD5</mechanism>
  </mechanisms>
  <compression xmlns="http://jabber.org/features/compress">
    <method>zlib</method>
  </compression>
  <auth xmlns="http://jabber.org/features/iq-auth" />
</stream:features>
2015-10-22 14:54:33,157 [3] ERROR: XmppMessagePusher gws_test635811164521550513.xmm - XmppClient_OnError
Matrix.XmppStreamException: Unable to send data. The XMPP Stream is inactive
2015-10-22 14:54:33,157 [3] DEBUG: XmppMessagePusher gws_test635811164521550513.xmm - XmppClient_OnError: aborting current connection attempt
2015-10-22 14:54:33,157 [3] INFO: CloseMessage: message was not handled

Please note that we've changed the way we handle the OnError: since that error appears unrecoverable, we abort the connection and close the request. So you won't see anymore
Timeout...
but
Aborting...

MatriX .NET library 1.6.0.6

Hope this helps
Avatar
Alex 2015-10-23, 12:05 #14
Member since Feb 2003 · 4449 posts · Location: Germany
Group memberships: Administrators, Members
Show profile · Link to this post
Hello,

we studied the codes again.
I see only 2 reasons why you can get this error:

1) the xmpp server, a firewall or something else kills the socket during the login process
2) there is something in your code which is calling xmppClient.Open() twice, or xmppClient.Send() or something similar while connection is not ready yet.

I don't think that we can solve this without having a test case where we can reproduce this in our labs and study your logic and code.

Alex
Close Smaller – Larger + Reply to this post:
Verification code: VeriCode Please enter the word from the image into the text field below. (Type the letters only, lower case is okay.)
Smileys: :-) ;-) :-D :-p :blush: :cool: :rolleyes: :huh: :-/ <_< :-( :'( :#: :scared: 8-( :nuts: :-O
Special characters:

Forum: MatriX and XmppDotNet RSS