Smack is unable to receive omemo offline messages

cmeng · July 5, 2017, 5:51am

I setup an environment to test for omemo offline messages.

aTalk client - leapoard@atalk.org (goes offline)
conversation client - swan@atalk.org (online)
swan first sends a plain message; then followed by an omemo encrypted message.
start aTalk with leopard auto login
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.
Swan send another omemo encrypted message while leopard is online
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:featuresPLAINX-OAUTH2SCRAM-SHA-1</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.().52 ### Registered omemoListener for: leopard@atalk.org

07-05 13:26:55.388 D/SMACK: SENT (0): biwsbj1sZW9wYXJkLHI9bzN8T2VvSXpMYz9mXChNMnZsQGI3SW1AeGp AK19BMnM=

07-05 13:26:55.398 D/SMACK: RECV (0): cj1vM3xPZW9JekxjP2ZcKE0ydmxAYjdJbUB4ak ArX0EyczQvWjFjR0hZcm52NFVIL3lGR3BKR3c9PSxzPUNxQmkvM2h5a2JWckRFcnd6RlNJTGc9PSxpPT QwOTY=

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

07-05 13:26:55.818 D/SMACK: SENT (0): Yz1iaXdzLHI9bzN8T2VvSXpMYz9mXChNMnZsQG I3SW1AeGpAK19BMnM0L1oxY0dIWXJudjRVSC95RkdwSkd3PT0scD1uOEdkcDRzU3VsTmpDVnYxMjhLbU 5rSGIzYTg9

07-05 13:26:55.828 D/SMACK: RECV (0): dj1aRkc3SmRMUEhaK2p0SWhUUzYwQnkzZGNwTG 89

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</stream:features>

07-05 13:26:55.838 D/SMACK: SENT (0): atalk

07-05 13:26:55.958 D/SMACK: RECV (0): leopard@atalk.org/atalk

07-05 13:26:55.988 D/SMACK: SENT (0):

07-05 13:26:55.988 D/SMACK: RECV (0):

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): 30ed341d7cb4d39f423989c0cf5fe8d9527be3ffde</ph oto>

07-05 13:26:59.028 D/SMACK: SENT (0):

07-05 13:26:59.188 D/SMACK: SENT (0):

07-05 13:26:59.218 D/SMACK: RECV (0):

07-05 13:26:59.218 D/SMACK: RECV (0): Offline StorageSend plain offline message

07-05 13:26:59.228 D/SMACK: RECV (0): MwgDEiEFOmOEA5w9J66CT8nG7LWl5x/Uyy8quduZS2EBzF8HolQaIQUUV5ApOiQnN cECsTvKWCH8wDMrQe4XtFTcxf88Tg61YSJiMwohBYakBsGB75jRG03R9fMYINhqZe4FSaoQG0xG0tFX3 xkJEHQYACIwd68/kRvPHLRBDsOmBEtH23+sRDMsefI9hLjuH6BshxDVfSt1xsR1YxQkQ5/y+rqXBTSCH 9GXo6AomZyyhQMwAQ==MwohBYcomjOFs5uhIPkoe/rEHavx7Qcrr8j2777RtVH4SBBBEAcYACIwG57JKc vRvZkbxspak29oufw+aTw1SCle4MJKWzXhfisW7zL4wo1NHPKEFNjhMvRbbNDs++gMDtI= VJKShFtn3MB5zHriVeLI3Q==1WtNBQoYttqY9m4yOz3XBjbsoJQ4fJFZz cE=Offline Storage

07-05 13:27:00.328 D/SMACK: SENT (0): BRrzarnIyYx8CiyOcvGZHGFDIuk8ahApVUTYJlGmNQ8y</signedPreKeyPu blic>RuMzAEBr21bXjsJ91GdlAnhyQSAFTKWms1tSq/IOnfcdh2LRlvPu UJJvznd6vfVzxgOsW+oNyXswJUKFYYFsjQ==BcBVdk+ +LLlB+H0cVIWl/HUg4PB3B/lYnTuZSW4pLt0DBUh1xIbw9n+iD5vVxsP3e8fHd8ZTEUCMAmbGP9gk5k1xBU7/+mypKARX1RvaEIfPdveJ7rsH7zXaUL9ny5hgamk4BeSRFhYzQSQcMEnJTAal8pWJO9pNiYIghqWJsqzo4fks<preKe yPublic …

…

preKeyId=‘54’>Bd+TMbbghylI/lbzjinwd1KsrRN8jCzPbexfTDrAWCU9<preKey Public

preKeyId=‘25’>BV1SoVVLMwVUIBZ8dlaFizfDffY2OWuemyPiMDetcEsOBcKBPX5CNwZd45OOWoQ1qXh6dYI58RfUZSAtggArJjkWBatlhKhFMR7YYoYJXGKCjwSro16fiUua95YT6LnnvbdIBUtbjsjmtt8BEZE1tTlmqkd+yTNMCZdacHMZDVHUY3M7BQodeYv5ABJpZ7AT7zvpD5S9UeWrzTLGSbSr9Uv6hvAaBZ0dNyimKh/

07-05 13:27:00.328 D/SMACK: SENT (0):

07-05 13:27:04.678 D/SMACK: RECV (0):

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

07-05 13:36:43.138 D/SMACK: RECV (0): MwgDEiEFOmOEA5w9J66CT8nG7LWl5x/Uyy8quduZS2EBzF8HolQaIQUUV5ApOiQnN cECsTvKWCH8wDMrQe4XtFTcxf88Tg61YSJiMwohBYakBsGB75jRG03R9fMYINhqZe4FSaoQG0xG0tFX3 xkJEHUYACIwTpawVu3bIvTlhGGI2MmfKpIm9L6a1QHkbRIz95pCUINocQRwrt14kVosxyp2jPrZ+6XfQ J5OBzsomZyyhQMwAQ==MwohBYcomjOFs5uhIPkoe/rEHavx7Qcrr8j2777RtVH4SBBBEAgYACIwUmuebE VaIKLYn2hMRBB+mcgOn+El2WR5MgssIPqqN6B2B7Neogu8DW0hF5ItsBFJAy+f2kwOiSE= /bHvI4y+WckGF4Qi/9yfyA==HNdWBtBll4DlmMJ5VgLreg==
omemo_offline_msg.xml.zip (36711 Bytes)

cmeng · July 5, 2017, 6:57am

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

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

OmemoService#registerOmemoMessageStanzaLitseners is executed only after account is authenticated.

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.

Paul_Schaub · July 5, 2017, 7:56am

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 .

Paul_Schaub · July 5, 2017, 12:49pm

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

cmeng · July 5, 2017, 11:36pm

No, aTalk has yet to implement this feature.

cmeng · July 22, 2017, 3:59am

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”

cmeng · July 23, 2017, 5:51am

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();
}
}

cmeng · July 23, 2017, 7:42am

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)