NotAuthorizedException in MessageDeliveryLogic causes incorrect packet (#1310)

Closed

Activities

wojciech.kapcia@tigase.net opened 3 years ago

[2022-02-15 03:51:32:489] [FINE    ] [   in_3-message-router ] MessageDeliveryLogic.handleDelivery(): NotAuthorizedException for packet: from=null, to=sess-man@ip-172-31-38-91.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, SIZE=1686, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=LOCAL, TYPE=null, STABLE_ID=cd061c48-1f3d-485d-8a17-dc8fff7e808c for session: XMPPResourceConnection=[user_jid=…@tigase.im/…iPhone, packets=44, connectioId=c2s@ip-172-31-38-91.us-west-2.compute.internal/… domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=0, parentSession liveTime=]
tigase.xmpp.NotAuthorizedException: Session has not been yet authorised.
	at tigase.xmpp.XMPPResourceConnection.isUserId(XMPPResourceConnection.java:616)
	at tigase.xmpp.impl.MessageDeliveryLogic.handleDelivery(MessageDeliveryLogic.java:82)
	at tigase.xmpp.impl.MessageAmp.process(MessageAmp.java:259)
	at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2685)
	at tigase.util.processing.WorkerThread.run(WorkerThread.java:67)

wojciech.kapcia@tigase.net commented 3 years ago

