{"action":"opened","issue":{"url":"https://api.github.com/repos/siacs/Conversations/issues/1938","repository_url":"https://api.github.com/repos/siacs/Conversations","labels_url":"https://api.github.com/repos/siacs/Conversations/issues/1938/labels{/name}","comments_url":"https://api.github.com/repos/siacs/Conversations/issues/1938/comments","events_url":"https://api.github.com/repos/siacs/Conversations/issues/1938/events","html_url":"https://github.com/siacs/Conversations/issues/1938","id":163516897,"number":1938,"title":"SMACKS session resume not working half of the time","user":{"login":"tmolitor-stud-tu","id":6234248,"avatar_url":"https://avatars.githubusercontent.com/u/6234248?v=3","gravatar_id":"","url":"https://api.github.com/users/tmolitor-stud-tu","html_url":"https://github.com/tmolitor-stud-tu","followers_url":"https://api.github.com/users/tmolitor-stud-tu/followers","following_url":"https://api.github.com/users/tmolitor-stud-tu/following{/other_user}","gists_url":"https://api.github.com/users/tmolitor-stud-tu/gists{/gist_id}","starred_url":"https://api.github.com/users/tmolitor-stud-tu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tmolitor-stud-tu/subscriptions","organizations_url":"https://api.github.com/users/tmolitor-stud-tu/orgs","repos_url":"https://api.github.com/users/tmolitor-stud-tu/repos","events_url":"https://api.github.com/users/tmolitor-stud-tu/events{/privacy}","received_events_url":"https://api.github.com/users/tmolitor-stud-tu/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2016-07-02T12:40:57Z","updated_at":"2016-07-02T12:40:57Z","closed_at":null,"body":"#### General information\r\n\r\n* **Version:** 1.13.3\r\n* **Device:** LG D605\r\n* **Android Version:** Android 4.4.2 Stock\r\n* **Server name:** self hosted\r\n* **Server software:** latest prosody 0.10\r\n* **Installed server modules:** Stream Managment, CSI, MAM, throttle_presence, filter_chatstates\r\n* **Conversations source:** PlayStore\r\n\r\n\r\n#### Steps to reproduce\r\n\r\n1. Put device in plain mode, wait some time (~ 10 minutes)\r\n2. Switch plain mode off again and let Conversations reconnect\r\n3. Watch your server logs to see if the session got resumed\r\n\r\n\r\n#### Expected result\r\n\r\nI'm expecting Conversations to resume the session, but often it doesn't.\r\nI would guess about 50% of reconnects don't resume properly.\r\nSee the attached server logs and adb output of the last incident.\r\n\r\n\r\n#### Debug output\r\n\r\n````\r\nadb logcat -v time -s conversations\r\n* daemon not running. starting it now on port 5037 *\r\n* daemon started successfully *\r\n--------- beginning of /dev/log/system\r\n--------- beginning of /dev/log/main\r\n07-01 22:22:28.800 D/conversations(14015): resetting all attempt counts\r\n07-01 22:22:28.850 D/conversations(14015): user@example.org: push mode false\r\n07-01 22:22:29.311 D/conversations(14015): user@example.org: connecting\r\n07-01 22:22:29.571 D/conversations(14015): using dns server: 192.168.2.1 to look up example.org\r\n07-01 22:22:47.330 D/conversations(14015): ignoring timeout exception when querying AAAA record on 192.168.2.1\r\n07-01 22:22:47.400 D/conversations(14015): user@example.org: using values from dns example.org[1.2.3.4]:5222 tls: false\r\n07-01 22:22:51.284 D/conversations(14015): user@example.org: TLS connection established\r\n07-01 22:22:51.675 D/conversations(14015): user@example.org/phone: Authenticating with SCRAM-SHA-1\r\n07-01 22:22:52.886 D/conversations(14015): user@example.org: logged in\r\n07-01 22:22:53.216 D/conversations(14015): user@example.org: starting service discovery\r\n07-01 22:22:53.316 D/conversations(14015): user@example.org: stream management(3) enabled (resumable)\r\n07-01 22:22:53.977 D/conversations(14015): user@example.org: server name: Prosody\r\n07-01 22:22:54.117 D/conversations(14015): user@example.org: has pep but is not persistent\r\n07-01 22:22:54.227 D/conversations(14015): user@example.org: successfully enabled carbons\r\n07-01 22:22:56.730 D/conversations(14015): AxolotlService (user@example.org): Bundle 1715417867 in PEP was current\r\n07-01 22:22:56.730 D/conversations(14015): AxolotlService (user@example.org): Announcing device 1715417867\r\n07-01 22:22:56.830 D/conversations(14015): user@example.org: online with resource phone\r\n07-01 22:22:56.830 D/conversations(14015): user@example.org: fetching roster\r\n07-01 22:22:56.940 D/conversations(14015): user@example.org: has push support\r\n07-01 22:22:57.070 D/conversations(14015): user@example.org: running mam query with=*, start=2016-07-01T20:08:56.167Z, end=2016-07-01T20:22:53.286Z\r\n07-01 22:22:57.080 D/conversations(14015): user@example.org sending csi//inactive\r\n07-01 22:22:57.251 D/conversations(14015): AxolotlService (user@example.org): Received PEP device list update from user@example.org, processing...\r\n07-01 22:22:57.251 D/conversations(14015): AxolotlService (user@example.org): Received non-empty own device list. Resetting publish attempts and pepBroken status.\r\n07-01 22:22:57.331 D/conversations(14015): AxolotlService (user@example.org): Received PEP device list update from userB@example.org, processing...\r\n07-01 22:22:57.781 D/conversations(14015): skipping duplicate message from userB@example.org Ich werd' jetzt den Fehler auslÃ¶sen, oder es zumindest versuchen.\r\n07-01 22:22:58.192 D/conversations(14015): user@example.org: finished mam after 11 messages. messages left=true\r\n07-01 22:22:59.863 D/conversations(14015): user@example.org: invalid response from app server\r\n07-01 22:22:59.954 D/conversations(14015): resetting all attempt counts\r\n07-01 22:23:08.883 D/conversations(14015): app switched into foreground\r\n07-01 22:23:23.348 D/conversations(14015): resetting all attempt counts\r\n07-01 22:24:43.354 D/conversations(14015): app switched into background\r\n07-01 22:24:44.195 D/conversations(14015): app switched into foreground\r\n07-01 22:25:05.047 D/conversations(14015): app switched into background\r\n07-01 22:25:54.199 D/conversations(14015): user@example.org: activating grace period till 22:28:18\r\n````\r\n\r\n````\r\nProsody log:\r\n\r\nJul 01 22:09:02 c2s969cd58      debug   Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='70'>\r\nJul 01 22:09:02 c2s969cd58      debug   ACK: h=70, last=69\r\nJul 01 22:09:02 c2s969cd58      debug   #queue = 0\r\nJul 01 22:09:51 c2s969cd58      debug   #queue = 1\r\nJul 01 22:09:51 c2s969cd58      debug   Queuing <r> (in a moment)\r\nJul 01 22:09:51 c2s969cd58      debug   Sending <r> (after send)\r\nJul 01 22:09:51 c2s969cd58      debug   Sending <r> (really after send)\r\nJul 01 22:11:50 c2s969cd58      debug   #queue = 2\r\nJul 01 22:12:18 c2s969cd58      debug   #queue = 3\r\nJul 01 22:13:57 c2s969cd58      debug   #queue = 4\r\nJul 01 22:14:13 c2s969cd58      debug   #queue = 5\r\nJul 01 22:14:27 c2s969cd58      debug   #queue = 6\r\nJul 01 22:22:48 c2s9aceb68      info    Client connected\r\nJul 01 22:22:48 c2s9aceb68      debug   Client sent opening <stream:stream> to example.org\r\nJul 01 22:22:48 c2s9aceb68      debug   Sent reply <stream:stream> to client\r\nJul 01 22:22:48 c2s9aceb68      debug   Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>\r\nJul 01 22:22:48 c2s9aceb68      debug   TLS negotiation started for c2s_unauthed...\r\nJul 01 22:22:52 c2s9aceb68      debug   Client sent opening <stream:stream> to example.org\r\nJul 01 22:22:52 c2s9aceb68      debug   Sent reply <stream:stream> to client\r\nJul 01 22:22:52 c2s9aceb68      info    Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-SHA)\r\nJul 01 22:22:52 c2s9aceb68      debug   Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>\r\nJul 01 22:22:53 c2s9aceb68      debug   Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>\r\nJul 01 22:22:53 c2s9aceb68      info    Authenticated as user@example.org\r\nJul 01 22:22:53 c2s9aceb68      debug   Client sent opening <stream:stream> to example.org\r\nJul 01 22:22:53 c2s9aceb68      debug   Sent reply <stream:stream> to client\r\nJul 01 22:22:54 c2s9aceb68      debug   Received[c2s]: <iq id='c43pamuo8m' type='set'>\r\nJul 01 22:22:54 c2s969cd58      debug   Disconnecting client, <stream:error> is: <stream:error><conflict xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xmlns='urn:ietf:params:xml:ns:xmpp-streams'>Replaced by new connection</text></stream:error>\r\nJul 01 22:22:54 c2s969cd58      debug   c2s stream for user@example.org/phone closed: Replaced by new connection\r\nJul 01 22:22:54 c2s969cd58      debug   Destroying session for user@example.org/phone (user@example.org): Replaced by new connection\r\nJul 01 22:22:54 c2s969cd58      warn    Destroying session with 6 unacked stanzas\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <message type='error' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <message type='error' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <message type='error' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <message type='error' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <message type='error' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <message type='error' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s969cd58      debug   Handled 37 incoming stanzas\r\nJul 01 22:22:54 c2s969cd58      debug   Received[c2s]: <presence type='unavailable'>\r\nJul 01 22:22:54 c2s9aceb68      debug   Resource bound: user@example.org/phone\r\nJul 01 22:22:54 c2s969cd58      info    Client disconnected: closed\r\nJul 01 22:22:54 c2s969cd58      debug   Destroying session for (unknown) ((unknown)@(unknown)): closed\r\nJul 01 22:22:54 c2s9aceb68      debug   Received[c2s]: <enable xmlns='urn:xmpp:sm:3' resume='true'>\r\nJul 01 22:22:54 c2s9aceb68      debug   Handled 1 incoming stanzas\r\nJul 01 22:22:54 c2s9aceb68      debug   Received[c2s]: <iq id='mjsf0lpo3v' type='get' to='example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s9aceb68      debug   #queue = 1\r\nJul 01 22:22:54 c2s9aceb68      debug   Queuing <r> (in a moment)\r\nJul 01 22:22:54 c2s9aceb68      debug   Handled 2 incoming stanzas\r\nJul 01 22:22:54 c2s9aceb68      debug   Received[c2s]: <iq id='2q41qj93ne' type='get' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s9aceb68      debug   #queue = 2\r\nJul 01 22:22:54 c2s9aceb68      debug   Handled 3 incoming stanzas\r\nJul 01 22:22:54 c2s9aceb68      debug   Received[c2s]: <iq id='tf1vdf93g2' type='get' to='example.org' from='user@example.org/phone'>\r\nJul 01 22:22:54 c2s9aceb68      debug   #queue = 3\r\nJul 01 22:22:54 c2s9aceb68      debug   Sending <r> (after send)\r\nJul 01 22:22:54 c2s9aceb68      debug   Sending <r> (really after send)\r\nJul 01 22:22:54 c2s9aceb68      debug   Received[c2s]: <r xmlns='urn:xmpp:sm:3'>\r\nJul 01 22:22:55 c2s9aceb68      debug   Handled 4 incoming stanzas\r\nJul 01 22:22:55 c2s9aceb68      debug   Received[c2s]: <iq id='ekj5ah7tjq' type='set' from='user@example.org/phone'>\r\nJul 01 22:22:55 c2s9aceb68      debug   #queue = 4\r\nJul 01 22:22:55 c2s9aceb68      debug   Handled 5 incoming stanzas\r\nJul 01 22:22:55 c2s9aceb68      debug   Received[c2s]: <iq id='uhvql70gq0' type='get' from='user@example.org/phone'>\r\nJul 01 22:22:55 c2s9aceb68      debug   #queue = 5\r\nJul 01 22:22:55 c2s9aceb68      debug   Handled 6 incoming stanzas\r\nJul 01 22:22:55 c2s9aceb68      debug   Received[c2s]: <iq id='t7ce1b0fc5' type='get' to='user@example.org' from='user@example.org/phone'>\r\nJul 01 22:22:55 c2s9aceb68      debug   #queue = 6\r\nJul 01 22:22:55 c2s9aceb68      debug   Handled 7 incoming stanzas\r\nJul 01 22:22:55 c2s9aceb68      debug   Received[c2s]: <iq id='faikof8fpf' type='get' to='conference.example.org' from='user@example.org/phone'>\r\n````\r\n\r\n"}}
{"actor":{"display_login":"tmolitor-stud-tu"}}