Project

General

Profile

Invalid SID - BOSH

Tue Topholm
Added over 1 year ago

Hi guys,

Suddenly I am experiencing Invalid SID responses from my installation.

Here is a small communication using strophe:

SENT <body rid='1238195164'

xmlns='http://jabber.org/protocol/httpbind' to='xmpp.yousee.tv' xml:lang='en' wait='60' hold='1' content='text/xml; charset=utf-8' ver='1.6' xmpp:version='1.0'

xmlns:xmpp='urn:xmpp:xbosh'/>

RECV <body

xmlns='http://jabber.org/protocol/httpbind'

xmlns:stream='http://etherx.jabber.org/streams'

xmlns:xmpp='urn:xmpp:xbosh' xmpp:version='1.0' wait='30' sid='494465ae-06d3-4f19-83ad-e5bf51719b56' secure='true' ack='1238195164' authid='9c033e82-f59c-4873-8906-e0827213d980' ver='1.6' from='xmpp.yousee.tv' hold='1' polling='10' requests='30' inactivity='30' host='p-xmpp01.yousee.idk' maxpause='30'/>

SENT <body rid='1238195165'

xmlns='http://jabber.org/protocol/httpbind' sid='494465ae-06d3-4f19-83ad-e5bf51719b56'/>

The first response also sometimes takes 30 seconds:

After I request the last one, it returns 404 (Invalid SID)

Have you seen this before?

Here is the log:

2017-08-25 21:42:08.813 [pool-12-thread-3] BoshConnectionManager.processSocketData() FINE: CREATE : 8dd45d1d-8338-4a06-bc05-71ea55ce43c6 (Socket bosh session)

2017-08-25 21:42:08.814 [pool-12-thread-3] BoshSession.disconnected() FINEST: TIMER : 8dd45d1d-8338-4a06-bc05-71ea55ce43c6 (10.233.113.24_5280_10.233.113.24_31867)

2017-08-25 21:42:08.817 [in_0-message-router] MessageRouter.processPacket() FINEST: Processing packet: from=null, to=null, DATA=a966dac9-069c-44d6-990b-88f90089a11axmpp.yousee.tven, SIZE=481, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:08.817 [in_0-message-router] MessageRouter.processPacket() FINEST: 1. Packet will be processed by: sess-man@p-xmpp01.yousee.idk, from=null, to=null, DATA=a966dac9-069c-44d6-990b-88f90089a11axmpp.yousee.tven, SIZE=481, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:08.818 [in_16-sess-man] SessionManagerClustered.processPacket() FINEST: Received packet: from=null, to=null, DATA=a966dac9-069c-44d6-990b-88f90089a11axmpp.yousee.tven, SIZE=481, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:08.818 [in_16-sess-man] SessionManager.processCommand() FINER: STREAM_OPENED command from: bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.822 [session-open Queue Worker 0] SessionManager$SessionOpenProc.process() FINER: Adding resource connection for: bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.823 [session-open Queue Worker 0] SessionManager.createUserSession() FINEST: Setting hostname xmpp.yousee.tv for connection: bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, VHostItem: Domain: xmpp.yousee.tv, enabled: true, anonym: true, register: true, maxusers: 0, tls: false, s2sSecret: edf740b7-839b-4012-985c-46bff2f04215, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null

2017-08-25 21:42:08.823 [session-open Queue Worker 0] SessionManager.createUserSession() FINEST: Domain set for connectionId bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.823 [session-open Queue Worker 0] SessionManager$SessionOpenProc.process() FINEST: Setting session-id a966dac9-069c-44d6-990b-88f90089a11a for connection: XMPPResourceConnection=[user_jid=null, packets=0, connectioId=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, domain=xmpp.yousee.tv, authState=NOT_AUTHORIZED, isAnon=false, isTmp=false]

2017-08-25 21:42:08.824 [in_3-message-router] MessageRouter.processPacket() FINEST: Processing packet: from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=, SIZE=164, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:08.824 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: Called for : bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.824 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: No componentID matches (fast lookup against exact address): bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, for map: [[basic-conf@p-xmpp01.yousee.idk, bosh@p-xmpp01.yousee.idk, cl-comp@p-xmpp01.yousee.idk, monitor@p-xmpp01.yousee.idk, c2s@p-xmpp01.yousee.idk, cluster-contr@p-xmpp01.yousee.idk, stats@p-xmpp01.yousee.idk, amp@p-xmpp01.yousee.idk, ws2s@p-xmpp01.yousee.idk, rest@p-xmpp01.yousee.idk, vhost-man@p-xmpp01.yousee.idk, sess-man@p-xmpp01.yousee.idk]]; trying VHost lookup

2017-08-25 21:42:08.824 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: Called for : bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.824 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: No componentID matches (fast lookup against exact address): bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, for map: [[basic-conf@p-xmpp01.yousee.idk, bosh@p-xmpp01.yousee.idk, cl-comp@p-xmpp01.yousee.idk, monitor@p-xmpp01.yousee.idk, c2s@p-xmpp01.yousee.idk, cluster-contr@p-xmpp01.yousee.idk, stats@p-xmpp01.yousee.idk, amp@p-xmpp01.yousee.idk, ws2s@p-xmpp01.yousee.idk, rest@p-xmpp01.yousee.idk, vhost-man@p-xmpp01.yousee.idk, sess-man@p-xmpp01.yousee.idk]]; trying VHost lookup

