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

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

Activities

	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 'to' 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 Relevant link: https://tc.tigase.net/viewLog.html?buildId=50207&buildTypeId=TigaseMessageArchiving_Build
	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 'stanzaTo' and 'packetTo' 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 'stanzaTo' and 'packetTo' 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

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

Related

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#1075

Please wait...

Page is in error, reload to recover