[2022-02-15 03:50:01.943] [TRACE] [ in_5-message-router] tigase.server.MessageRouter.processPacket(): Processing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/??????iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="d5965abe-9258-4011-8baa-8f8d14247fee" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:26.28Z" xmlns="urn:xmpp:delay"/><message type="chat" to="siwen@tigase.im" xmlns="jabber:client" from="hyh@tigase.im/Snikket.uxEO" id="ee34e198-53d7-4ada-b0c7-082d99445c77"><body>I sent you an OMEMO encrypted message but your client doesn’t seem to support that. Find more information on https://conversations.im/omemo</body><encrypted xmlns="eu.siacs.conversations.axolotl"><header sid="1633337038"><key rid="320974958">MwohBdSM0a0OJ2j7osYloPW5oA9PKKB6juNpAmTcaqShQY85EAAYACIwii/VnUPFHyYA1N9Uhv4mZFypWALsp1pAsr2Atf6yvW3VcHqkL8LOIujhnJ5TADvmglBqdYCi7o4=</key><key rid="1991510905">MwohBQyOfvJ+4/eJMIaBViPyHtddE02e/V8n+5kMFkN8yBd+ECwYACIwg9qsWnvVNyihRL+Igv49syE8bXSKIOGObB3/op19QA4W/RJKQ9aMzgxX2YnKOxN8tT3Jxf+DQWI=</key><key rid="2096988480">MwohBd9tqWaz48A+TgOmi/+1NTvyeK ... , SIZE=1525, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=NONE, TYPE=null, STABLE_ID=nullm
…
[2022-02-15 03:51:32.484] [TRACE] [       in_5-sess-man] tigase.server.cluster.strategy.OnlineUsersCachingStrategy.getNodesForPacketForward(): Packet not suitable for forwarding: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/??????iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="d5965abe-9258-4011-8baa-8f8d14247fee" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:26.28Z" xmlns="urn:xmpp:delay"/><message type="chat" to="siwen@tigase.im" xmlns="jabber:client" from="hyh@tigase.im/Snikket.uxEO" id="ee34e198-53d7-4ada-b0c7-082d99445c77"><body>I sent you an OMEMO encrypted message but your client doesn’t seem to support that. Find more information on https://conversations.im/omemo</body><encrypted xmlns="eu.siacs.conversations.axolotl"><header sid="1633337038"><key rid="320974958">MwohBdSM0a0OJ2j7osYloPW5oA9PKKB6juNpAmTcaqShQY85EAAYACIwii/VnUPFHyYA1N9Uhv4mZFypWALsp1pAsr2Atf6yvW3VcHqkL8LOIujhnJ5TADvmglBqdYCi7o4=</key><key rid="1991510905">MwohBQyOfvJ+4/eJMIaBViPyHtddE02e/V8n+5kMFkN8yBd+ECwYACIwg9qsWnvVNyihRL+Igv49syE8bXSKIOGObB3/op19QA4W/RJKQ9aMzgxX2YnKOxN8tT3Jxf+DQWI=</key><key rid="2096988480">MwohBd9tqWaz48A+TgOmi/+1NTvyeK ... , SIZE=1686, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=NONE, TYPE=null, STABLE_ID=cd061c48-1f3d-485d-8a17-dc8fff7e808c
…
[2022-02-15 03:51:32:487] [FINEST  ] [   in_3-message-router ] DomainFilter.filter()            : Filtering (packet): from=null, to=sess-man@ip-172-31-38-91.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="d5965abe-9258-4011-8baa-8f8d14247fee" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:26.28Z" xmlns="urn:xmpp:delay"/><message type="chat" to="siwen@tigase.im" xmlns="jabber:client" from="hyh@tigase.im/Snikket.uxEO" id="ee34e198-53d7-4ada-b0c7-082d99445c77"><body>I sent you an OMEMO encrypted message but your client doesn’t seem to support that. Find more information on https://conversations.im/omemo</body><encrypted xmlns="eu.siacs.conversations.axolotl"><header sid="1633337038"><key rid="320974958">MwohBdSM0a0OJ2j7osYloPW5oA9PKKB6juNpAmTcaqShQY85EAAYACIwii/VnUPFHyYA1N9Uhv4mZFypWALsp1pAsr2Atf6yvW3VcHqkL8LOIujhnJ5TADvmglBqdYCi7o4=</key><key rid="1991510905">MwohBQyOfvJ+4/eJMIaBViPyHtddE02e/V8n+5kMFkN8yBd+ECwYACIwg9qsWnvVNyihRL+Igv49syE8bXSKIOGObB3/op19QA4W/RJKQ9aMzgxX2YnKOxN8tT3Jxf+DQWI=</key><key rid="2096988480">MwohBd9tqWaz48A+TgOmi/+1NTvyeK ... , SIZE=1686, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=LOCAL, TYPE=null, STABLE_ID=cd061c48-1f3d-485d-8a17-dc8fff7e808c
[2022-02-15 03:51:32:489] [FINE    ] [   in_3-message-router ] MessageDeliveryLogic.handleDelivery(): NotAuthorizedException for packet: from=null, to=sess-man@ip-172-31-38-91.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="d5965abe-9258-4011-8baa-8f8d14247fee" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:26.28Z" xmlns="urn:xmpp:delay"/><message type="chat" to="siwen@tigase.im" xmlns="jabber:client" from="hyh@tigase.im/Snikket.uxEO" id="ee34e198-53d7-4ada-b0c7-082d99445c77"><body>I sent you an OMEMO encrypted message but your client doesn’t seem to support that. Find more information on https://conversations.im/omemo</body><encrypted xmlns="eu.siacs.conversations.axolotl"><header sid="1633337038"><key rid="320974958">MwohBdSM0a0OJ2j7osYloPW5oA9PKKB6juNpAmTcaqShQY85EAAYACIwii/VnUPFHyYA1N9Uhv4mZFypWALsp1pAsr2Atf6yvW3VcHqkL8LOIujhnJ5TADvmglBqdYCi7o4=</key><key rid="1991510905">MwohBQyOfvJ+4/eJMIaBViPyHtddE02e/V8n+5kMFkN8yBd+ECwYACIwg9qsWnvVNyihRL+Igv49syE8bXSKIOGObB3/op19QA4W/RJKQ9aMzgxX2YnKOxN8tT3Jxf+DQWI=</key><key rid="2096988480">MwohBd9tqWaz48A+TgOmi/+1NTvyeK ... , SIZE=1686, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=LOCAL, TYPE=null, STABLE_ID=cd061c48-1f3d-485d-8a17-dc8fff7e808c for session: XMPPResourceConnection=[user_jid=siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone, packets=44, connectioId=c2s@ip-172-31-38-91.us-west-2.compute.internal/192.168.48.2_5223_123.123.102.114_21953, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=0, parentSession liveTime=]
tigase.xmpp.NotAuthorizedException: Session has not been yet authorised.
	at tigase.xmpp.XMPPResourceConnection.isUserId(XMPPResourceConnection.java:616)
	at tigase.xmpp.impl.MessageDeliveryLogic.handleDelivery(MessageDeliveryLogic.java:82)
	at tigase.xmpp.impl.MessageAmp.process(MessageAmp.java:259)
	at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2685)
	at tigase.util.processing.WorkerThread.run(WorkerThread.java:67)

