9 Replies Latest reply on Sep 18, 2017 7:18 AM by Paul Schaub

    Smack is unable to receive omemo offline messages

    cmeng

      I setup an environment to test for omemo offline messages.

      1. aTalk client - leapoard@atalk.org (goes offline)

      2. conversation client - swan@atalk.org (online)

      3. swan first sends a plain message; then followed by an omemo encrypted message.

      4. start aTalk with leopard auto login

      5. aTalk is able to receive the plain offline message and display OK on chat window. However the omemo encrypted message sent from swan is not displayed; although from the trace log, the xmpp server did indeed send the delayed encrypted message.

      6. Swan send another omemo encrypted message while leopard is online

      7. leopard is able to receive the omemo encrypted message and display in the chat window.

       

      Note: Both the messageListeners for normal and omemo message are registered upon successful xmpp connection, and before user authentication.

      I have attached the full log file in case you need it.

       

      ================= aTalk offline messages log (strip version) ==========

      07-05 13:26:55.338 D/SMACK: RECV (0): <stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism >X-OAUTH2</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms><register xmlns='http://jabber.org/features/iq-register'/></stream:features>

      07-05 13:26:55.338 I/αTalk: [4] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connected().1389 Smack: CP Connection Successful

      07-05 13:26:55.348 I/αTalk: [4] org.atalk.crypto.omemo.AndroidOmemoService.<init>().52 ### Registered omemoListener for: leopard@atalk.org

      07-05 13:26:55.388 D/SMACK: SENT (0): <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>biwsbj1sZW9wYXJkLHI9bzN8T2VvSXpMYz9mXChNMnZsQGI3SW1AeGp AK19BMnM=</auth>

      07-05 13:26:55.398 D/SMACK: RECV (0): <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1vM3xPZW9JekxjP2ZcKE0ydmxAYjdJbUB4ak ArX0EyczQvWjFjR0hZcm52NFVIL3lGR3BKR3c9PSxzPUNxQmkvM2h5a2JWckRFcnd6RlNJTGc9PSxpPT QwOTY=</challenge>

      07-05 13:26:55.578 W/art: Suspending all threads took: 18.731ms

      07-05 13:26:55.818 D/SMACK: SENT (0): <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>Yz1iaXdzLHI9bzN8T2VvSXpMYz9mXChNMnZsQG I3SW1AeGpAK19BMnM0L1oxY0dIWXJudjRVSC95RkdwSkd3PT0scD1uOEdkcDRzU3VsTmpDVnYxMjhLbU 5rSGIzYTg9</response>

      07-05 13:26:55.828 D/SMACK: RECV (0): <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1aRkc3SmRMUEhaK2p0SWhUUzYwQnkzZGNwTG 89</success>

      07-05 13:26:55.828 D/SMACK: SENT (0): <stream:stream xmlns='jabber:client' to='atalk.org' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' id='15330940179649143976' xml:lang='en'>

      07-05 13:26:55.838 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id='9427873496962683657' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='atalk.org' xmlns='jabber:client'>

      07-05 13:26:55.838 D/SMACK: RECV (0): <stream:features><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session><c ver='cJUVXXV+5khBwVJS8OXzJd4l35c=' node='http://www.process-one.net/en/ejabberd/' hash='sha-1' xmlns='http://jabber.org/protocol/caps'/><sm xmlns='urn:xmpp:sm:2'/><sm xmlns='urn:xmpp:sm:3'/><ver xmlns='urn:xmpp:features:rosterver'/><csi xmlns='urn:xmpp:csi:0'/></stream:features>

      07-05 13:26:55.838 D/SMACK: SENT (0): <iq id='LQCtj-30' type='set'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><resource>atalk</resource></bind></iq>

      07-05 13:26:55.958 D/SMACK: RECV (0): <iq type='result' id='LQCtj-30'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>leopard@atalk.org/atalk</jid></bind></iq>

      07-05 13:26:55.988 D/SMACK: SENT (0): <enable xmlns='urn:xmpp:sm:3' resume='true'/>

      07-05 13:26:55.988 D/SMACK: RECV (0): <enabled resume='true' max='300' id='g2gCbQAAAAVhdGFsa2gDYgAABdtiAAOLoGIAAGH7' xmlns='urn:xmpp:sm:3'/>

      07-05 13:26:55.988 D/SMACK: User logged (0): leopard@atalk.org:5222/atalk

      07-05 13:26:58.788 I/αTalk: [4] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().1412 Smack: User Authenticated-isResumed: false

      07-05 13:26:59.028 D/SMACK: SENT (0): <presence id='LQCtj-100'><status></status><priority>30</priority><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='FzoaRQcKGdEXopGqoTe/dMzpwZk='/><x xmlns='vcard-temp:x:update'><photo>ed341d7cb4d39f423989c0cf5fe8d9527be3ffde</ph oto></x></presence>

      07-05 13:26:59.028 D/SMACK: SENT (0): <r xmlns='urn:xmpp:sm:3'/>

      07-05 13:26:59.188 D/SMACK: SENT (0): <iq to='leopard@atalk.org' id='LQCtj-102' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq>

      07-05 13:26:59.218 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@atalk.org/atalk' from='leopard@atalk.org' type='result' id='LQCtj-101'/>

      07-05 13:26:59.218 D/SMACK: RECV (0): <message xml:lang='en' to='leopard@atalk.org/atalk' from='swan@atalk.org/phone' type='chat' id='3d3834fe-20d6-4983-8041-b5045fb0ef5c'><markable xmlns='urn:xmpp:chat-markers:0'/><origin-id xmlns='urn:xmpp:sid:0' id='3d3834fe-20d6-4983-8041-b5045fb0ef5c'/><delay xmlns='urn:xmpp:delay' from='atalk.org' stamp='2017-07-05T05:25:17.260468Z'>Offline Storage</delay><body>Send plain offline message</body></message>

      07-05 13:26:59.228 D/SMACK: RECV (0): <message xml:lang='en' to='leopard@atalk.org/atalk' from='swan@atalk.org/phone' type='chat' id='173d165a-737f-47f9-919d-03404096ad4c'><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='816614937'><key rid='37379719' prekey='true'>MwgDEiEFOmOEA5w9J66CT8nG7LWl5x/Uyy8quduZS2EBzF8HolQaIQUUV5ApOiQnN cECsTvKWCH8wDMrQe4XtFTcxf88Tg61YSJiMwohBYakBsGB75jRG03R9fMYINhqZe4FSaoQG0xG0tFX3 xkJEHQYACIwd68/kRvPHLRBDsOmBEtH23+sRDMsefI9hLjuH6BshxDVfSt1xsR1YxQkQ5/y+rqXBTSCH 9GXo6AomZyyhQMwAQ==</key><key rid='1604234256'>MwohBYcomjOFs5uhIPkoe/rEHavx7Qcrr8j2777RtVH4SBBBEAcYACIwG57JKc vRvZkbxspak29oufw+aTw1SCle4MJKWzXhfisW7zL4wo1NHPKEFNjhMvRbbNDs++gMDtI=</key><iv> VJKShFtn3MB5zHriVeLI3Q==</iv></header><payload>1WtNBQoYttqY9m4yOz3XBjbsoJQ4fJFZz cE=</payload></encrypted><markable xmlns='urn:xmpp:chat-markers:0'/><origin-id xmlns='urn:xmpp:sid:0' id='173d165a-737f-47f9-919d-03404096ad4c'/><store xmlns='urn:xmpp:hints'/><encryption xmlns='urn:xmpp:eme:0' namespace='eu.siacs.conversations.axolotl' name='OMEMO'/><delay xmlns='urn:xmpp:delay' from='atalk.org' stamp='2017-07-05T05:25:34.291876Z'>Offline Storage</delay></message>

      07-05 13:27:00.328 D/SMACK: SENT (0): <iq to='leopard@atalk.org' id='LQCtj-119' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1604234256'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>BRrzarnIyYx8CiyOcvGZHGFDIuk8ahApVUTYJlGmNQ8y</signedPreKeyPu blic><signedPreKeySignature>RuMzAEBr21bXjsJ91GdlAnhyQSAFTKWms1tSq/IOnfcdh2LRlvPu UJJvznd6vfVzxgOsW+oNyXswJUKFYYFsjQ==</signedPreKeySignature><identityKey>BcBVdk+ +LLlB+H0cVIWl/HUg4PB3B/lYnTuZSW4pLt0D</identityKey><prekeys><preKeyPublic preKeyId='71'>BUh1xIbw9n+iD5vVxsP3e8fHd8ZTEUCMAmbGP9gk5k1x</preKeyPublic><preKe yPublic preKeyId='97'>BU7/+mypKARX1RvaEIfPdveJ7rsH7zXaUL9ny5hgamk4</preKeyPublic><preKe yPublic preKeyId='23'>BeSRFhYzQSQcMEnJTAal8pWJO9pNiYIghqWJsqzo4fks</preKeyPublic><preKe yPublic ......

      .....

      preKeyId='54'>Bd+TMbbghylI/lbzjinwd1KsrRN8jCzPbexfTDrAWCU9</preKeyPublic><preKey Public

      preKeyId='25'>BV1SoVVLMwVUIBZ8dlaFizfDffY2OWuemyPiMDetcEsO</preKeyPublic><preKey Public preKeyId='60'>BcKBPX5CNwZd45OOWoQ1qXh6dYI58RfUZSAtggArJjkW</preKeyPublic><preKe yPublic preKeyId='58'>BatlhKhFMR7YYoYJXGKCjwSro16fiUua95YT6LnnvbdI</preKeyPublic><preKe yPublic preKeyId='46'>BUtbjsjmtt8BEZE1tTlmqkd+yTNMCZdacHMZDVHUY3M7</preKeyPublic><preKe yPublic preKeyId='14'>BQodeYv5ABJpZ7AT7zvpD5S9UeWrzTLGSbSr9Uv6hvAa</preKeyPublic><preKe yPublic preKeyId='20'>BZ0dNyimKh/

      07-05 13:27:00.328 D/SMACK: SENT (0): </pubsub></iq><a xmlns='urn:xmpp:sm:3' h='34'/>

      07-05 13:27:04.678 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@atalk.org/atalk' from='leopard@atalk.org' type='result' id='LQCtj-119'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1604234256'><item id='5DB38BA888BA6'/></publish></pubsub></iq>

       

      .... swan send omemo enrypted message when leopard is online (rx and diplay ok) ........

      07-05 13:36:43.138 D/SMACK: RECV (0): <message xml:lang='en' to='leopard@atalk.org/atalk' from='swan@atalk.org/phone' type='chat' id='d43bb3cd-f7ce-4417-90ba-a1adc3f82d52'><encrypted xmlns='eu.siacs.conversations.axolotl'><header sid='816614937'><key rid='37379719' prekey='true'>MwgDEiEFOmOEA5w9J66CT8nG7LWl5x/Uyy8quduZS2EBzF8HolQaIQUUV5ApOiQnN cECsTvKWCH8wDMrQe4XtFTcxf88Tg61YSJiMwohBYakBsGB75jRG03R9fMYINhqZe4FSaoQG0xG0tFX3 xkJEHUYACIwTpawVu3bIvTlhGGI2MmfKpIm9L6a1QHkbRIz95pCUINocQRwrt14kVosxyp2jPrZ+6XfQ J5OBzsomZyyhQMwAQ==</key><key rid='1604234256'>MwohBYcomjOFs5uhIPkoe/rEHavx7Qcrr8j2777RtVH4SBBBEAgYACIwUmuebE VaIKLYn2hMRBB+mcgOn+El2WR5MgssIPqqN6B2B7Neogu8DW0hF5ItsBFJAy+f2kwOiSE=</key><iv> /bHvI4y+WckGF4Qi/9yfyA==</iv></header><payload>HNdWBtBll4DlmMJ5VgLreg==</payload ></encrypted><markable xmlns='urn:xmpp:chat-markers:0'/><origin-id xmlns='urn:xmpp:sid:0' id='d43bb3cd-f7ce-4417-90ba-a1adc3f82d52'/><store xmlns='urn:xmpp:hints'/><encryption xmlns='urn:xmpp:eme:0' namespace='eu.siacs.conversations.axolotl' name='OMEMO'/></message>

        • Re: Smack is unable to receive omemo offline messages
          cmeng

          I did a quick trace on Omemo and following are my findings:

          1. Unlike aTalk, where all message listeners are registered upon successful xmpp connection.

          OmemoService#registerOmemoMessageStanzaLitseners is executed only after account is authenticated.

           

          2. OmemoStanzaListener#processStanza is not triggered when the offline omemo message is send from server. But working as expected when the account is online in steady state.

            • Re: Smack is unable to receive omemo offline messages
              Paul Schaub

              Thank you for the hint. Registering the stanza listener only after authentication might indeed be to late. I'll add that to the TODO list .

              • Re: Smack is unable to receive omemo offline messages
                Paul Schaub

                Btw: Have you taken a look at the querying MAM messages yet?

                  • Re: Smack is unable to receive omemo offline messages
                    cmeng

                    No, aTalk has yet to implement this feature.

                      • Re: Smack is unable to receive omemo offline messages
                        cmeng

                        aTalk testing indicates that Smack 4.2.1-beta2-SNAPSHOT release still still having the reported problem:

                        "Smack is unable to receive omemo offline messages"

                          • Re: Smack is unable to receive omemo offline messages
                            cmeng

                            To allow receiving the offline olmMessages with smack-4.2.1-beta2-SNAPSHOT library, aTalk has implemented the following reflection method call to OmemoService#registerOmemoMessageStanzaListeners right after the xmpp connection is made. aTalk is tested working and able to receive all offline olmMessages using smack-4.2.1-beta2-SNAPSHOT library.

                             

                            private void addOmemoListener(OmemoManager omemoManager)
                            {
                               OmemoService omemoService = OmemoService.getInstance();
                               try {
                               Method addMsgListener = OmemoService.class.getDeclaredMethod
                               ("registerOmemoMessageStanzaListeners", OmemoManager.class);
                               addMsgListener.setAccessible(true);
                               addMsgListener.invoke(omemoService, omemoManager);
                               }
                               catch (NoSuchMethodException | IllegalAccessException | InvocationTargetException e) {
                               e.printStackTrace();
                               }
                            }

                              • Re: Smack is unable to receive omemo offline messages
                                cmeng

                                Although the receipt of muc offline olmMessages is also tested working for conference in aTalk. However Smack Omemo MUST take care the following situation. otherwise errors/exceptions as attached log will occur.

                                 

                                When a user joins a chatRoom, some server is setup to re-sent some number of History olmMessages; with some of them can be duplication of exchanged olmMessages just before user last left the conference. aTalk takes care the muc plain messages with the following check. Hopefully smack omemo will implement similarly, to discard silently any duplication, and forward only new delayed olmMessage to the application.

                                 

                                // This is a delayed chat room message, a history message for the room coming from
                                  // server. Lets check have we already shown this message and if this is the case
                                  // skip it otherwise save it as last seen delayed message
                                   if (lastSeenDelayedMessage == null) {
                                   // initialise this from configuration
                                   String timestamp = ConfigurationUtils.getChatRoomProperty(mProvider,
                                   getName(), LAST_SEEN_DELAYED_MESSAGE_PROP);

                                   try {
                                   lastSeenDelayedMessage = new Date(Long.parseLong(timestamp));
                                   }
                                   catch (Throwable ex) {
                                   ex.printStackTrace();
                                   }
                                  }

                                   if (lastSeenDelayedMessage != null && !timeStamp.after(lastSeenDelayedMessage))
                                   return;

                                   // save it in configuration
                                   ConfigurationUtils.updateChatRoomProperty(mProvider, getName(),
                                   LAST_SEEN_DELAYED_MESSAGE_PROP, String.valueOf(timeStamp.getTime()));
                                   lastSeenDelayedMessage = timeStamp;
                                }
                                else {
                                   timeStamp = new Date();
                                }

                                 

                                ============ aTalk error log on duplicated delayed history olmMessage ===========

                                07-23 15:22:27.588 E/αTalk: [35] org.jivesoftware.smackx.omemo.signal.SignalOmemoSession.decryptMessageKey() Error decrypting message header, org.whispersystems.libsignal.DuplicateMessageException: Received message with old counter: 6 , 5

                                07-23 15:22:27.608 E/αTalk: [36] org.jivesoftware.smackx.omemo.signal.SignalOmemoSession.decryptMessageKey() Error decrypting message header, org.whispersystems.libsignal.DuplicateMessageException: Received message with old counter: 6 , 4

                                07-23 15:22:27.608 W/αTalk: [35] org.jivesoftware.smackx.omemo.OmemoService.processStanza() internal omemoMessageListener failed to decrypt incoming OMEMO message: Transported key could not be decrypted, since no provided message key. Provides keys: [1011347036, 1796289951]

                                07-23 15:22:31.968 E/αTalk: [37] util.UtilActivator.uncaughtException().95 An uncaught exception occurred in thread=Thread[Smack-Cached Executor 17 (0),5,main] and message was: Received message with old counter: 2 , 0

                                                            org.whispersystems.libsignal.DuplicateMessageException: Received message with old counter: 2 , 0

                                                                at org.whispersystems.libsignal.SessionCipher.getOrCreateMessageKeys(SessionCipher .java:365)

                                                                at org.whispersystems.libsignal.SessionCipher.decrypt(SessionCipher.java:297)

                                                                at org.whispersystems.libsignal.SessionCipher.decrypt(SessionCipher.java:265)

                                                                at org.whispersystems.libsignal.SessionCipher.decrypt(SessionCipher.java:235)

                                                                at org.whispersystems.libsignal.SessionCipher.decrypt(SessionCipher.java:203)

                                                                at org.jivesoftware.smackx.omemo.signal.SignalOmemoSession.decryptMessageKey(Signa lOmemoSession.java:128)

                                                                at org.jivesoftware.smackx.omemo.internal.OmemoSession.decryptTransportedKey(Omemo Session.java:109)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.decryptTransportedOmemoKey(OmemoServ ice.java:936)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.decryptOmemoMessageElement(OmemoServ ice.java:906)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.processReceivingMessage(OmemoService .java:730)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.access$200(OmemoService.java:107)

                                                                at org.jivesoftware.smackx.omemo.OmemoService$OmemoStanzaListener.processStanza(Om emoService.java:1238)

                                                                at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java :1202)

                                                                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1120)

                                                                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)

                                                                at java.lang.Thread.run(Thread.java:820)

                                07-23 15:22:36.468 E/αTalk: [38] org.jivesoftware.smackx.omemo.signal.SignalOmemoSession.decryptMessageKey() Error decrypting message header, org.whispersystems.libsignal.DuplicateMessageException: Received message with old counter: 4 , 0

                                07-23 15:22:36.508 E/αTalk: [38] util.UtilActivator.uncaughtException().95 An uncaught exception occurred in thread=Thread[Smack-Cached Executor 13 (0),5,main] and message was: Transported key could not be decrypted, since no provided message key. Provides keys: [1711246335, 1011347036]

                                                            org.jivesoftware.smackx.omemo.exceptions.CryptoFailedException: Transported key could not be decrypted, since no provided message key. Provides keys: [1711246335, 1011347036]

                                                                at org.jivesoftware.smackx.omemo.internal.OmemoSession.decryptTransportedKey(Omemo Session.java:124)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.decryptTransportedOmemoKey(OmemoServ ice.java:936)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.decryptOmemoMessageElement(OmemoServ ice.java:906)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.processReceivingMessage(OmemoService .java:730)

                                                                at org.jivesoftware.smackx.omemo.OmemoService.access$200(OmemoService.java:107)

                                                                at org.jivesoftware.smackx.omemo.OmemoService$OmemoStanzaListener.processStanza(Om emoService.java:1238)

                                                                at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java :1202)

                                                                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1120)

                                                                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)

                                                                at java.lang.Thread.run(Thread.java:820)

                      • Re: Smack is unable to receive omemo offline messages
                        Vishnu Prajapati

                        Paul Schaub @cmen

                        Hi,

                        We are too receiving this duplicate message exception with some counter error.

                         

                        SignalOmemoSession: Error decrypting message header, org.whispersystems.libsignal.DuplicateMessageException: Received message with old counter: 100 , 97

                        W/System.err: org.jivesoftware.smackx.omemo.exceptions.CryptoFailedException: Transported key could not be decrypted, since no provided message key. Provides keys: [889190764]

                        W/System.err:    at org.jivesoftware.smackx.omemo.internal.OmemoSession.decryptTransportedKey(Omemo Session.java:124)

                        W/System.err:    at org.jivesoftware.smackx.omemo.OmemoService.decryptTransportedOmemoKey(OmemoServ ice.java:936)

                         

                        We are receiving omemo encrypted messages from ejabberd server in disorder, so this might be the cause of the message duplication error we are receiving.

                        Please confirm that the message disorder could be the cause for this duplication error or this error only occurred when client tries to decrypt a message again.

                         

                        Thanks