I’m not sure what the problem is here, if it’s a problem with a way the client is requesting the session to be paused or the way it’s resuming it.
From the extra debugging logging I’ve added to the openfire server, it looks like the pause is happening correctly, as the default wait period goes from 30 to 120.
Here’s the inital connect sequnce:
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b): <body xmlns:xmpp=“urn:xmpp:xbosh” content=“text/xml; charset=utf-8” hold=“1” requests=“2” rid=“8338017” to="host.chatserver.
net" inactivity=“300” ver=“1.6” cache=“on” wait=“120” maxpause=“120” secure=“false” xmpp:version=“1.0” xmpp:restartlogic=“true”>
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b): <body xmlns="****http://jabber.org/protocol/httpbind" xmlns:stream=“http://etherx.jabber.org/streams” authid=“86cbe04b” sid="86cb
e04b" secure=“true” requests=“5” inactivity=“30” polling=“5” wait=“120” hold=“1” ack=“8338017” maxpause=“300” ver=“1.6”>stream:features<mechanisms xmlns="urn:ietf:params:xml:n
s:xmpp-sasl">DIGEST-MD5JIVE-SHAREDSECRET</mech anism>PLAINANONYMOUSCRA M-MD5
zlib<session xmlns="urn:ietf
:params:xml:ns:xmpp-session"/></stream:features>
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b): ADQyADQy
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b):
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b):
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b): ijab34CF
3
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b): stream:features<compressi
on xmlns=“http://jabber.org/features/compress”>zlib<session xmlns="urn:ietf:params:xml:ns:xmpp-ses
sion"/></stream:features>
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b): <iq xmlns=“jabber:client” type=“result” id=“drJT” to="host.chatserver.net/
86cbe04b">42@host.chatserver.net/ijab34CF3
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b):
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b): <iq xmlns=“jabber:client” type=“result” id=“get_roster_0” to="42@java.vs.sr
.dbuzz.net/ijab34CF3">Contacts<item jid="8@java.vs.sr.db
uzz.net" name=“warrenski” subscription=“none”>ContactsContacts</it
em>ContactsC
ontactsContacts<item jid="1575947@host.chatserver.net" name="garth
m_t" subscription=“none”>ContactsContacts<item jid="3@ja
va.vs.sr.dbuzz.net" name=“zarf” subscription=“none”>ContactsContacts</g
roup>Contacts<item jid="7@host.chatserver.net" name=“Zarina” subscription="none
“>ContactsContacts<item jid="1@host.chatserver.net” name="dm
f" subscription=“none”>ContactsContacts</
body>
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b): 5
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b): <vCard xmlns=“vcard-temp” version="2
.0" prodid="-//HandGen//NONSGML vGen v1.0//EN"/>
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b):
Fri May 27 11:48:21 SAST 2011: HTTP RECV(86cbe04b): <
/query>
Fri May 27 11:48:21 SAST 2011: HTTP SENT(86cbe04b):
Fri May 27 11:48:22 SAST 2011: HTTP SENT(86cbe04b): <iq xmlns=“jabber:client” type=“result” id=“O2LU” from="42@java.vs.sr.dbuzz
.net" to="42@host.chatserver.net/ijab34CF3">
Fri May 27 11:48:22 SAST 2011: HTTP RECV(86cbe04b):
Fri May 27 11:48:22 SAST 2011: HTTP SENT(86cbe04b): <iq xmlns=“jabber:client” type=“result” id=“aouC” to="42@host.chatserver.n
et/ijab34CF3">
Fri May 27 11:48:22 SAST 2011: HTTP RECV(86cbe04b):
After which the pause comes through:
Fri May 27 11:48:28 SAST 2011: HTTP RECV(86cbe04b):
Fri May 27 11:48:28 SAST 2011: HTTP SENT(86cbe04b):
Fri May 27 11:48:28 SAST 2011: HTTP SENT(86cbe04b):
I then get the following in the warn.log:
2011.05.27 11:48:30 Deliverable unavailable for 8338027
And at the same time the following debug:
Fri May 27 11:48:30 SAST 2011: HTTP RECV(86cbe04b):
Fri May 27 11:48:30 SAST 2011: HTTP ERR(86cbe04b): terminate, item-not-found.
Fri May 27 11:48:30 SAST 2011: HTTP SENT(86cbe04b):
Afterwhich it just goes ahead and establishes a new connection, since it can’t resume the old one correctly.
I’m not sure I understand what is going on here properly. Is anyone able to shed some light as to what is going on?
Thanks
G