…

[2022-02-15 03:51:32:490] [FINEST  ] [   in_3-message-router ] MessageRouter.processPacket()    : 2. Packet will be processed by: sess-man@ip-172-31-38-91.us-west-2.compute.internal, from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="b8738242-ef83-4d95-9fd0-a6925fb31c50" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:51.238Z" xmlns="urn:xmpp:delay"/><message type="chat" to="hyh@tigase.im" xmlns="jabber:client" from="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone" id="A91DECE1-4B84-4935-BF88-64D48DEE3E61"><origin-id xmlns="urn:xmpp:sid:0" id="A91DECE1-4B84-4935-BF88-64D48DEE3E61"/><received xmlns="urn:xmpp:chat-markers:0" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><received xmlns="urn:xmpp:receipts" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><store xmlns="urn:xmpp:hints"/></message></forwarded></result><delay from="tigase.im" stamp="2022-02-15T03:50:01.971Z" xmlns="urn:xmpp:delay"/><delivery-error stamp="1644897001971" xmlns="http://tigase.org/delivery-error"/></message>, SIZE=901, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2022-02-15 03:51:32:490] [FINEST  ] [   in_3-message-router ] MessageRouter.processPacket()    : Processing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="c7ee1f46-93bc-45f9-b554-2edbf6e9f84c" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:51.3Z" xmlns="urn:xmpp:delay"/><message type="chat" to="hyh@tigase.im" xmlns="jabber:client" from="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone" id="F77E9DF6-DA43-4189-99FB-0BF5D1CC8662"><origin-id xmlns="urn:xmpp:sid:0" id="F77E9DF6-DA43-4189-99FB-0BF5D1CC8662"/><displayed xmlns="urn:xmpp:chat-markers:0" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><store xmlns="urn:xmpp:hints"/></message></forwarded></result><delay from="tigase.im" stamp="2022-02-15T03:50:01.973Z" xmlns="urn:xmpp:delay"/><delivery-error stamp="1644897001973" xmlns="http://tigase.org/delivery-error"/></message>, SIZE=821, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2022-02-15 03:51:32:490] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message type="result" from="siwen@tigase.im/\uD83E\uDD13\uD83D\uDC37\uD83D\uDC30iPhone" xmlns="jabber:client">Session is not yet authorized.</message>, SIZE=121, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=LOCAL, TYPE=result, STABLE_ID=null

Basically result of StreammnagementIOProcessor:

