Issue with stream management | Android #2020

sandeepjangir · 2018-08-05T19:42:03Z

MongooseIM version: 3.0
Installed from: source
Erlang/OTP version: latest with MIM3.0

Hi

We are developing the messaging mobile application with MIM with stream management enabled but sometimes in the Android client we encounter the error by stream management feature.
The android error description is below:

closed with error
    org.jivesoftware.smack.SmackException: Parser got END_DOCUMENT event. This could happen e.g. if the server closed the connection without sending a closing stream element

Note: we were using the ejabberd server as well and the same code and configuration is working well there; now we are not understanding what the issue and how to fix it because this is not a regular issue and we are not facing to other XMPP servers (ejabberd) even a single time.

We are very much confused whether this is client side issue or server-side. and we really want to move our app to MIM but due to this, we are facing the problem.

Thanks
Sandeep Jangir

The text was updated successfully, but these errors were encountered:

fenek · 2018-08-06T04:42:03Z

Hi @sandy5487

Have you checked if the problem disappears with stream management disabled?

sandeepjangir · 2018-08-06T06:51:57Z

Hi @fenek

yes, I have tried with stream management disabled as well but the problem is same and one observation is this that the problem is not persistent, sometimes it happens and sometimes its working fine. But in ejabberd server, this is working fine and when we move the server to mongooseim this thing starts occurring.

Now we are confused where is the issue on the client side or the server side?

arcusfelis · 2018-08-06T08:19:03Z

@sandy5487 Do you have anything in logs?

sandeepjangir · 2018-08-06T08:19:30Z

Hi @fenek , @arcusfelis

there is one obervation from my side that when we receive any message from offline queue this error appears and our logs on clients side are:

<r xmlns="urn:xmpp:sm:3"/>


<a xmlns="urn:xmpp:sm:3" h="28"/>


<r xmlns="urn:xmpp:sm:3"/>


<a xmlns="urn:xmpp:sm:3" h="29"/>


<message id="SlKqe-29" xml:lang="en" to="sandeep@im.mydomain.com" from="6-6001_127-otr@im.mydomain.com/9FC13CA79576A29A1533542160763220">
<body>Hello Sandeep</body>
<stanza-id xmlns="urn:xmpp:sid:0" id="ASLVJGP11V81" by="sandeep@im.mydomain.com"/>
<delay xmlns="urn:xmpp:delay" stamp="2018-08-06T07:56:08.400871Z" from="localhost">SM Storage</delay>
</message>

PS: we are connecting server with multiple accounts parralel for our in app requirement

Thanks

fenek · 2018-08-06T08:58:19Z

In normal operation MongooseIM always sends closing stream element. I'll try to create a branch with extended logging so we might pinpoint the reason for this disconnection.

sandeepjangir · 2018-08-06T09:11:00Z

@fenek

when can I expect an update on this?

fenek · 2018-08-06T09:27:35Z

Hopefully later today.

sandeepjangir · 2018-08-06T17:05:02Z

Hi

one more thing observed in mongooseim logs which are:

2018-08-06 16:54:33.846 [error] <0.3362.0>@ejabberd_c2s:process_incoming_stanza_with_conflict_check:1322 event=conflict_check_failed jid=6-6001_254@im.mydomain.com/A-6001-866463039255503 c2s_sid={{1533,574432,432889},<0.3362.0>} origin_sid={{1533,574396,661903},<0.3251.0>} acc=#{attrs => [{<<"xml:lang">>,<<"en">>},{<<"id">>,<<"2GjTE-529">>}],element => {xmlel,<<"presence">>,[{<<"xml:lang">>,<<"en">>},{<<"id">>,<<"2GjTE-529">>}],[{xmlel,<<"c">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/caps">>},{<<"hash">>,<<"sha-1">>},{<<"node">>,<<"http://www.igniterealtime.org/projects/smack">>},{<<"ver">>,<<"tUtPo6aj3mjjQWfXQO8eNy8Pwm8=">>}],[]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"6-6001_72@im.mydomain.com/A-6001-358187074823074">>},{<<"stamp">>,<<"2018-08-06T16:50:54Z">>}],[{xmlcdata,<<>>}]}]},from => <<"6-6001_254@im.mydomain.com/A-6001-866463039255503">>,from_jid => {jid,<<"6-6001_254">>,<<"im.mydomain.com">>,<<"A-6001-866463039255503">>,<<"6-6001_254">>,<<"im.mydomain.com">>,<<"A-6001-866463039255503">>},mongoose_acc => true,name => <<"presence">>,persistent_properties => [{origin_jid,{jid,<<"6-6001_254">>,<<"im.mydomain.com">>,<<"A-6001-866463039255503">>,<<"6-6001_254">>,<<"im.mydomain.com">>,<<"A-6001-866463039255503">>}},{origin_sid,{{1533,574396,661903},<0.3251.0>}}],ref => #Ref<0.4014134408.1798569986.190890>,server => <<"im.mydomain.com">>,timestamp => {1533,574397,595346},to_jid => {jid,<<"6-6001_254">>,<<"im.mydomain.com">>,<<>>,<<"6-6001_254">>,<<"im.mydomain.com">>,<<>>},type => undefined,user => <<"6-6001_254">>}
2018-08-06 16:56:28.728 [error] <0.3910.0>@ejabberd_router:route:525 error when routing from=sandeep@im.mydomain.com to=6-6001_115@im.mydomain.com in module=mongoose_router_localdomain