2017-08-25 21:42:08.824 [in_3-message-router] MessageRouter.processPacket() FINEST: 1. Packet will be processed by: bosh@p-xmpp01.yousee.idk, from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=, SIZE=164, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:08.824 [session-open Queue Worker 0] DomainFilter.filter() FINEST: Filtering (packet): from=null, to=null, DATA=a966dac9-069c-44d6-990b-88f90089a11axmpp.yousee.tven, SIZE=481, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:08.824 [in_0-message-router] MessageRouter.processPacket() FINEST: Processing packet: from=null, to=null, DATA=, SIZE=238, XMLNS=null, PRIORITY=HIGH, PERMISSION=NONE, TYPE=get

2017-08-25 21:42:08.825 [in_0-message-router] MessageRouter.processPacket() FINEST: 1. Packet will be processed by: sess-man@p-xmpp01.yousee.idk, from=null, to=null, DATA=, SIZE=238, XMLNS=null, PRIORITY=HIGH, PERMISSION=NONE, TYPE=get

2017-08-25 21:42:08.825 [in_16-sess-man] SessionManagerClustered.processPacket() FINEST: Received packet: from=null, to=null, DATA=, SIZE=238, XMLNS=null, PRIORITY=HIGH, PERMISSION=NONE, TYPE=get

2017-08-25 21:42:08.825 [in_16-sess-man] SessionManager.processCommand() FINER: GETFEATURES command from: bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.825 [in_3-message-router] MessageRouter.processPacket() FINEST: Processing packet: from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=PLAINANONYMOUSzlib, SIZE=611, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:08.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: Called for : bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: No componentID matches (fast lookup against exact address): bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, for map: [[basic-conf@p-xmpp01.yousee.idk, bosh@p-xmpp01.yousee.idk, cl-comp@p-xmpp01.yousee.idk, monitor@p-xmpp01.yousee.idk, c2s@p-xmpp01.yousee.idk, cluster-contr@p-xmpp01.yousee.idk, stats@p-xmpp01.yousee.idk, amp@p-xmpp01.yousee.idk, ws2s@p-xmpp01.yousee.idk, rest@p-xmpp01.yousee.idk, vhost-man@p-xmpp01.yousee.idk, sess-man@p-xmpp01.yousee.idk]]; trying VHost lookup

2017-08-25 21:42:08.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: Called for : bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:08.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: No componentID matches (fast lookup against exact address): bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, for map: [[basic-conf@p-xmpp01.yousee.idk, bosh@p-xmpp01.yousee.idk, cl-comp@p-xmpp01.yousee.idk, monitor@p-xmpp01.yousee.idk, c2s@p-xmpp01.yousee.idk, cluster-contr@p-xmpp01.yousee.idk, stats@p-xmpp01.yousee.idk, amp@p-xmpp01.yousee.idk, ws2s@p-xmpp01.yousee.idk, rest@p-xmpp01.yousee.idk, vhost-man@p-xmpp01.yousee.idk, sess-man@p-xmpp01.yousee.idk]]; trying VHost lookup

2017-08-25 21:42:08.827 [in_3-message-router] MessageRouter.processPacket() FINEST: 1. Packet will be processed by: bosh@p-xmpp01.yousee.idk, from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=PLAINANONYMOUSzlib, SIZE=611, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:08.827 [in_3-bosh] BoshConnectionManager.processPacket() FINEST: Processing packet: from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=PLAINANONYMOUSzlib, SIZE=611, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:08.827 [in_3-bosh] ClientConnectionManager.processPacket() FINEST: Processing packet: from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=CData size: 5CData size: 9CData size: 4, SIZE=611, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:08.828 [in_3-bosh] BoshSession.processPacket() FINEST: [0] Processing packet: from=null, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=stream:featuresPLAINANONYMOUSzlib/stream:features, SIZE=396, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

2017-08-25 21:42:18.816 [scheduler_pool-3-thread-1-bosh] BoshSession.task() FINEST: task called for 8dd45d1d-8338-4a06-bc05-71ea55ce43c6, inactivityTimer = tigase.server.bosh.BoshTask@3bcc3826, tt = tigase.server.bosh.BoshTask@3bcc3826

2017-08-25 21:42:18.817 [scheduler_pool-3-thread-1-bosh] BoshSession.task() FINEST: TIMER : 8dd45d1d-8338-4a06-bc05-71ea55ce43c6 (inactivityTimer fired)

2017-08-25 21:42:18.817 [scheduler_pool-3-thread-1-bosh] BoshSession.task() FINEST: REMOVE : 8dd45d1d-8338-4a06-bc05-71ea55ce43c6 (Closing session, inactivity timeout expired)