[2022-02-15 03:50:01.971] [TRACE] [            in_1-c2s] tigase.server.xmppclient.StreamManagementIOProcessor.processOutgoing(): Queuing StreamManagement packet: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-38-91.us-west-2.compute.internal/192.168.48.2_5223_123.123.102.114_21953, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/??????iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="b8738242-ef83-4d95-9fd0-a6925fb31c50" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:51.238Z" xmlns="urn:xmpp:delay"/><message type="chat" to="hyh@tigase.im" xmlns="jabber:client" from="siwen@tigase.im/??????iPhone" id="A91DECE1-4B84-4935-BF88-64D48DEE3E61"><origin-id xmlns="urn:xmpp:sid:0" id="A91DECE1-4B84-4935-BF88-64D48DEE3E61"/><received xmlns="urn:xmpp:chat-markers:0" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><received xmlns="urn:xmpp:receipts" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><store xmlns="urn:xmpp:hints"/></message></forwarded></result></message>, SIZE=740, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=null, STABLE_ID=7d75fda2-6209-4121-a7d7-a126a3d18972, queue size: 7 [jid: siwen@tigase.im/??????iPhone, C2SIOService, UniqueId: 192.168.48.2_5223_123.123.102.114_21953, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-38-91.us-west-2.compute.internal/192.168.48.2_5223_123.123.102.114_21953, connected Socket[addr=/123.123.102.114,port=21953,localport=5223]]
[2022-02-15 03:50:01.971] [TRACE] [       in_5-sess-man] tigase.server.xmppsession.SessionManager.getResourceConnection(): Session not null, searching session for jid: siwen@tigase.im/??????iPhone
[2022-02-15 03:50:01.971] [TRACE] [       in_5-sess-man] tigase.server.xmppsession.SessionManager.getResourceConnection(): Found session: XMPPResourceConnection=[user_jid=siwen@tigase.im/??????iPhone, packets=19, connectioId=c2s@ip-172-31-38-91.us-west-2.compute.internal/192.168.48.2_5223_123.123.102.114_21953, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=704029858, parentSession liveTime=1697], for jid: siwen@tigase.im/??????iPhone
…
[2022-02-15 03:51:32.483] [TRACE] [ in_5-message-router] tigase.server.MessageRouter.processPacket(): Processing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message xmlns="jabber:client" to="siwen@tigase.im/??????iPhone"><result queryid="7BF05F97-450F-4551-ADF3-079764916613" id="b8738242-ef83-4d95-9fd0-a6925fb31c50" xmlns="urn:xmpp:mam:2"><forwarded xmlns="urn:xmpp:forward:0"><delay stamp="2022-02-14T13:31:51.238Z" xmlns="urn:xmpp:delay"/><message type="chat" to="hyh@tigase.im" xmlns="jabber:client" from="siwen@tigase.im/??????iPhone" id="A91DECE1-4B84-4935-BF88-64D48DEE3E61"><origin-id xmlns="urn:xmpp:sid:0" id="A91DECE1-4B84-4935-BF88-64D48DEE3E61"/><received xmlns="urn:xmpp:chat-markers:0" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><received xmlns="urn:xmpp:receipts" id="ee34e198-53d7-4ada-b0c7-082d99445c77"/><store xmlns="urn:xmpp:hints"/></message></forwarded></result><delay from="tigase.im" stamp="2022-02-15T03:50:01.971Z" xmlns="urn:xmpp:delay"/><delivery-error stamp="1644897001971" xmlns="http://tigase.org/delivery-error"/></message>, SIZE=901, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=NONE, TYPE=null, STABLE_ID=null

wojciech.kapcia@tigase.net commented 3 years ago

Issue most likely caused by concurrency changes to session auth-state and some parts of the code relying on it instead of explicit Authorized enum value -- for example BindResource had following code:

} catch (NotAuthorizedException e) {
			results.offer(session.getAuthState().getResponseMessage(packet, "Session is not yet authorized.", false));
}

Which resulted in obviously error packet ("Session is not yet authorized.") that was of type "result":

[2022-02-15 03:51:32:490] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<message type="result" from="…@tigase.im/…" xmlns="jabber:client">Session is not yet authorized.</message>, SIZE=121, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=LOCAL, TYPE=result, STABLE_ID=null

What's more, I added same check for presence of from attribute we do in tigase.xmpp.Authorization#getResponseMessage to overrode AUTHORIZED#getResponseMessage to avoid generating incorrect stanzas.

Type	Bug
Priority	Normal
Assignee	wojciech.kapcia@tigase.net
Version	tigase-server-8.2.0
Spent time	7h 15m

#1075 Closed

Error packet from disconnected client generates error which causes "WARNING: Packet with TO attribute set to NULL"

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#1310