reason={{badrecord,jid},[{mongoose_router_localdomain,route,4,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/mongoose_router_localdomain.erl"},{line,24}]},{ejabberd_router,route,5,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/ejabberd_router.erl"},{line,523}]},{ejabberd_c2s,'-re_route_packets/1-lc$^0/1-0-',1,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/ejabberd_c2s.erl"},{line,3136}]},{ejabberd_c2s,re_route_packets,1,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/ejabberd_c2s.erl"},{line,3136}]},{ejabberd_c2s,reroute_unacked_messages,1,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/ejabberd_c2s.erl"},{line,1709}]},{ejabberd_c2s,terminate,3,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/ejabberd_c2s.erl"},{line,1701}]},{p1_fsm_old,terminate,7,[{file,"/root/MongooseIM-3.0.0/_build/prod/lib/mongooseim/src/p1_fsm_old.erl"},{line,709}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}

packet=<presence from='sandeep@im.mydomain.com' to='6-6001_115@im.mydomain.com' type='subscribe'><status></status></presence>

sandeepjangir · 2018-08-06T18:26:34Z

Hi @fenek

any update on this?

arcusfelis · 2018-08-06T21:57:41Z

ejabberd_c2s:process_incoming_stanza_with_conflict_check warning is expected behaviour, just signals that stanza expired and non-relevant. But we can check, that the conflict detection code works correctly with session resumption.

badrecord is actually bug.

route(From, To, Acc, Packet) ->                                                      
    LDstDomain = To#jid.lserver,

We would need to figure out why To is not record.

Also, a routing error is not a reason to close a connection.

@sandy5487 more info can be found in crash.log.

arcusfelis · 2018-08-06T21:59:49Z

@sandy5487
We usually debug such errors with tcp-dump and higher loglevel (debug: 5). Tcp-dump means no TLS encryption.
If the bug happens not on production.

sandeepjangir · 2018-08-07T03:39:04Z

@fenek @arcusfelis

Yes, this issue is not the reason of disconnection but I am still not sure why the connection disconnects on client's side when a message packet receives and again that I said it only happens sometimes not always.

sandeepjangir · 2018-08-07T15:12:43Z

Hi @fenek

still waiting for your update

fenek · 2018-08-24T16:16:40Z

Hi @sandy5487

I'm sorry for the delay, I couldn't re-inspect this issue earlier. :( According to the last logs you've provided, I think it is fairly probable that it's a bug in Client State Indication implementation. Can you please check if the problem disappears when you disable it on the client side?

sandeepjangir · 2018-08-24T16:27:06Z

Hello @fenek

Yes, I have also tried to disable the stream management on the client side but the issue is the same.
But I have found one observation that whenever there are messages in offline queue and clients receive those messages then it usually got the end of document error and client gets disconnected from the server.

Thanks

fenek · 2018-08-24T19:12:44Z

Actually ignore my previous comment. I was able to find and fix 3 distinct bugs or issues in stream resumption process. You were very unlucky to trigger them, it's really difficult to reach these code fragments. :)

Please give this branch a try: https://github.com/esl/MongooseIM/tree/c2s-resumption-edge-cases
It should resolve all problems described in this ticket.

Writing regression tests for these will be much more difficult than fixing them, so I'll add them a bit later. It also means that I'm not 100% certain that this fix is completely correct. Anyway, please check it. It should make conflict_check_failed logs less frequent, eliminate END_DOCUMENT issue and fix reason={{badrecord,jid} crash.

sandeepjangir · 2018-08-30T08:56:06Z

Hi @fenek

we have tried again and while reproducing the same error we are facing the similar issue:
here is the error log.

when the user is getting offline messages this error occurs.

and getting END_OF_DOCUMENT on the client side.

08:36:59.006 [info] Timeout on ejabberd_tls:send 08:36:59.006 [debug] Send element error: error, try enter resume session 08:36:59.006 [debug] targets [] from resources [{0,<<"ANDROID">>}] and ccenabled [] 08:36:59.007 [debug] Send XML on stream = <<"<message from='sandeep@mg.myappdomain.com/Sandeeps-MacBook-Pro' to='918128184101@mg.myappdomain.com' type='chat' id='purple81f97925'><active xmlns='http://jabber.org/protocol/chatstates'/><body>3</body><stanza-id by='918128184101@mg.myappdomain.com' id='AT52UVU16901' xmlns='urn:xmpp:sid:0'/><delay xmlns='urn:xmpp:delay' stamp='2018-08-30T08:36:17.570833Z' from='mg.myappdomain.com'>Offline Storage</delay></message>">> 08:36:59.007 [debug] Error in ejabberd_tls:send: {error,enotconn} 08:36:59.007 [debug] Send element error: error, try enter resume session 08:36:59.007 [debug] targets [] from resources [{0,<<"ANDROID">>}] and ccenabled [] 08:36:59.007 [debug] Send XML on stream = <<"<message from='sandeep@mg.myappdomain.com/Sandeeps-MacBook-Pro' to='918128184101@mg.myappdomain.com' type='chat' id='purple81f97926'><active xmlns='http://jabber.org/protocol/chatstates'/><body>4</body><stanza-id by='918128184101@mg.myappdomain.com' id='AT52V01LIU81' xmlns='urn:xmpp:sid:0'/><delay xmlns='urn:xmpp:delay' stamp='2018-08-30T08:36:18.047349Z' from='mg.myappdomain.com'>Offline Storage</delay></message>">> 08:36:59.007 [debug] Error in ejabberd_tls:send: {error,enotconn} 08:36:59.007 [debug] Send element error: error, try enter resume session 08:36:59.007 [debug] targets [] from resources [{0,<<"ANDROID">>}] and ccenabled [] 08:36:59.007 [debug] Send XML on stream = <<"<message from='sandeep@mg.myappdomain.com/Sandeeps-MacBook-Pro' to='918128184101@mg.myappdomain.com' type='chat' id='purple81f97927'><active xmlns='http://jabber.org/protocol/chatstates'/><body>5</body><stanza-id by='918128184101@mg.myappdomain.com' id='AT52V04N62G1' xmlns='urn:xmpp:sid:0'/><delay xmlns='urn:xmpp:delay' stamp='2018-08-30T08:36:18.447283Z' from='mg.myappdomain.com'>Offline Storage</delay></message>">>

GalaxyGorilla · 2018-08-31T12:00:18Z

So, this is also solved due to the timeout stuff in #2022?

fenek · 2018-08-31T12:19:23Z

I think it is a combination of the 3 fixes I've added and the timeout fix. :)

sudhamab · 2019-01-03T10:51:06Z

@fenek Could you please confirm if these changes are in the release 3.2.0?

fenek · 2019-01-07T05:15:37Z

Hi @sudhamab

No, these fixes are not included in 3.2.0.

fenek added the community Non ESL issues and PRs label Aug 6, 2018

fenek self-assigned this Aug 6, 2018

fenek mentioned this issue Aug 24, 2018

Fix 3 issues in SM resumption #2049

Merged

5 tasks

fenek closed this as completed Nov 27, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issue with stream management | Android #2020

Issue with stream management | Android #2020

sandeepjangir commented Aug 5, 2018 •

edited

Loading

fenek commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

arcusfelis commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018 •

edited

Loading

fenek commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

fenek commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

arcusfelis commented Aug 6, 2018

arcusfelis commented Aug 6, 2018 •

edited

Loading

sandeepjangir commented Aug 7, 2018

sandeepjangir commented Aug 7, 2018

fenek commented Aug 24, 2018

sandeepjangir commented Aug 24, 2018

fenek commented Aug 24, 2018

sandeepjangir commented Aug 30, 2018 •

edited

Loading

GalaxyGorilla commented Aug 31, 2018

fenek commented Aug 31, 2018

sudhamab commented Jan 3, 2019

fenek commented Jan 7, 2019

Issue with stream management | Android #2020

Issue with stream management | Android #2020

Comments

sandeepjangir commented Aug 5, 2018 • edited Loading

fenek commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

arcusfelis commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018 • edited Loading

fenek commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

fenek commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

sandeepjangir commented Aug 6, 2018

arcusfelis commented Aug 6, 2018

arcusfelis commented Aug 6, 2018 • edited Loading

sandeepjangir commented Aug 7, 2018

sandeepjangir commented Aug 7, 2018

fenek commented Aug 24, 2018

sandeepjangir commented Aug 24, 2018

fenek commented Aug 24, 2018

sandeepjangir commented Aug 30, 2018 • edited Loading

GalaxyGorilla commented Aug 31, 2018

fenek commented Aug 31, 2018

sudhamab commented Jan 3, 2019

fenek commented Jan 7, 2019

sandeepjangir commented Aug 5, 2018 •

edited

Loading

sandeepjangir commented Aug 6, 2018 •

edited

Loading

arcusfelis commented Aug 6, 2018 •

edited

Loading

sandeepjangir commented Aug 30, 2018 •

edited

Loading