Message carbons generating excessive traffic (#428)

Activities

Artur Hefczyc opened 10 years ago

Due Date
2015-02-15

After logs analysis attached to message#4301 it looks like an IQ with message carbons enabling request gets to SM (message carbons plugin) a IQ result is generated and also a new IQ is generated (disabling message carbons without ID). This in turn is being processed by SM (and plugin) generating IQ result and again a new IQ set request (disabling message carbons with ID).

As a result a client receives a flood of IQ results without ID.

Log excerpt (complete logs can be found attached to the topic)

 2015-02-12 23:20:12.705 [pool-15-thread-1]  BoshConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<body rid="6961223301" xmlns="http://jabber.org/protocol/httpbind" sid="ec6996e9-fc79-4045-8ca5-cab618ec6507"><iq from="lmc@*chat.bid2bang.com" id="enablecarbons" xmlns="jabber:client" type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq><iq id="1:roster" xmlns="jabber:client" type="get"><query xmlns="jabber:iq:roster"/></iq></body>, SIZE=332, XMLNS=http://jabber.org/protocol/httpbind, PRIOR*ITY=NORMAL, PERMISSION=NONE, TYPE=null
 2015-02-12 23:20:12.705 [pool-15-thread-1]  BoshSession.processSocketPacket()  FINEST:  [0] Processing socket packet: from=null, to=null, DATA=<body rid="6961223301" xmlns="http://jabber.org/protocol/httpbind" sid="ec6996e9-fc79-4045-8ca5-cab618ec6507"><iq from="lmc@c*hat.bid2bang.com" id="enablecarbons" xmlns="jabber:client" type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq><iq id="1:roster" xmlns="jabber:client" type="get"><query xmlns="jabber:iq:roster"/></iq></body>, SIZE=332, XMLNS=http://jabber.org/protocol/httpbind, PRIORI*TY=NORMAL, PERMISSION=NONE, TYPE=null
 2015-02-12 23:20:12.705 [pool-15-thread-1]  BoshSession.processSocketPacket()  FINEST:  Canceling inactivityTimer: ec6996e9-fc79-4045-8ca5-cab618ec6507
 2015-02-12 23:20:12.705 [pool-15-thread-1]  BoshSession.processSocketPacket()  FINEST:  Setting waitTimer for 30: ec6996e9-fc79-4045-8ca5-cab618ec6507
*2015-02-12 23:20:12.706 [pool-15-thread-1]  BoshSession.processSocketPacket()  FINEST:  Sending out packet: from=null, to=null, DATA=<iq from="lmc@chat.bid2bang.com" id="enablecarbons" xmlns="jabber:client" type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=12*6, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set
 2015-02-12 23:20:12.706 [pool-15-thread-1]  BoshSession.processSocketPacket()  FINEST:  Sending out packet: from=null, to=null, DATA=<iq id="1:roster" xmlns="jabber:client" type="get"><query xmlns="jabber:iq:roster"/></iq>, SIZE=89, XMLNS=jabber:client, PRIORITY=NORMA L, PERMISSION=NONE, TYPE=get
 2015-02-12 23:20:12.706 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, to=sess-man@b2bdv-node, DATA=<iq from="lmc@chat.bid2bang.com" id="enablecarbons" xmlns="jabber:client"* type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=126, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set
 2015-02-12 23:20:12.706 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@b2bdv-node
 2015-02-12 23:20:12.706 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@b2bdv-node, from=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, to=sess-man@b2bdv-node, DATA=<iq from="lmc@chat.bid2bang.com" id="en*ablecarbons" xmlns="jabber:client" type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=126, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set
 2015-02-12 23:20:12.707 [in_4-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, to=sess-man@b2bdv-node, DATA=<iq from="lmc@chat.bid2bang.com" id="enablecarbons" xmlns="jabber:client"* type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=126, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set, connection: user_jid=lmc@chat.bid2bang.com/tigase-1, packets=3, connectioId=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, domain=c*hat.bid2bang.com, authState=AUTHORIZED, isAnon=false, isTmp=false
 2015-02-12 23:20:12.707 [in_4-sess-man]    PacketDefaultHandler.preprocess()  FINEST:   Skipping setting correct from attribute: lmc@chat.bid2bang.com/tigase-1, is already correct.
 2015-02-12 23:20:12.707 [in_4-sess-man]    SessionManager.walk()              FINEST:   XMPPProcessorIfc: MessageCarbons (message-carbons)Request: from=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, to=sess-man@b2bdv-node, DATA=<iq from="lmc@chat.bid2bang.com" *id="enablecarbons" xmlns="jabber:client" type="set"><enable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=126, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set, conn: user_jid=lmc@chat.bid2bang.com/tigase-1, packets=4, connectioId=bosh@b2bdv-node/ec6996e9-fc7*9-4045-8ca5-cab618ec6507, domain=chat.bid2bang.com, authState=AUTHORIZED, isAnon=false, isTmp=false
 2015-02-12 23:20:12.708 [in_4-sess-man]    SessionManager.processPacket()     FINEST:   Packet processed by: [message-carbons]
*2015-02-12 23:20:12.711 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=sess-man@b2bdv-node, to=null, DATA=<iq to="lmc@chat.bid2bang.com" xmlns="jabber:client" type="set" from="lmc@chat.bid2bang.com/tigase-1"><disable xmlns="urn*:xmpp:carbons:2"/></iq>, SIZE=144, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set
 2015-02-12 23:20:12.712 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : lmc@chat.bid2bang.com
 2015-02-12 23:20:12.712 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches (fast lookup): lmc@chat.bid2bang.com, for map: {bosh@b2bdv-node=tigase.cluster.BoshConnectionClustered@51de4e31, s2s@b2bdv-node=tigase.cluster.S2SConnectionCl ustered@5c464132, proxy@b2bdv-node=tigase.socks5.Socks5ProxyComponent@39c4d0cd, stats@b2bdv-node=tigase.stats.StatisticsCollector@127fe494, muc@b2bdv-node=tigase.muc.MUCComponent@40f72a51, monitor@b2bdv-node=tigase.cluster.MonitorClustered@30221872, cl-comp@b2bdv-node =tigase.cluster.ClusterConnectionManager@7c92a214, message-archive@b2bdv-node=tigase.archive.MessageArchiveComponent@22762e43, vhost-man@b2bdv-node=tigase.cluster.VHostManagerClustered@26506c57, c2s@b2bdv-node=tigase.cluster.ClientConnectionClustered@70917c5c, cluster -contr@b2bdv-node=tigase.cluster.ClusterController@79764f5f, ws2s@b2bdv-node=tigase.cluster.WebSocketClientConnectionClustered@6efce31f, pubsub@b2bdv-node=tigase.pubsub.PubSubComponent@51c5f232, sess-man@b2bdv-node=tigase.cluster.SessionManagerClustered@2fe6f732, amp@ b2bdv-node=tigase.server.amp.AmpComponent@53d01363, basic-conf@b2bdv-node=tigase.conf.Configurator@277ba411}
 2015-02-12 23:20:12.712 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Still no comp name matches (VHost lookup): lmc@chat.bid2bang.com, for map: {cl-comp=tigase.cluster.ClusterConnectionManager@7c92a214, c2s=tigase.cluster.ClientConnectionClustered @70917c5c, basic-conf=tigase.conf.Configurator@277ba411, s2s=tigase.cluster.S2SConnectionClustered@5c464132, cluster-contr=tigase.cluster.ClusterController@79764f5f, bosh=tigase.cluster.BoshConnectionClustered@51de4e31, proxy=tigase.socks5.Socks5ProxyComponent@39c4d0c d, vhost-man=tigase.cluster.VHostManagerClustered@26506c57, sess-man=tigase.cluster.SessionManagerClustered@2fe6f732, ws2s=tigase.cluster.WebSocketClientConnectionClustered@6efce31f, message-router=tigase.server.MessageRouter@69f8d767, stats=tigase.stats.StatisticsCol lector@127fe494, message-archive=tigase.archive.MessageArchiveComponent@22762e43, pubsub=tigase.pubsub.PubSubComponent@51c5f232, amp=tigase.server.amp.AmpComponent@53d01363, monitor=tigase.cluster.MonitorClustered@30221872, muc=tigase.muc.MUCComponent@40f72a51}, for a ll VHosts: {3}
 2015-02-12 23:20:12.712 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: lmc@chat.bid2bang.com, for comp: {cl-comp=tigase.cluster.ClusterConnectionManager@7c92a214, c2s=tigase.cluster.ClientConnectionClustered@70917c5c, basic-c onf=tigase.conf.Configurator@277ba411, s2s=tigase.cluster.S2SConnectionClustered@5c464132, cluster-contr=tigase.cluster.ClusterController@79764f5f, bosh=tigase.cluster.BoshConnectionClustered@51de4e31, proxy=tigase.socks5.Socks5ProxyComponent@39c4d0cd, vhost-man=tigas e.cluster.VHostManagerClustered@26506c57, sess-man=tigase.cluster.SessionManagerClustered@2fe6f732, ws2s=tigase.cluster.WebSocketClientConnectionClustered@6efce31f, message-router=tigase.server.MessageRouter@69f8d767, stats=tigase.stats.StatisticsCollector@127fe494, m essage-archive=tigase.archive.MessageArchiveComponent@22762e43, pubsub=tigase.pubsub.PubSubComponent@51c5f232, amp=tigase.server.amp.AmpComponent@53d01363, monitor=tigase.cluster.MonitorClustered@30221872, muc=tigase.muc.MUCComponent@40f72a51}, basename: bid2bang.com
 2015-02-12 23:20:12.712 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : lmc@chat.bid2bang.com
 2015-02-12 23:20:12.713 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches (fast lookup): lmc@chat.bid2bang.com, for map: {bosh@b2bdv-node=tigase.cluster.BoshConnectionClustered@51de4e31, s2s@b2bdv-node=tigase.cluster.S2SConnectionCl ustered@5c464132, proxy@b2bdv-node=tigase.socks5.Socks5ProxyComponent@39c4d0cd, stats@b2bdv-node=tigase.stats.StatisticsCollector@127fe494, muc@b2bdv-node=tigase.muc.MUCComponent@40f72a51, monitor@b2bdv-node=tigase.cluster.MonitorClustered@30221872, cl-comp@b2bdv-node =tigase.cluster.ClusterConnectionManager@7c92a214, message-archive@b2bdv-node=tigase.archive.MessageArchiveComponent@22762e43, vhost-man@b2bdv-node=tigase.cluster.VHostManagerClustered@26506c57, c2s@b2bdv-node=tigase.cluster.ClientConnectionClustered@70917c5c, cluster -contr@b2bdv-node=tigase.cluster.ClusterController@79764f5f, ws2s@b2bdv-node=tigase.cluster.WebSocketClientConnectionClustered@6efce31f, pubsub@b2bdv-node=tigase.pubsub.PubSubComponent@51c5f232, sess-man@b2bdv-node=tigase.cluster.SessionManagerClustered@2fe6f732, amp@ b2bdv-node=tigase.server.amp.AmpComponent@53d01363, basic-conf@b2bdv-node=tigase.conf.Configurator@277ba411}
 2015-02-12 23:20:12.713 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Still no comp name matches (VHost lookup): lmc@chat.bid2bang.com, for map: {cl-comp=tigase.cluster.ClusterConnectionManager@7c92a214, c2s=tigase.cluster.ClientConnectionClustered @70917c5c, basic-conf=tigase.conf.Configurator@277ba411, s2s=tigase.cluster.S2SConnectionClustered@5c464132, cluster-contr=tigase.cluster.ClusterController@79764f5f, bosh=tigase.cluster.BoshConnectionClustered@51de4e31, proxy=tigase.socks5.Socks5ProxyComponent@39c4d0c d, vhost-man=tigase.cluster.VHostManagerClustered@26506c57, sess-man=tigase.cluster.SessionManagerClustered@2fe6f732, ws2s=tigase.cluster.WebSocketClientConnectionClustered@6efce31f, message-router=tigase.server.MessageRouter@69f8d767, stats=tigase.stats.StatisticsCol lector@127fe494, message-archive=tigase.archive.MessageArchiveComponent@22762e43, pubsub=tigase.pubsub.PubSubComponent@51c5f232, amp=tigase.server.amp.AmpComponent@53d01363, monitor=tigase.cluster.MonitorClustered@30221872, muc=tigase.muc.MUCComponent@40f72a51}, for a ll VHosts: {3}
 2015-02-12 23:20:12.713 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: lmc@chat.bid2bang.com, for comp: {cl-comp=tigase.cluster.ClusterConnectionManager@7c92a214, c2s=tigase.cluster.ClientConnectionClustered@70917c5c, basic-c onf=tigase.conf.Configurator@277ba411, s2s=tigase.cluster.S2SConnectionClustered@5c464132, cluster-contr=tigase.cluster.ClusterController@79764f5f, bosh=tigase.cluster.BoshConnectionClustered@51de4e31, proxy=tigase.socks5.Socks5ProxyComponent@39c4d0cd, vhost-man=tigas e.cluster.VHostManagerClustered@26506c57, sess-man=tigase.cluster.SessionManagerClustered@2fe6f732, ws2s=tigase.cluster.WebSocketClientConnectionClustered@6efce31f, message-router=tigase.server.MessageRouter@69f8d767, stats=tigase.stats.StatisticsCollector@127fe494, m essage-archive=tigase.archive.MessageArchiveComponent@22762e43, pubsub=tigase.pubsub.PubSubComponent@51c5f232, amp=tigase.server.amp.AmpComponent@53d01363, monitor=tigase.cluster.MonitorClustered@30221872, muc=tigase.muc.MUCComponent@40f72a51}, basename: bid2bang.com
 2015-02-12 23:20:12.714 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   2. Packet will be processed by: sess-man@b2bdv-node, from=sess-man@b2bdv-node, to=null, DATA=<iq to="lmc@chat.bid2bang.com" xmlns="jabber:client" type="set" from="lmc@chat.bid2bang*.com/tigase-1"><disable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=144, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set
 2015-02-12 23:20:12.715 [in_0-sess-man]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: lmc@chat.bid2bang.com
 2015-02-12 23:20:12.715 [in_0-sess-man]    SessionManager.getResourceConnection()  FINEST: Session not null, searching session for jid: lmc@chat.bid2bang.com
 2015-02-12 23:20:12.716 [in_0-sess-man]    SessionManager.getResourceConnection()  FINEST: Found session: user_jid=lmc@chat.bid2bang.com/tigase-1, packets=4, connectioId=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, domain=chat.bid2bang.com, authState=AUTHORIZ ED, isAnon=false, isTmp=false, for jid: lmc@chat.bid2bang.com
 2015-02-12 23:20:12.716 [in_0-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=sess-man@b2bdv-node, to=sess-man@b2bdv-node, DATA=<iq to="lmc@chat.bid2bang.com" xmlns="jabber:client" type="set" from="lmc@chat.bid2bang.com/tigase-1"><dis*able xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=144, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set, connection: user_jid=lmc@chat.bid2bang.com/tigase-1, packets=4, connectioId=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab618ec6507, domain=chat.bid2bang.co*m, authState=AUTHORIZED, isAnon=false, isTmp=false
 2015-02-12 23:20:12.717 [in_0-sess-man]    SessionManager.walk()              FINEST:   XMPPProcessorIfc: MessageCarbons (message-carbons)Request: from=sess-man@b2bdv-node, to=sess-man@b2bdv-node, DATA=<iq to="lmc@chat.bid2bang.com" xmlns="jabber:client" type="set" fr*om="lmc@chat.bid2bang.com/tigase-1"><disable xmlns="urn:xmpp:carbons:2"/></iq>, SIZE=144, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set, conn: user_jid=lmc@chat.bid2bang.com/tigase-1, packets=5, connectioId=bosh@b2bdv-node/ec6996e9-fc79-4045-8ca5-cab*618ec6507, domain=chat.bid2bang.com, authState=AUTHORIZED, isAnon=false, isTmp=false

Andrzej Wójcik (Tigase) commented 10 years ago

I checked this issue and it was caused by from attribute being set to bare jid. It should be replaced on server side by full jid of user connection, which was not done. I fixed this by changes in plugin to make sure this issue will not happen, but I also decided to fix code responsible for setting from to make sure that it is set to full jid as it should be according to latest RFC about XMPP.

During verification of this fix, I also found issue with Message Carbons not working properly with latest ACS and fixed this to make sure we have Message Carbons working in clustering with or without ACS.

Artur Hefczyc commented 10 years ago

Just make sure the form attribute is correctly set in all cases, as the spec is different depending on the stanza type. For example, presence subscriptions should have the from attribute set to BareJID. If this is implemented correctly you can close the ticket.

Andrzej Wójcik (Tigase) commented 10 years ago

Yes, it is implemented correctly according to RFC to make Tigase XMPP Server RFC compatible.

Artur Hefczyc commented 10 years ago

Thank you.

Type	Bug
Priority	Major
Assignee	Artur Hefczyc
RedmineID	2693
Spent time	36h

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#428