2017-08-25 21:42:18.818 [scheduler_pool-3-thread-1-bosh] BoshConnectionManager.addOutStreamClosed() FINEST: REMOVE : 8dd45d1d-8338-4a06-bc05-71ea55ce43c6 (Closing bosh session)

2017-08-25 21:42:18.818 [in_3-message-router] MessageRouter.processPacket() FINEST: Processing packet: from=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, to=sess-man@p-xmpp01.yousee.idk, DATA=, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:18.818 [in_3-message-router] MessageRouter.processPacket() FINEST: 1. Packet will be processed by: sess-man@p-xmpp01.yousee.idk, from=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, to=sess-man@p-xmpp01.yousee.idk, DATA=, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:18.818 [scheduler_pool-3-thread-1-bosh] BoshTask.run() FINER: Closing session for BS task: 8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:18.818 [in_3-sess-man] SessionManagerClustered.processPacket() FINEST: Received packet: from=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, to=sess-man@p-xmpp01.yousee.idk, DATA=, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:18.820 [in_3-sess-man] SessionManager.processCommand() FINER: STREAM_CLOSED command from: bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:18.820 [in_3-message-router] MessageRouter.processPacket() FINEST: Processing packet: from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=, SIZE=164, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:18.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: Called for : bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:18.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: No componentID matches (fast lookup against exact address): bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, for map: [[basic-conf@p-xmpp01.yousee.idk, bosh@p-xmpp01.yousee.idk, cl-comp@p-xmpp01.yousee.idk, monitor@p-xmpp01.yousee.idk, c2s@p-xmpp01.yousee.idk, cluster-contr@p-xmpp01.yousee.idk, stats@p-xmpp01.yousee.idk, amp@p-xmpp01.yousee.idk, ws2s@p-xmpp01.yousee.idk, rest@p-xmpp01.yousee.idk, vhost-man@p-xmpp01.yousee.idk, sess-man@p-xmpp01.yousee.idk]]; trying VHost lookup

2017-08-25 21:42:18.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: Called for : bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:18.827 [in_3-message-router] MessageRouter.getLocalComponent() FINEST: No componentID matches (fast lookup against exact address): bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, for map: [[basic-conf@p-xmpp01.yousee.idk, bosh@p-xmpp01.yousee.idk, cl-comp@p-xmpp01.yousee.idk, monitor@p-xmpp01.yousee.idk, c2s@p-xmpp01.yousee.idk, cluster-contr@p-xmpp01.yousee.idk, stats@p-xmpp01.yousee.idk, amp@p-xmpp01.yousee.idk, ws2s@p-xmpp01.yousee.idk, rest@p-xmpp01.yousee.idk, vhost-man@p-xmpp01.yousee.idk, sess-man@p-xmpp01.yousee.idk]]; trying VHost lookup

2017-08-25 21:42:18.827 [in_3-message-router] MessageRouter.processPacket() FINEST: 1. Packet will be processed by: bosh@p-xmpp01.yousee.idk, from=sess-man@p-xmpp01.yousee.idk, to=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, DATA=, SIZE=164, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result

2017-08-25 21:42:18.820 [session-close Queue Worker 3] SessionManager$SessionCloseProc.process() FINEST: Executing connection close for: from=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, to=sess-man@p-xmpp01.yousee.idk, DATA=, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:18.827 [session-close Queue Worker 3] SessionManager.closeConnection() FINER: Stream closed from: bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6

2017-08-25 21:42:18.828 [session-close Queue Worker 3] SessionManagerClustered.closeSession() FINEST: Called for conn: XMPPResourceConnection=[user_jid=null, packets=0, connectioId=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, domain=xmpp.yousee.tv, authState=NOT_AUTHORIZED, isAnon=false, isTmp=false], closeOnly: false

2017-08-25 21:42:18.830 [session-close Queue Worker 3] DomainFilter.filter() FINEST: Filtering (packet): from=bosh@p-xmpp01.yousee.idk/8dd45d1d-8338-4a06-bc05-71ea55ce43c6, to=sess-man@p-xmpp01.yousee.idk, DATA=, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

2017-08-25 21:42:26.885 [pool-12-thread-8] BoshConnectionManager.processSocketData() FINEST: Processing socket data: from=null, to=null, DATA=, SIZE=111, XMLNS=http://jabber.org/protocol/httpbind, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

2017-08-25 21:42:26.885 [pool-12-thread-8] BoshConnectionManager.processSocketData() FINE: INVALID_SID : 8dd45d1d-8338-4a06-bc05-71ea55ce43c6 (Invalid SID)

Is using 7.0.4 and mysql. It is running behind a F5 Big IP load balancer, but on this one I am just connecting to a single machine directly.


Replies (2)

Added by Tue Topholm over 1 year ago

I am also seeing Invalid hostname.

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 1 year ago

Invalid hostname usually means misconfiguration of the Tigase server or network (DNS).

Invalid SID usually happens when you have clustered installation and your client makes first requests to one of the cluster nodes and then makes another request to a different cluster node.

    (1-2/2)