Projects tigase _server server-core Issues #1075
Error packet from disconnected client generates error which causes "WARNING: Packet with TO attribute set to NULL" (#1075)
Closed
wojciech.kapcia@tigase.net opened 5 years ago

From monitor:

2019-07-19 05:03:59.667 [in_4-message-router]  PacketDefaultHandler.process()      FINEST:   Processing packet: from=c2s@ip-10-0-13-5.us-west-2.compute.internal/10.0.13.5_5222_86.111.112.44_43683, to=sess-man@ip-10-0-13-5.us-west-2.compute.internal, DATA=[message to="bmalkow@malkowscy.net/stork"][result id="huS8rBBTE7/dkYzmng84NOjuJ7/bay78MSxg7A/jAOQ=" queryid="mam-HrZXkLSQ4maHBs9EJX0vp1m" xmlns="urn:xmpp:mam:1"][forwarded xmlns="urn:xmpp:forward:0"][delay xmlns="urn:xmpp:delay" stamp="2019-07-19T11:53:45.235Z"/][message id="2e559507-b69a-4d0d-ab0f-02bfc3aeaa8f" type="chat" xmlns="jabber:client" from="ahanak@axeos.nl/gajim.1GG4P9OP" to="bmalkow@malkowscy.net/stork" time="1563537225235"][body]…[/body][origin-id id="2e559507-b69a-4d0d-ab0f-02bfc3aeaa8f" xmlns="urn:xmpp:sid:0"/][request xmlns="urn:xmpp:receipts"/][thread]hHWQQtUXfKGVeHNEMrSXLmgxflowYHGd[/thread][/message][/forwarded][/result][delay from="malkowscy.net" xmlns="urn:xmpp:delay" stamp="2019-07-19T12:02:28.748Z"/][delivery-error xmlns="http://tigase.org/delivery-error" stamp="1563537748748"/][/message], SIZE=871, XMLNS=null, PRIORITY=HIGH, PERMISSION=ADMIN, TYPE=null
…
2019-07-19 05:03:59.669 [in_4-message-router]  MessageRouter.processPacket()       WARNING:  Packet with TO attribute set to NULL: from=sess-man@ip-10-0-13-5.us-west-2.compute.internal, to=null, DATA=[message type="error" from="bmalkow@malkowscy.net/stork"][result id="huS8rBBTE7/dkYzmng84NOjuJ7/bay78MSxg7A/jAOQ=" queryid="mam-HrZXkLSQ4maHBs9EJX0vp1m" xmlns="urn:xmpp:mam:1"][forwarded xmlns="urn:xmpp:forward:0"][delay xmlns="urn:xmpp:delay" stamp="2019-07-19T11:53:45.235Z"/][message id="2e559507-b69a-4d0d-ab0f-02bfc3aeaa8f" type="chat" xmlns="jabber:client" from="ahanak@axeos.nl/gajim.1GG4P9OP" to="bmalkow@malkowscy.net/stork" time="1563537225235"][body]…[/body][origin-id id="2e559507-b69a-4d0d-ab0f-02bfc3aeaa8f" xmlns="urn:xmpp:sid:0"/][request xmlns="urn:xmpp:receipts"/][thread]hHWQQtUXfKGVeHNEMrSXLmgxflowYHGd[/thread][/message][/forwarded][/result][delay from="malkowscy.net" xmlns="urn:xmpp:delay" stamp="2019-07-19T12:02:28.748Z"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]The recipient is no longer available.[/text][/error][/message], SIZE=1020, XMLNS=null, PRIORITY=HIGH, PERMISSION=ADMIN, TYPE=error
wojciech.kapcia@tigase.net commented 5 years ago

@bmalkow after second look (especially at the removed part) it seems that the packet was not processed by tigase.xmpp.impl.BindResource#preProcess - it simply generated error and swapped to/from, and given that from was missing it caused missing to in returned error.

wojciech.kapcia@tigase.net commented 5 years ago

@andrzej.wojcik given that similar issue was reported by client I took a look and it seems (judging by the presence of delivery-error xmlns="http://tigase.org/delivery-error") that there was a problem delivering the packet and it should be handled by tigase.xmpp.impl.C2SDeliveryErrorProcessor - correct? In case of FullJID it should be passed for further processing? However, for some reason instead of being processed by any of the Message plugins (which could handle possible re-delivery or silently dropping the package) it ends up in tigase.server.xmppsession.PacketDefaultHandler#process, which then detects that the connection for this particular JID is gone (obviously as we received the bounce from ConnectionManager) and directly generates error response (Message stanza semantics are more intricate in this case, and if there is no connection it should be stored in offline store) here: tigase/server/xmppsession/PacketDefaultHandler.java:173 and tigase.server.Packet#errorResult finally swaps To/From.

I think, that we should

  • change tigase.xmpp.Authorization#getResponseMessage to actually check that both to and from are present;
  • make sure that all out-going packets have correct from and XMLNS set
  • figure out why that message packet wasn't handled by any of the message plugins (most likely due to missing XMLNS)
  • add warning log if session manager receives packet without XMLNS set.

At any rate - currently the Warning can be ignored it seems.

Comments?

wojciech.kapcia@tigase.net commented 4 years ago

@andrzej.wojcik can you take a look at my previous comment as this issue started to happen more and more recently.

Andrzej Wójcik (Tigase) commented 4 years ago

OK, let's start with the fact that this is a message sent from MAM archive (MAM component) to the client upon clients request. Those messages should not be stored in MAM nor in offline storage.

Why message had no XMLNS? I have no idea, the code properly stamps MAM messages in the MAMItemHandler class.

Why there is no from attribute? It is set to the to attribute of a <iq/> request which caused that message to be sent. According to the MAM XEP it is correct for the local server to turn messages from the local MAM archive without from being set (as those are generated by the local server).

I suppose that MAM messages sent to not connected resources (bounced with delivery-error) should just be dropped. Maybe C2SDeliveryErrorProcessor should do that for us? That would limit required processing power.

wojciech.kapcia@tigase.net commented 4 years ago

@andrzej.wojcik Well, not exactly. There are a lot of warnings about Packet with TO attribute set to NULL and MAM messages are not the only ones affected:

[2019-09-16 18:49:39:839] [WARNING ] [   in_4-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-7-125.us-west-2.compute.internal, to=null, DATA=[message from="inger.lilja@jabber.today/xabber-android-40l2pqic" type="error"][result queryid="7b5c28ef-a219-4799-9ad6-68fb3be5bebb" id="/cUAgUfp2OxbfMUvWTrD95A3Xv/m1U5cnIGNZcJy0wE=" xmlns="urn:xmpp:mam:1"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2019-09-16T18:49:15.639Z" xmlns="urn:xmpp:delay"/][message id="mir9d2a819edf9e7ba1_8169" time="1568659755639" xmlns="jabber:client" from="ola.lilja@jabber.today/Miranda" type="chat" to="inger.lilja@jabber.today/xabber-android-40l2pqic"][body]CData size: 17[/body][active xmlns="http://jabber.org/protocol/chatstates"/][request xmlns="urn:xmpp:receipts"/][/message][/forwarded][/result][delay stamp="2019-09-16T18:49:37.129Z" from="jabber.today" xmlns="urn:xmpp:delay"/][delivery-error stamp="1568659777129" xmlns="http://tigase.org/delivery-error"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=1034, XMLNS=null, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error
[2019-09-17 17:26:50:356] [WARNING ] [   in_4-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-34-141.us-west-2.compute.internal, to=null, DATA=[message type="error" from="swehner@jabber.me/Xabber_d8H3r366"][result xmlns="urn:xmpp:mam:1" id="dSwetO8ZW0Ivk+X64V+GZdCii2qtPsFgu0k5keE4YIs=" queryid="505e93db-76a7-4eb5-91f4-14108d39f4e0"][forwarded xmlns="urn:xmpp:forward:0"][delay xmlns="urn:xmpp:delay" stamp="2019-09-13T17:10:25.929Z"/][message xmlns="jabber:client" id="prof_msg_f0697714-3df6-448a-9c26-80b257d645bf" from="martin.wehner@jabber.me/home" to="swehner@jabber.me/Xabber_d8H3r366" type="chat" time="1568394625929"][body]:)[/body][/message][/forwarded][/result][delay xmlns="urn:xmpp:delay" from="jabber.me" stamp="2019-09-17T17:26:11.971Z"/][delivery-error xmlns="http://tigase.org/delivery-error" stamp="1568741171971"/][error type="wait" code="404"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=914, XMLNS=null, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error
[2019-10-10 19:00:50:723] [WARNING ] [   in_1-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=c2s@ip-10-0-34-141.us-west-2.compute.internal/10.0.34.141_5222_12.104.171.19_40456, to=null, DATA=[stream:features type="error"][sm xmlns="urn:xmpp:sm:3"/][pipelining  xmlns="urn:xmpp:features:pipelining"/][register xmlns="http://jabber.org/features/iq-register"/][mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/][ver xmlns="urn:xmpp:features:rosterver"/][sub xmlns="urn:xmpp:features:pre-approval"/][starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"][required/][/starttls][compression xmlns="http://jabber.org/features/compress"][method]CData size: 4[/method][/compression][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][/error][/stream:features], SIZE=595, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
[2020-02-21 10:09:10:165] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, to=null, DATA=[stream:features type="error"][sm xmlns="urn:xmpp:sm:3"/][pipelining  xmlns="urn:xmpp:features:pipelining"/][auth xmlns="http://jabber.org/features/iq-auth"/][register xmlns="http://jabber.org/features/iq-register"/][mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"][mechanism]CData size: 13[/mechanism][mechanism]CData size: 11[/mechanism][mechanism]CData size: 5[/mechanism][/mechanisms][ver xmlns="urn:xmpp:features:rosterver"/][sub xmlns="urn:xmpp:features:pre-approval"/][compression xmlns="http://jabber.org/features/compress"][method]CData size: 4[/method][/compression][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][/error][/stream:features], SIZE=683, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
[2020-08-19 04:17:44:151] [WARNING ] [   in_7-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=maktaduai@sure.im/319382470-tigase-3845, to=null, DATA=[iq type="error" id="rsttig4" from="maktaduai@sure.im/319382470-tigase-3845" xmlns="jabber:client"][query ver="" xmlns="jabber:iq:roster"][item jid="mtd01" ask="subscribe" name="Maktaduai" subscription="none"][group]CData size: 9[/group][/item][/query][error type="wait" code="404"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][/error][/iq], SIZE=359, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
[2020-08-19 17:08:12:611] [WARNING ] [   in_6-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-9-172.us-west-2.compute.internal, to=null, DATA=[message type="error" from="samir@sure.im/Monal-iOS.ad312b49" xmlns="jabber:client"][result xmlns="urn:xmpp:mam:2" id="b24c6cc6-63e7-4260-8679-88c7717a9d19"][forwarded xmlns="urn:xmpp:forward:0"][delay xmlns="urn:xmpp:delay" stamp="2020-08-16T16:36:09.163Z"/][message from="smir@dismail.de/Monal-iOS.72ee089b" xmlns="jabber:client" type="chat" id="B3959C9D-3CA1-4E0D-B4E5-666E3CD42E9D" to="samir@sure.im" xml:lang="en"][request xmlns="urn:xmpp:receipts"/][store xmlns="urn:xmpp:hints"/][body]CData size: 6[/body][/message][/forwarded][/result][delay from="sure.im" stamp="2020-08-19T17:07:05.569Z" xmlns="urn:xmpp:delay"/][delivery-error xmlns="http://tigase.org/delivery-error" stamp="1597856825569"/][error type="wait" code="404"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=919, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error, STABLE_ID=null
[2020-08-19 17:08:29:401] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=null, DATA=[message type="error" xmlns="jabber:client" from="samir@sure.im/Monal-iOS.ad312b49"][result id="b24c6cc6-63e7-4260-8679-88c7717a9d19" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-16T16:36:09.163Z" xmlns="urn:xmpp:delay"/][message id="B3959C9D-3CA1-4E0D-B4E5-666E3CD42E9D" xmlns="jabber:client" type="chat" to="samir@sure.im" xml:lang="en" from="smir@dismail.de/Monal-iOS.72ee089b"][request xmlns="urn:xmpp:receipts"/][store xmlns="urn:xmpp:hints"/][body]CData size: 6[/body][/message][/forwarded][/result][delay stamp="2020-08-19T17:07:22.808Z" xmlns="urn:xmpp:delay" from="sure.im"/][delivery-error stamp="1597856842808" xmlns="http://tigase.org/delivery-error"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=919, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error, STABLE_ID=null
[2020-08-19 17:14:47:427] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=null, DATA=[message type="error" xmlns="jabber:client" from="samir@sure.im/Monal-iOS.ad312b49"][result id="b24c6cc6-63e7-4260-8679-88c7717a9d19" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-16T16:36:09.163Z" xmlns="urn:xmpp:delay"/][message id="B3959C9D-3CA1-4E0D-B4E5-666E3CD42E9D" xmlns="jabber:client" type="chat" to="samir@sure.im" xml:lang="en" from="smir@dismail.de/Monal-iOS.72ee089b"][request xmlns="urn:xmpp:receipts"/][store xmlns="urn:xmpp:hints"/][body]CData size: 6[/body][/message][/forwarded][/result][delay stamp="2020-08-19T17:13:31.349Z" xmlns="urn:xmpp:delay" from="sure.im"/][delivery-error stamp="1597857211349" xmlns="http://tigase.org/delivery-error"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=919, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error, STABLE_ID=null
[2020-08-21 06:58:29:515] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=null, DATA=[message type="error" xmlns="jabber:client" from="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="D1671D6A-E6E7-4980-BBC8-354F88933A83" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T06:56:31.596Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1597992991596" xmlns="http://tigase.org/delivery-error"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=988, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error, STABLE_ID=null
[2020-08-21 07:12:15:151] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=null, DATA=[message type="error" xmlns="jabber:client" from="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="F03EA79F-7DA8-400F-AB25-7486DC9F1F3E" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T07:10:17.635Z" xmlns="urn:xmpp:delay" from="tigase.im"/][error code="401" type="auth"][not-authorized xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 33[/text][/error][/message], SIZE=897, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=LOCAL, TYPE=error, STABLE_ID=null
[2020-08-21 10:39:56:370] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=null, DATA=[message type="error" xmlns="jabber:client" from="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=988, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error, STABLE_ID=null

What's seems to be a pattern here is that majority (all?) of them relates to mobile devices (judging by the resource name: Id' say Xabber, Monal and even Siskin).

I think that my previous suggestion: "change tigase.xmpp.Authorization#getResponseMessage to actually check that both to and from are present;" should fixed all of those issues - it would skip generating any (faulty) package if it's not possible to deliver it because destination is missing (basically if packet without packetFrom and stanzaFrom entering getResponseMessage would not generate any packet - possibly throwing PacketErrorTypeException)

I checked one of the packets processing (message) and it seems that the issue is caused by tigase.xmpp.impl.MessageDeliveryLogic.handleDelivery and special handling for MAM should be done there:

# MAM response comming to SM and being processed

[2020-08-21 10:39:56:368] [FINEST  ] [   in_3-message-router ] SessionManagerClustered.processPacket(): Received packet: from=null, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns="jabber:client" to="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][/message], SIZE=759, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=null, STABLE_ID=40d8b228-9f29-4c94-9d90-c691db7feb32
[2020-08-21 10:39:56:368] [FINEST  ] [   in_3-message-router ] SessionManager.getXMPPResourceConnection(): Searching for resource connection for: layer8@tigase.im/iPhone von Layer
[2020-08-21 10:39:56:368] [FINEST  ] [   in_3-message-router ] SessionManager.getResourceConnection(): Session not null, searching session for jid: layer8@tigase.im/iPhone von Layer
[2020-08-21 10:39:56:368] [FINEST  ] [   in_3-message-router ] SessionManager.getResourceConnection(): Found session: XMPPResourceConnection=[user_jid=layer8@tigase.im/iPhone von Layer, packets=16, connectioId=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=463065581, parentSession liveTime=116965], for jid: layer8@tigase.im/iPhone von Layer
[2020-08-21 10:39:56:368] [FINEST  ] [   in_3-message-router ] SessionManagerClustered.processPacket(): Ressource connection found: XMPPResourceConnection=[user_jid=layer8@tigase.im/iPhone von Layer, packets=16, connectioId=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=463065581, parentSession liveTime=116965]
…
2020-08-21 10:39:56:369] [FINEST  ] [   in_3-message-router ] SessionManager.walk()            : XMPPProcessorIfc: MessageAmp (amp)Request: from=null, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns="jabber:client" to="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][/message], SIZE=759, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=null, STABLE_ID=40d8b228-9f29-4c94-9d90-c691db7feb32, conn: XMPPResourceConnection=[user_jid=layer8@tigase.im/iPhone von Layer, packets=16, connectioId=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=463065581, parentSession liveTime=116965]
[2020-08-21 10:39:56:368] [FINEST  ] [   in_3-message-router ] SessionManagerClustered.processPacket(): Received packet: from=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[iq id="12ff8fa8-2e79-45ad-88df-7220d5e9d5da" delay="120" type="set" to="sess-man@ip-10-0-35-46.us-west-2.compute.internal" retryCount="15" from="c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302"][command node="STREAM_CLOSED" xmlns="http://jabber.org/protocol/commands"][x type="submit" xmlns="jabber:x:data"][field var="user-jid"][value]CData size: 33[/value][/field][/x][/command][/iq], SIZE=439, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2020-08-21 10:39:56:369] [FINER   ] [   in_3-message-router ] SessionManager.processCommand()  : STREAM_CLOSED command from: c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302


# User disconnects

[2020-08-21 10:39:56:369] [FINEST  ] [   in_3-message-router ] ClientConnectionManager$StoppedHandler.responseReceived(): Response for stop received...

# Because in the meantime session disappeared message is deemed as for "offline user"

[2020-08-21 10:39:56:369] [FINEST  ] [   in_3-message-router ] MessageDeliveryLogic.handleDelivery(): Processing packet: from=null, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns="jabber:client" to="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][/message], SIZE=759, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=null, STABLE_ID=40d8b228-9f29-4c94-9d90-c691db7feb32, for session: XMPPResourceConnection=[user_jid=layer8@tigase.im/iPhone von Layer, packets=16, connectioId=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=463065581, parentSession liveTime=116965]
[2020-08-21 10:39:56:370] [FINEST  ] [   in_3-message-router ] MessageDeliveryLogic.handleDelivery(): Message &apos;to&apos; this user, packet: from=null, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns="jabber:client" to="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][/message], SIZE=759, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=null, STABLE_ID=40d8b228-9f29-4c94-9d90-c691db7feb32, for session: XMPPResourceConnection=[user_jid=layer8@tigase.im/iPhone von Layer, packets=16, connectioId=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_89.247.155.232_49302, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=463065581, parentSession liveTime=116965]
[2020-08-21 10:39:56:370] [FINEST  ] [   in_3-message-router ] MessageDeliveryLogic.processOfflineUser(): Processing message to offline user, packet: from=null, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns="jabber:client" to="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][/message], SIZE=759, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=null, STABLE_ID=40d8b228-9f29-4c94-9d90-c691db7feb32, deliveryRules: inteligent


# … and because it's not `chat` it generates error, which doesn't have any 'to' as it didn't have any 'from'


[2020-08-21 10:39:56:370] [FINEST  ] [   in_3-message-router ] JabberIqPrivacy.filter()         : Checking outbound packet: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=null, DATA=[message type="error" xmlns="jabber:client" from="layer8@tigase.im/iPhone von Layer"][result id="8d2d815d-25b8-433e-a91c-553dc5ff651e" queryid="EA722953-E777-4664-AEF9-8AEA7C2F7534" xmlns="urn:xmpp:mam:2"][forwarded xmlns="urn:xmpp:forward:0"][delay stamp="2020-08-21T00:07:42.755Z" xmlns="urn:xmpp:delay"/][message xmlns="jabber:client" to="layer8@tigase.im" from="push.tigase.im"][pubsub xmlns="http://jabber.org/protocol/pubsub" node="01#C5FBBC44ED7C3B262EE892DC3B4B3F5D7DB2D38EB3AF5178F781C9B73E946DA2"][affiliation jid="layer8@tigase.im" affiliation="none"/][/pubsub][/message][/forwarded][/result][delay stamp="2020-08-21T10:38:00.442Z" xmlns="urn:xmpp:delay" from="tigase.im"/][delivery-error stamp="1598006280442" xmlns="http://tigase.org/delivery-error"/][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"]CData size: 37[/text][/error][/message], SIZE=988, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=AUTH, TYPE=error, STABLE_ID=null

As I said - in this case we should handle MAM case and don't generate further messages/error.

Here is non-message example:

[2020-02-21 10:09:10:162] [FINEST  ] [   in_3-message-router ] ConnectionManager.writePacketToSocket(): c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, type: accept, Socket: TLS: c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112 Socket[unconnected], jid: null, Writing packet: from=null, to=c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, DATA=[stream:features][sm xmlns="urn:xmpp:sm:3"/][pipelining  xmlns="urn:xmpp:features:pipelining"/][auth xmlns="http://jabber.org/features/iq-auth"/][register xmlns="http://jabber.org/features/iq-register"/][mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"][mechanism]CData size: 13[/mechanism][mechanism]CData size: 11[/mechanism][mechanism]CData size: 5[/mechanism][/mechanisms][ver xmlns="urn:xmpp:features:rosterver"/][sub xmlns="urn:xmpp:features:pre-approval"/][compression xmlns="http://jabber.org/features/compress"][method]CData size: 4[/method][/compression][/stream:features], SIZE=564, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

[2020-02-21 10:09:10:162] [FINER   ] [   in_3-message-router ] SessionManager.processCommand()  : STREAM_CLOSED command from: c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112
[2020-02-21 10:09:10:162] [FINEST  ] [   in_3-message-router ] XMPPIOService.processWaitingPackets(): c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, type: accept, Socket: TLS: c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112 Socket[unconnected], jid: null, Sending packet: from=null, to=c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, DATA=[stream:features][sm xmlns="urn:xmpp:sm:3"/][pipelining  xmlns="urn:xmpp:features:pipelining"/][auth xmlns="http://jabber.org/features/iq-auth"/][register xmlns="http://jabber.org/features/iq-register"/][mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"][mechanism]CData size: 13[/mechanism][mechanism]CData size: 11[/mechanism][mechanism]CData size: 5[/mechanism][/mechanisms][ver xmlns="urn:xmpp:features:rosterver"/][sub xmlns="urn:xmpp:features:pre-approval"/][compression xmlns="http://jabber.org/features/compress"][method]CData size: 4[/method][/compression][/stream:features], SIZE=564, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

[2020-02-21 10:09:10:165] [FINER   ] [   in_3-message-router ] ConnectionManager.serviceStopped(): [[c2s]] Connection stopped: c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, type: accept, Socket: TLS: c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112 Socket[unconnected], jid: null
[2020-02-21 10:09:10:165] [WARNING ] [   in_3-message-router ] MessageRouter.processPacket()    : Packet with TO attribute set to NULL: from=c2s@ip-10-0-45-158.us-west-2.compute.internal/10.0.45.158_5222_154.160.21.160_32112, to=null, DATA=[stream:features type="error"][sm xmlns="urn:xmpp:sm:3"/][pipelining  xmlns="urn:xmpp:features:pipelining"/][auth xmlns="http://jabber.org/features/iq-auth"/][register xmlns="http://jabber.org/features/iq-register"/][mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"][mechanism]CData size: 13[/mechanism][mechanism]CData size: 11[/mechanism][mechanism]CData size: 5[/mechanism][/mechanisms][ver xmlns="urn:xmpp:features:rosterver"/][sub xmlns="urn:xmpp:features:pre-approval"/][compression xmlns="http://jabber.org/features/compress"][method]CData size: 4[/method][/compression][error code="404" type="wait"][recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/][/error][/stream:features], SIZE=683, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
Andrzej Wójcik (Tigase) commented 4 years ago

I agree that we may be able to fix that by improving a check in tigase.xmpp.Authorization#getResponseMessage so that if delivery of generated error stanza would not be possible, we would skip sending it.

Andrzej Wójcik (Tigase) commented 4 years ago

About MAM and mobile clients, those issues appear as mobile clients are disappearing during synchronization of messages and MAM component already sent those messages to the clients so we need to process them if there is no client (and drop them).

Andrzej Wójcik (Tigase) commented 4 years ago

About change in tigase.xmpp.impl.MessageDeliveryLogic.handleDelivery, will we need that after a change in Authorization#getResponseMessage? Wouldn't that fix this issue as well? (MessageDeliverLogic would not save a message and sending of an error back would fail...)

wojciech.kapcia@tigase.net commented 4 years ago

As fixing Authorization#getResponseMessage would tackle the issue completely I decided to go with that approach. I ran into an issue that currently method was throwing PacketErrorTypeException and reusing it for incorrect addressing would be kinda confusing. On the other hand changing thrown exception would require adjustment in many places (less of an issue) and would also change method signature which would result in API breakage (and we are not bumping major version here). After discussion with Andrzej we went for middleground approach - new, relevant exceptions were introduced and current exception was marked as deprecated with indication to adjust method signature in version 9.0.0.

I checked other places and it seems this shouldn't generate more warnings in this context (warnings for those errors were very inadequate).

Andrzej Wójcik (Tigase) commented 4 years ago

It looks like this change caused some tests (JUnit) to fail. See TC errors.

wojciech.kapcia@tigase.net commented 4 years ago
wojciech.kapcia@tigase.net commented 4 years ago

There was a problem with test - Packet objects didn't have any from addressing (neither stanza nor packet) so when error response was generated it didn't contain any to address (which made it undeliverable at all hence hitting this issue). I fixed the tests and add correct addressing.

wojciech.kapcia@tigase.net commented 4 years ago

The problem still exists in a way, but only for <presence/> packets:

StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-19-100.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_75.119.241.105_44322, DATA=…
wojciech.kapcia@tigase.net commented 4 years ago

Complete log entry:

[2020-08-28 08:33:06:646] [WARNING ] [scheduler_pool-15-thread-1-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-19-100.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_75.119.241.105_44322, DATA=[presence xmlns="jabber:client" from="hone@tigase.im/phone"][c ver="J4DkJOCHg8pwLcq6fqA2HW5Z3S0=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/][/presence], SIZE=207, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
issue 1 of 1
Type
Bug
Priority
Normal
Assignee
Version
tigase-server-8.2.0
Spent time
16h 35m
Issue Votes (0)
Watchers (0)
Reference
tigase/_server/server-core#1075
Please wait...
Page is in error, reload to recover