Better handling of "The target is unavailable at this time." / PacketInvalidTypeException (#1303)

Activities
wojciech.kapcia@tigase.net opened 3 years ago
There are relatively lot warnings regarding packet delivery to (most likely mobile, iPhone) users. On the one hand those shouldn't be logged as Warnings, on the other - those should not be generated (i.e. track the root cause instead of dedicated handling)
[2021-12-02 06:15:21:271] [WARNING ] [   in_0-message-router ] MessageRouter.processPacketMR()  : Packet processing exception: tigase.xmpp.PacketInvalidTypeException: The packet has already 'error' type: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=message-router@tigase.im, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq to="message-router@tigase.im" type="error" id="556DE602-6326-4DFA-832D-D559FF551F84" xmlns="jabber:client" from="…@tigase.im/iPhoneXS-…"><query xmlns="http://jabber.org/protocol/disco#info"><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="router" category="component"/><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="im" category="server"/><feature var="http://jabber.org/protocol/commands"/><x type="result" xmlns="jabber:x:data"><field type="hidden" var="FORM_TYPE"><value>http://jabber.org/network/serverinfo</value></field><field type="list-multi" var="abuse-addresses"><value>mailto:support@tigase.net</value><value>xmpp:tigase@muc.tigase.im</value><value>https://tigase.net/technical-support</value></field></x></query><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 target is unavailable at this time.</text></error></iq>, SIZE=1008, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
…
[2021-12-02 08:30:04:805] [WARNING ] [   in_0-message-router ] MessageRouter.processPacketMR()  : Packet processing exception: tigase.xmpp.PacketInvalidTypeException: The packet has already 'error' type: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=message-router@jabber.today, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq to="message-router@jabber.today" type="error" id="005E026F-949E-4C9A-9237-BF90CF06AD4B" xmlns="jabber:client" from="…@jabber.today/…"><query xmlns="http://jabber.org/protocol/disco#info"><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="router" category="component"/><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="im" category="server"/><feature var="http://jabber.org/protocol/commands"/><x type="result" xmlns="jabber:x:data"><field type="hidden" var="FORM_TYPE"><value>http://jabber.org/network/serverinfo</value></field><field type="list-multi" var="abuse-addresses"><value>mailto:support@tigase.net</value><value>xmpp:tigase@muc.tigase.im</value><value>https://tigase.net/technical-support</value></field></x></query><error code="404" type="wait"><recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">The target is unavailable at this time.</text></error></iq>, SIZE=986, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
…
[2021-12-02 09:08:23:211] [WARNING ] [   in_0-message-router ] MessageRouter.processPacketMR()  : Packet processing exception: tigase.xmpp.PacketInvalidTypeException: The packet has already 'error' type: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=message-router@jabber.today, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq to="message-router@jabber.today" type="error" id="43C107AD-9B5C-499C-8A80-87C72ABF7C83" xmlns="jabber:client" from="…@jabber.today/…iPhone"><query xmlns="http://jabber.org/protocol/disco#info"><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="router" category="component"/><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="im" category="server"/><feature var="http://jabber.org/protocol/commands"/><x type="result" xmlns="jabber:x:data"><field type="hidden" var="FORM_TYPE"><value>http://jabber.org/network/serverinfo</value></field><field type="list-multi" var="abuse-addresses"><value>mailto:support@tigase.net</value><value>xmpp:tigase@muc.tigase.im</value><value>https://tigase.net/technical-support</value></field></x></query><error code="404" type="wait"><recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">The target is unavailable at this time.</text></error></iq>, SIZE=994, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
…
[2021-12-02 09:30:17:009] [WARNING ] [   in_0-message-router ] MessageRouter.processPacketMR()  : Packet processing exception: tigase.xmpp.PacketInvalidTypeException: The packet has already 'error' type: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=message-router@tigase.im, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq to="message-router@tigase.im" type="error" id="DF753C2B-3810-42DE-9276-79552550A73F" xmlns="jabber:client" from="…@tigase.im/…"><query xmlns="http://jabber.org/protocol/disco#info"><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="router" category="component"/><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="im" category="server"/><feature var="http://jabber.org/protocol/commands"/><x type="result" xmlns="jabber:x:data"><field type="hidden" var="FORM_TYPE"><value>http://jabber.org/network/serverinfo</value></field><field type="list-multi" var="abuse-addresses"><value>mailto:support@tigase.net</value><value>xmpp:tigase@muc.tigase.im</value><value>https://tigase.net/technical-support</value></field></x></query><error code="404" type="wait"><recipient-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">The target is unavailable at this time.</text></error></iq>, SIZE=983, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
…
[2021-12-02 10:01:48:204] [WARNING ] [   in_0-message-router ] MessageRouter.processPacketMR()  : Packet processing exception: tigase.xmpp.PacketInvalidTypeException: The packet has already 'error' type: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=message-router@tigase.im, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq to="message-router@tigase.im" type="error" id="A20AD63F-0860-423D-8E92-CB37FFE0E800" xmlns="jabber:client" from="…@tigase.im/iPhoneXS-…"><query xmlns="http://jabber.org/protocol/disco#info"><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="router" category="component"/><identity name="Tigase ver. 8.2.0-SNAPSHOT-b11574/c2603d9c" type="im" category="server"/><feature var="http://jabber.org/protocol/commands"/><x type="result" xmlns="jabber:x:data"><field type="hidden" var="FORM_TYPE"><value>http://jabber.org/network/serverinfo</value></field><field type="list-multi" var="abuse-addresses"><value>mailto:support@tigase.net</value><value>xmpp:tigase@muc.tigase.im</value><value>https://tigase.net/technical-support</value></field></x></query><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 target is unavailable at this time.</text></error></iq>, SIZE=1008, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
…
wojciech.kapcia@tigase.net commented 3 years ago
Logging refined, adjusted slightly ServiceDiscovery plugin to avoid generating packets when not needed.
wojciech.kapcia@tigase.net commented 3 years ago
The issue is fixed.
Type	Task
Priority	Normal
Assignee	wojciech.kapcia@tigase.net
Version	tigase-server-8.2.0
Spent time	2h 30m
Issue Votes (0)
Watchers (0)
Reference
tigase/_server/server-core#1303