Incorrect CSeq value in 200 OK response to NOTIFY causing NOTIFY retransmissions to server
203 views
Skip to first unread message
michael
Oct 14, 2008, 11:49:21 AM10/14/08
to mobicent...@googlegroups.com
Hi
I'm getting a problem where the 200 OK response to an incoming NOTIFY
occasionally has the incorrect CSeq value. The scenario has a sequence
of NOTIFY -> 200 OK messages, and the problem arises when the 200 OK
response to a NOTIFY takes the CSeq value of the PREVIOUS NOTIFY
request, rather than the NOTIFY it is responding to. This seems to cause
retransmissions of the NOTIFY, and hence the (incorrect) 200 OK, until
the NOTIFY retransmissions time out, and treat the transaction/dialog as
dead because of no acknowledgement, or the correct 200 OK eventually
gets sent in response.
I don't know what triggers the 200 OK with the right CSeq to be sent
after a series of 200 OKs with the incorrect CSeq, but it does happen
sometimes. More importantly, I can't find a cause for the incorrect CSeq
to be used by the 200 OK.
I'm getting a problem where the 200 OK response to an incoming NOTIFY
occasionally has the incorrect CSeq value. The scenario has a sequence
of NOTIFY -> 200 OK messages, and the problem arises when the 200 OK
response to a NOTIFY takes the CSeq value of the PREVIOUS NOTIFY
request, rather than the NOTIFY it is responding to. This seems to cause
retransmissions of the NOTIFY, and hence the (incorrect) 200 OK, until
the NOTIFY retransmissions time out, and treat the transaction/dialog as
dead because of no acknowledgement, or the correct 200 OK eventually
gets sent in response.
I don't know what triggers the 200 OK with the right CSeq to be sent
after a series of 200 OKs with the incorrect CSeq, but it does happen
sometimes. More importantly, I can't find a cause for the incorrect CSeq
to be used by the 200 OK.
I've managed to track the problem in the attached log file, but outlined
are the main points/events I've managed to identify. I don't know the
significance of all the logging, but I've included what I gather are
relatively important events. There are 5 SipSessions open in the test,
and I follow one (which exhibited the problem) with Call-ID:
7d90980d4ec0b793...@192.168.5.1. The time stamps are
included to make them easy to find:
15:32:00,076 Incoming NOTIFY request is received (CSeq value of 3)
newSIPServerRequest
Returning request interface for NOTIFY
acquireSem() returning: true
processRequest: NOTIFY
tx state = null
15:32:00,115 Done processing Message NOTIFY
15:32:00,121 Dispatching request NOTIFY to SignalServlet
15:32:00,123 Sending response 200 OK (with CSeq 3)
There's random occurrence of a message with the Call-ID at 15:32:11,830
then the problem occurs:
15:32:24,296 Incoming NOTIFY request is received (CSeq value of 4)
newSIPServerRequest
Returning request interface for NOTIFY
acquireSem() returning: true
processRequest: NOTIFY
tx state = Completed Transaction
15:32:24,324 sendMessage 200 OK (with CSeq 3 - it should be CSeq 4)
Then, at the very end of the log file (I stopped the test when I saw the
retransmissions starting, otherwise the log file gets huge) the
retransmitted NOTIFY gets routed to the servlet, and the correct 200 OK
response to the NOTIFY request gets sent at 15:32:33,185.
I guess that changes the problem to one of why the incoming NOTIFY
requests aren't getting routed to the servlet, and being handled in the
container instead? My biggest problem is that if the correct 200 OK (ie
correct CSeq value) doesn't eventually get sent, the retransmission
times out, and my test pool shrinks, which is problematic for my tests.
Is it something I'm doing? I don't think so, because of the apparent
randomness of the occurrence.
Thanks in advance!
mike
Jean Deruelle
Oct 15, 2008, 8:34:29 AM10/15/08
to mobicent...@googlegroups.com
Your NOTIFY requests don't contain the Event header. That is wrong, not sure if this is related but you want to fix it and retry.
I need to check also but maybe the container should generate an error response if the NOTIFY doesn't contain an Event header matching the SUBSCRIBE one...
Also I suspect your problem stems from the fact that the branch id is the same in all your incoming NOTIFY requests (I suspect it is a sipp script issue), it should be different as per RFC 3261, Section 8.1.1.7 Via
See extracted requests below
2008-10-14 15:32:00,076
NOTIFY sip:192.168.5.1:5080 SIP/2.0
Call-ID: 7d90980d4ec0b793...@192.168.5.1
CSeq: 3 NOTIFY
From: <sip:A...@127.0.0.1:5073>;tag=1
To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
Via: SIP/2.0/UDP 127.0.1.1:5073;branch=z9hG4bK-9831-1-7
Contact: <sip:127.0.1.1:5073;transport=UDP>
Max-Forwards: 70
Expires: 18000
Subscription-State: active
Content-Type: text/plain
Content-Length: 315
2008-10-14 15:32:24,296
NOTIFY sip:192.168.5.1:5080 SIP/2.0
Call-ID: 7d90980d4ec0b793...@192.168.5.1
CSeq: 4 NOTIFY
From: <sip:A...@127.0.0.1:5073>;tag=1
To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
Via: SIP/2.0/UDP 127.0.1.1:5073;branch=z9hG4bK-9831-1-7
Contact: <sip:127.0.1.1:5073;transport=UDP>
Max-Forwards: 70
Expires: 18000
Subscription-State: active
Content-Type: text/plain
Content-Length: 315
Which version are you using ?
Jean
I need to check also but maybe the container should generate an error response if the NOTIFY doesn't contain an Event header matching the SUBSCRIBE one...
Also I suspect your problem stems from the fact that the branch id is the same in all your incoming NOTIFY requests (I suspect it is a sipp script issue), it should be different as per RFC 3261, Section 8.1.1.7 Via
See extracted requests below
2008-10-14 15:32:00,076
NOTIFY sip:192.168.5.1:5080 SIP/2.0
Call-ID: 7d90980d4ec0b793...@192.168.5.1
CSeq: 3 NOTIFY
From: <sip:A...@127.0.0.1:5073>;tag=1
To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
Via: SIP/2.0/UDP 127.0.1.1:5073;branch=z9hG4bK-9831-1-7
Contact: <sip:127.0.1.1:5073;transport=UDP>
Max-Forwards: 70
Expires: 18000
Subscription-State: active
Content-Type: text/plain
Content-Length: 315
2008-10-14 15:32:24,296
NOTIFY sip:192.168.5.1:5080 SIP/2.0
Call-ID: 7d90980d4ec0b793...@192.168.5.1
CSeq: 4 NOTIFY
From: <sip:A...@127.0.0.1:5073>;tag=1
To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
Via: SIP/2.0/UDP 127.0.1.1:5073;branch=z9hG4bK-9831-1-7
Contact: <sip:127.0.1.1:5073;transport=UDP>
Max-Forwards: 70
Expires: 18000
Subscription-State: active
Content-Type: text/plain
Content-Length: 315
Which version are you using ?
Jean
2008/10/14 3:31:04 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/lib/jvm/java-1.5.0-sun-1.5.0.13/jre/lib/i386/client:/usr/lib/jvm/java-1.5.0-sun-1.5.0.13/jre/lib/i386:/usr/lib/jvm/java-1.5.0-sun-1.5.0.13/jre/../lib/i386
2008/10/14 3:31:04 PM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
2008-10-14 15:31:04,754 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.init(SipApplicationDispatcherImpl.java:255) - Using the Service Provider Framework to load the application router provider
2008-10-14 15:31:04,773 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.init(SipApplicationDispatcherImpl.java:268) - Using the following Application Router : org.mobicents.servlet.sip.router.DefaultApplicationRouter
2008-10-14 15:31:04,792 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.init(SipApplicationDispatcherImpl.java:279) - Sip Application dispatcher registered under following name Catalina:type=SipApplicationDispatcher
2008/10/14 3:31:04 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 1852 ms
2008/10/14 3:31:04 PM org.apache.catalina.core.StandardService start
INFO: Starting service Sip-Servlets
2008/10/14 3:31:05 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.14
2008/10/14 3:31:05 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive signal-servlet.war
2008-10-14 15:31:05,187 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:202) - Starting the sip context
2008-10-14 15:31:05,233 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:135) - Initializing the sip context
2008-10-14 15:31:05,765 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:153) - sip context Initialized
2008-10-14 15:31:06,980 INFO main za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:72) - The chat room sip servlet has been started !
2008-10-14 15:31:06,987 INFO main za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:81) - Sip Factory ref from JNDI : org.mobicents.servlet.sip.message.SipFactoryFacade@766a24
2008-10-14 15:31:06,988 INFO main za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:87) - serverAddress is : sip:sig...@127.0.0.1:5080
2008-10-14 15:31:07,060 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:405) - the following sip servlet application has been added : SignalServlet
2008-10-14 15:31:07,062 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:408) - It contains the following Sip Servlets :
2008-10-14 15:31:07,064 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:410) - SipApplicationName : SignalServlet/ServletName : SignalServlet
2008-10-14 15:31:07,064 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:312) - sip context started
2008/10/14 3:31:07 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive sip-servlets-management.war
2008-10-14 15:31:07,069 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:202) - Starting the sip context
2008-10-14 15:31:07,070 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:135) - Initializing the sip context
2008-10-14 15:31:07,076 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:153) - sip context Initialized
2008-10-14 15:31:09,668 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:405) - the following sip servlet application has been added : DummyServlet
2008-10-14 15:31:09,669 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:408) - It contains the following Sip Servlets :
2008-10-14 15:31:09,672 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:410) - SipApplicationName : DummyServlet/ServletName : SimpleSipServlet
2008-10-14 15:31:09,673 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:312) - sip context started
2008/10/14 3:31:10 PM org.apache.catalina.core.ApplicationContext log
INFO: ContextListener: contextInitialized()
2008/10/14 3:31:10 PM org.apache.catalina.core.ApplicationContext log
INFO: SessionListener: contextInitialized()
2008/10/14 3:31:10 PM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
2008/10/14 3:31:11 PM org.apache.jk.common.ChannelSocket init
INFO: Port busy 8009 java.net.BindException: Address already in use
2008/10/14 3:31:11 PM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8010
2008/10/14 3:31:11 PM org.apache.jk.server.JkMain start
INFO: Jk running ID=1 time=0/138 config=null
2008-10-14 15:31:11,299 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:263) [Here are the stack configuration properties
{gov.nist.javax.sip.TRACE_LEVEL=DEBUG, javax.sip.AUTOMATIC_DIALOG_SUPPORT=off, javax.sip.STACK_NAME=SIP-Servlet-Tomcat-Server, gov.nist.javax.sip.DELIVER_UNSOLICITED_NOTIFY=true, gov.nist.javax.sip.SERVER_LOG=/home/mike/mss-0.6-apache-tomcat-6.0.14//logs/serverlog.txt, gov.nist.javax.sip.LOG_MESSAGE_CONTENT=true, gov.nist.javax.sip.DEBUG_LOG=/home/mike/mss-0.6-apache-tomcat-6.0.14//logs/debuglog.txt}
]
2008-10-14 15:31:11,301 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:266) [ ]]>]
2008-10-14 15:31:11,308 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:267) [</debug>]
2008-10-14 15:31:11,309 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:268) [<description
logDescription="SIP-Servlet-Tomcat-Server"
name="null" />
]
2008-10-14 15:31:11,310 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:274) [<debug>]
2008-10-14 15:31:11,311 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:275) [<![CDATA[ ]
2008-10-14 15:31:11,335 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:743) [createListeningPoint : address = 192.168.5.1 port = 5080 transport = udp]
2008-10-14 15:31:11,619 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:780) [Created Message Processor: 192.168.5.1 port = 5080 transport = udp]
2008-10-14 15:31:11,622 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@1fe8ce8 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@d4d66b]
2008-10-14 15:31:11,624 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:811) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@d4d66b]
2008-10-14 15:31:11,637 INFO main org.mobicents.servlet.sip.startup.SipProtocolHandler.start(SipProtocolHandler.java:376) - Sip Connector started on ip address : 192.168.5.1,port 5080, useStun false, stunAddress null, stunPort : 0
2008-10-14 15:31:11,665 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:205) [add SipListener org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl@d6b059]
2008/10/14 3:31:11 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 6930 ms
2008-10-14 15:31:12,863 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:287) [UDPMessageChannel: peerAddress = 192.168.5.1/5060]
2008-10-14 15:31:12,865 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:291) [Length = 758]
2008-10-14 15:31:12,866 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:293) [MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0
From: mike <sip:mi...@127.0.1.1:5060>;tag=1
To: SubscribeTester <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: sip:mi...@127.0.1.1:5060
Max-Forwards: 70
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 382
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry aggregationMethodIndicator="quantity" />
<entry maxPresenceSize="12000" />
<entry maxPresentitiesReceived="5" />
<entry threadDelay="10000" />
<entry threadPeriod="5000" />
</list>
</resource-lists>]
2008-10-14 15:31:13,259 INFO Thread-10 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5060"
to="192.168.5.1:5080"
time="1223991072875"
isSender="false"
transactionId="z9hg4bk-9827-1-0"
callId="1-9...@127.0.1.1"
firstLine="MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0"
>
<![CDATA[MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 382
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry aggregationMethodIndicator="quantity" />
<entry maxPresenceSize="12000" />
<entry maxPresentitiesReceived="5" />
<entry threadDelay="10000" />
<entry threadPeriod="5000" />
</list>
</resource-lists>]]>
</message>
2008-10-14 15:31:13,261 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:907) [looking for pending tx for :z9hg4bk-9827-1-0]
2008-10-14 15:31:13,276 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:499) [Creating Server Transactionnull]
2008-10-14 15:31:13,277 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPServerTransaction.java:501][SIPTransactionStack.java:1270][SIPTransactionStack.java:1068][UDPMessageChannel.java:444][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:13,282 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK-9827-1-0]
2008-10-14 15:31:13,283 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1083) [newSIPServerRequest( MESSAGE:z9hG4bK-9827-1-0):gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,291 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
gov.nist.javax.sip.DialogFilter@126d3df messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,292 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1141) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,293 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1142][SIPTransactionStack.java:1093][UDPMessageChannel.java:444][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:13,295 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true]
2008-10-14 15:31:13,295 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processMessage(UDPMessageChannel.java:473) [About to process MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
/gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,296 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:720) [processRequest: MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:13,297 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:722) [tx state = null]
2008-10-14 15:31:13,298 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK-9827-1-0]
2008-10-14 15:31:13,300 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79 branchID = z9hG4bK-9827-1-0 isClient = false]
2008-10-14 15:31:13,303 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPServerTransaction.java:1513][SIPServerTransaction.java:732][UDPMessageChannel.java:476][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:13,305 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()]
2008-10-14 15:31:13,309 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:111) [PROCESSING INCOMING REQUEST MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 382
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry aggregationMethodIndicator="quantity" />
<entry maxPresenceSize="12000" />
<entry maxPresentitiesReceived="5" />
<entry threadDelay="10000" />
<entry threadPeriod="5000" />
</list>
</resource-lists> transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79 listening point = 192.168.5.1:5080]
2008-10-14 15:31:13,312 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:139) [transaction state = Trying Transaction]
2008-10-14 15:31:13,313 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-9...@127.0.1.1:1) : returning null]
2008-10-14 15:31:13,314 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:209) [dialogId = 1-9...@127.0.1.1:1]
2008-10-14 15:31:13,315 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:210) [dialog = null]
2008-10-14 15:31:13,316 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:665) [CHECK FOR OUT OF SEQ MESSAGE null transaction gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,317 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:722) [MESSAGE transaction.isMapped = false]
2008-10-14 15:31:13,318 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:135) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@2016b0]currentTransaction = gov.nist.javax.sip.sta...@7a3d79this.sipListener = org.mobicents.servlet.sip.cor...@d6b059sipEvent.source = gov.nist.javax.sip.SipProviderImpl@2016b0]
2008-10-14 15:31:13,319 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:142) [Dialog = null]
2008-10-14 15:31:13,319 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SipProviderImpl.java:147][DialogFilter.java:917][SIPServerTransaction.java:830][UDPMessageChannel.java:476][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:13,323 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@c00025]
2008-10-14 15:31:13,324 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@c00025nevents 1]
2008-10-14 15:31:13,329 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@2016b0]source = gov.nist.javax.sip.SipProviderImpl@2016b0]
2008-10-14 15:31:13,330 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
transaction gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79 sipEvent.serverTx = null]
2008-10-14 15:31:13,331 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:797) [serverTx: looking for key z9hg4bk-9827-1-0 existing={}]
2008-10-14 15:31:13,332 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:907) [looking for pending tx for :z9hg4bk-9827-1-0]
2008-10-14 15:31:13,334 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1551) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,334 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:13,335 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,336 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:449) - Got a request event MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 382
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry aggregationMethodIndicator="quantity" />
<entry maxPresenceSize="12000" />
<entry maxPresentitiesReceived="5" />
<entry threadDelay="10000" />
<entry threadPeriod="5000" />
</list>
</resource-lists>
2008-10-14 15:31:13,337 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : MESSAGE returning false]
2008-10-14 15:31:13,338 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:797) [serverTx: looking for key z9hg4bk-9827-1-0 existing={}]
2008-10-14 15:31:13,338 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1423) [ putTransactionHash : key = z9hg4bk-9827-1-0]
2008-10-14 15:31:13,339 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-9...@127.0.1.1:1) : returning null]
2008-10-14 15:31:13,340 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:469) - ServerTx ref gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79
2008-10-14 15:31:13,340 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:470) - Dialog ref null
2008-10-14 15:31:13,370 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:524) - Routing State INITIAL
2008-10-14 15:31:13,376 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:13,377 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:13,377 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,378 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1733][EventScanner.java:254][EventScanner.java:492][Thread.java:595]]
2008-10-14 15:31:13,379 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:946) [removePendingTx: z9hg4bk-9827-1-0]
2008-10-14 15:31:13,403 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchMessage(InitialRequestDispatcher.java:97) - Routing of Initial Request MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 382
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry aggregationMethodIndicator="quantity" />
<entry maxPresenceSize="12000" />
<entry maxPresentitiesReceived="5" />
<entry threadDelay="10000" />
<entry threadPeriod="5000" />
</list>
</resource-lists>
2008-10-14 15:31:13,404 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchMessage(InitialRequestDispatcher.java:103) - popped route : null
2008-10-14 15:31:13,410 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchInsideContainer(InitialRequestDispatcher.java:197) - Dispatching the request event to SignalServlet
2008-10-14 15:31:13,422 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,423 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1733][UDPMessageChannel.java:481][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:13,424 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processMessage(UDPMessageChannel.java:486) [Done processing MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
/gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79]
2008-10-14 15:31:13,428 INFO pool-1-thread-1 za.ac.uct.ee.crg.domain.SessionExpiryEventListener.sessionCreated(SessionExpiryEventListener.java:23) - Session created: org.mobicents.servlet.sip.core.session.SipApplicationSessionImpl@c6eff5
2008-10-14 15:31:13,441 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.dispatchers.MessageDispatcher.callServlet(MessageDispatcher.java:168) - Dispatching request MESSAGE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 382
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry aggregationMethodIndicator="quantity" />
<entry maxPresenceSize="12000" />
<entry maxPresentitiesReceived="5" />
<entry threadDelay="10000" />
<entry threadPeriod="5000" />
</list>
</resource-lists> to following App/servlet => SignalServlet/SignalServlet
2008-10-14 15:31:13,458 INFO pool-1-thread-1 za.ac.uct.ee.crg.domain.SubscriberMap.clearMap(SubscriberMap.java:50) - SubscriberMap is cleared
2008-10-14 15:31:13,459 INFO pool-1-thread-1 za.ac.uct.ee.crg.domain.PresentityMap.clearMap(PresentityMap.java:47) - PresentityMap is cleared
2008-10-14 15:31:13,838 INFO pool-1-thread-1 za.ac.uct.ee.crg.sipservlet.SignalServlet.doMessage(SignalServlet.java:146) - Aggregation Method Indicator: quantity
2008-10-14 15:31:13,839 INFO pool-1-thread-1 za.ac.uct.ee.crg.sipservlet.SignalServlet.doMessage(SignalServlet.java:151) - Max Presence Size: 12000
2008-10-14 15:31:13,839 INFO pool-1-thread-1 za.ac.uct.ee.crg.sipservlet.SignalServlet.doMessage(SignalServlet.java:156) - Max presentities received: 5
2008-10-14 15:31:13,840 INFO pool-1-thread-1 za.ac.uct.ee.crg.sipservlet.SignalServlet.doMessage(SignalServlet.java:161) - Thread Delay: 10000
2008-10-14 15:31:13,840 INFO pool-1-thread-1 za.ac.uct.ee.crg.sipservlet.SignalServlet.doMessage(SignalServlet.java:166) - Thread period: 5000
2008-10-14 15:31:13,861 INFO pool-1-thread-1 org.mobicents.servlet.sip.message.SipServletResponseImpl.send(SipServletResponseImpl.java:381) - sending response SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3431863
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:192.168.5.1:5080;transport=udp>
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
2008-10-14 15:31:13,862 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79 branchID = z9hG4bK-9827-1-0 isClient = false]
2008-10-14 15:31:13,876 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPServerTransaction.java:1513][SIPServerTransaction.java:948][SIPServerTransaction.java:1459][SipServletResponseImpl.java:423][MessageOut.java:27][SignalServlet.java:175][SipServlet.java:241][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:13,878 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:606) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79 tickCount 64 currentTickCount = -1]
2008-10-14 15:31:13,879 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1113) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79 getState = Completed Transaction]
2008-10-14 15:31:13,880 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:196) [Creating message channel 192.168.5.1/5060]
2008-10-14 15:31:13,881 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[UDPMessageChannel.java:595][SIPServerTransaction.java:466][SIPServerTransaction.java:1118][SIPServerTransaction.java:1459][SipServletResponseImpl.java:423][MessageOut.java:27][SignalServlet.java:175][SipServlet.java:241][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:13,899 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:728) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.5.1/5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3431863
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:192.168.5.1:5080;transport=udp>
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]
2008-10-14 15:31:13,900 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:731) [*******************
]
2008-10-14 15:31:13,901 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:748) [sendMessage 192.168.5.1/5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3431863
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:192.168.5.1:5080;transport=udp>
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]
2008-10-14 15:31:13,974 INFO pool-1-thread-1 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5080"
to="192.168.5.1:5060"
time="1223991073898"
isSender="true"
transactionId="z9hg4bk-9827-1-0"
callId="1-9...@127.0.1.1"
firstLine="SIP/2.0 200 OK"
>
<![CDATA[SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9827-1-0;received=192.168.5.1
From: "mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3431863
Call-ID: 1-9...@127.0.1.1
CSeq: 1 MESSAGE
Contact: <sip:192.168.5.1:5080;transport=udp>
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]]>
</message>
2008-10-14 15:31:13,977 DEBUG pool-1-thread-1 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:335) [TransactionTimer() : z9hg4bk-9827-1-0]
2008-10-14 15:31:13,979 INFO pool-1-thread-1 za.ac.uct.ee.crg.domain.MessageOut.sendResponse(MessageOut.java:28) - 200 OK for changing parameters
2008-10-14 15:31:13,981 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.session.SipApplicationSessionImpl.invalidate(SipApplicationSessionImpl.java:450) - Invalidating the following sip application session (1-9...@127.0.1.1,SignalServlet)
2008-10-14 15:31:13,982 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.session.SipSessionImpl.invalidate(SipSessionImpl.java:570) - Invalidating the sip session (sip:mi...@127.0.1.1:5060,1,sip:subs...@127.0.0.1:5080,1-9...@127.0.1.1,SignalServlet)
2008-10-14 15:31:13,983 INFO pool-1-thread-1 za.ac.uct.ee.crg.domain.SessionExpiryEventListener.sessionDestroyed(SessionExpiryEventListener.java:27) - The session has been destroyed!
2008-10-14 15:31:13,984 INFO pool-1-thread-1 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchInsideContainer(InitialRequestDispatcher.java:277) - Request event dispatched to SignalServlet
2008-10-14 15:31:38,377 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:287) [UDPMessageChannel: peerAddress = 192.168.5.1/5060]
2008-10-14 15:31:38,377 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:291) [Length = 780]
2008-10-14 15:31:38,387 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:293) [SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0
From: Subs1 <sip:su...@127.0.1.1:5060>;tag=1
To: SubscribeTester <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: sip:mi...@127.0.1.1:5060
Max-Forwards: 70
Expires: 60
Event: presence
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 368
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry uri="sip:A...@127.0.0.1:5071" />
<entry uri="sip:A...@127.0.0.1:5072" />
<entry uri="sip:A...@127.0.0.1:5073" />
<entry uri="sip:A...@127.0.0.1:5074" />
</list>
</resource-lists>]
2008-10-14 15:31:38,411 INFO Thread-11 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5060"
to="192.168.5.1:5080"
time="1223991098388"
isSender="false"
transactionId="z9hg4bk-9836-1-0"
callId="1-9...@127.0.1.1"
firstLine="SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0"
>
<![CDATA[SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 60
Event: presence
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 368
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry uri="sip:A...@127.0.0.1:5071" />
<entry uri="sip:A...@127.0.0.1:5072" />
<entry uri="sip:A...@127.0.0.1:5073" />
<entry uri="sip:A...@127.0.0.1:5074" />
</list>
</resource-lists>]]>
</message>
2008-10-14 15:31:38,412 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:907) [looking for pending tx for :z9hg4bk-9836-1-0]
2008-10-14 15:31:38,412 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:499) [Creating Server Transactionnull]
2008-10-14 15:31:38,413 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPServerTransaction.java:501][SIPTransactionStack.java:1270][SIPTransactionStack.java:1068][UDPMessageChannel.java:444][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,414 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK-9836-1-0]
2008-10-14 15:31:38,415 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1083) [newSIPServerRequest( SUBSCRIBE:z9hG4bK-9836-1-0):gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,416 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
gov.nist.javax.sip.DialogFilter@272961 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,417 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1141) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,421 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1142][SIPTransactionStack.java:1093][UDPMessageChannel.java:444][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,423 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true]
2008-10-14 15:31:38,423 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processMessage(UDPMessageChannel.java:473) [About to process SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
/gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,424 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:720) [processRequest: SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:38,425 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:722) [tx state = null]
2008-10-14 15:31:38,429 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK-9836-1-0]
2008-10-14 15:31:38,430 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 branchID = z9hG4bK-9836-1-0 isClient = false]
2008-10-14 15:31:38,431 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPServerTransaction.java:1513][SIPServerTransaction.java:732][UDPMessageChannel.java:476][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,431 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()]
2008-10-14 15:31:38,433 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:111) [PROCESSING INCOMING REQUEST SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 60
Event: presence
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 368
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry uri="sip:A...@127.0.0.1:5071" />
<entry uri="sip:A...@127.0.0.1:5072" />
<entry uri="sip:A...@127.0.0.1:5073" />
<entry uri="sip:A...@127.0.0.1:5074" />
</list>
</resource-lists> transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 listening point = 192.168.5.1:5080]
2008-10-14 15:31:38,433 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:139) [transaction state = Trying Transaction]
2008-10-14 15:31:38,434 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-9...@127.0.1.1:1) : returning null]
2008-10-14 15:31:38,436 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:209) [dialogId = 1-9...@127.0.1.1:1]
2008-10-14 15:31:38,440 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:210) [dialog = null]
2008-10-14 15:31:38,441 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:665) [CHECK FOR OUT OF SEQ MESSAGE null transaction gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,441 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:722) [SUBSCRIBE transaction.isMapped = false]
2008-10-14 15:31:38,442 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:135) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@2016b0]currentTransaction = gov.nist.javax.sip.sta...@220fe97this.sipListener = org.mobicents.servlet.sip.cor...@d6b059sipEvent.source = gov.nist.javax.sip.SipProviderImpl@2016b0]
2008-10-14 15:31:38,444 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:142) [Dialog = null]
2008-10-14 15:31:38,445 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SipProviderImpl.java:147][DialogFilter.java:917][SIPServerTransaction.java:830][UDPMessageChannel.java:476][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,446 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@10dc656]
2008-10-14 15:31:38,446 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@10dc656nevents 1]
2008-10-14 15:31:38,447 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@2016b0]source = gov.nist.javax.sip.SipProviderImpl@2016b0]
2008-10-14 15:31:38,447 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
transaction gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 sipEvent.serverTx = null]
2008-10-14 15:31:38,448 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:797) [serverTx: looking for key z9hg4bk-9836-1-0 existing={z9hg4bk-9827-1-0=gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79}]
2008-10-14 15:31:38,449 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:907) [looking for pending tx for :z9hg4bk-9836-1-0]
2008-10-14 15:31:38,449 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1551) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,451 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:38,451 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,454 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:449) - Got a request event SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 60
Event: presence
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 368
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry uri="sip:A...@127.0.0.1:5071" />
<entry uri="sip:A...@127.0.0.1:5072" />
<entry uri="sip:A...@127.0.0.1:5073" />
<entry uri="sip:A...@127.0.0.1:5074" />
</list>
</resource-lists>
2008-10-14 15:31:38,455 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : SUBSCRIBE returning true]
2008-10-14 15:31:38,456 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:797) [serverTx: looking for key z9hg4bk-9836-1-0 existing={z9hg4bk-9827-1-0=gov.nist.javax.sip.stack.SIPServerTransaction@7a3d79}]
2008-10-14 15:31:38,456 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1381) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,457 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:946) [removePendingTx: z9hg4bk-9836-1-0]
2008-10-14 15:31:38,458 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1423) [ putTransactionHash : key = z9hg4bk-9836-1-0]
2008-10-14 15:31:38,458 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:469) - ServerTx ref gov.nist.javax.sip.stack.SIPServerTransaction@220fe97
2008-10-14 15:31:38,459 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:470) - Dialog ref null
2008-10-14 15:31:38,460 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:524) - Routing State INITIAL
2008-10-14 15:31:38,460 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:38,461 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
]
2008-10-14 15:31:38,461 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,481 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1733][EventScanner.java:254][EventScanner.java:492][Thread.java:595]]
2008-10-14 15:31:38,482 INFO pool-1-thread-2 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchMessage(InitialRequestDispatcher.java:97) - Routing of Initial Request SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 60
Event: presence
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 368
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry uri="sip:A...@127.0.0.1:5071" />
<entry uri="sip:A...@127.0.0.1:5072" />
<entry uri="sip:A...@127.0.0.1:5073" />
<entry uri="sip:A...@127.0.0.1:5074" />
</list>
</resource-lists>
2008-10-14 15:31:38,483 INFO pool-1-thread-2 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchMessage(InitialRequestDispatcher.java:103) - popped route : null
2008-10-14 15:31:38,487 INFO pool-1-thread-2 org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchInsideContainer(InitialRequestDispatcher.java:197) - Dispatching the request event to SignalServlet
2008-10-14 15:31:38,488 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.SessionExpiryEventListener.sessionCreated(SessionExpiryEventListener.java:23) - Session created: org.mobicents.servlet.sip.core.session.SipApplicationSessionImpl@e0e515
2008-10-14 15:31:38,489 INFO pool-1-thread-2 org.mobicents.servlet.sip.core.dispatchers.MessageDispatcher.callServlet(MessageDispatcher.java:168) - Dispatching request SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 60
Event: presence
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 368
<?xml version="1.0" encoding="UTF-8"?>
<resource-lists xmlns="urn:ietf:params:xml:ns:resource-lists"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<list>
<entry uri="sip:A...@127.0.0.1:5071" />
<entry uri="sip:A...@127.0.0.1:5072" />
<entry uri="sip:A...@127.0.0.1:5073" />
<entry uri="sip:A...@127.0.0.1:5074" />
</list>
</resource-lists> to following App/servlet => SignalServlet/SignalServlet
2008-10-14 15:31:38,482 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:946) [removePendingTx: z9hg4bk-9836-1-0]
2008-10-14 15:31:38,499 INFO pool-1-thread-2 org.mobicents.servlet.sip.message.SipServletResponseImpl.send(SipServletResponseImpl.java:381) - sending response SIP/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
2008-10-14 15:31:38,500 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Proceeding Transaction gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 branchID = z9hG4bK-9836-1-0 isClient = false]
2008-10-14 15:31:38,506 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPServerTransaction.java:1513][SIPServerTransaction.java:935][SIPServerTransaction.java:1459][SipServletResponseImpl.java:423][MessageOut.java:27][SignalServlet.java:200][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,507 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1113) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 getState = Proceeding Transaction]
2008-10-14 15:31:38,511 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:196) [Creating message channel 192.168.5.1/5060]
2008-10-14 15:31:38,512 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[UDPMessageChannel.java:595][SIPServerTransaction.java:466][SIPServerTransaction.java:1118][SIPServerTransaction.java:1459][SipServletResponseImpl.java:423][MessageOut.java:27][SignalServlet.java:200][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,520 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:728) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.5.1/5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]
2008-10-14 15:31:38,521 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:731) [*******************
]
2008-10-14 15:31:38,522 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:748) [sendMessage 192.168.5.1/5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]
2008-10-14 15:31:38,524 INFO pool-1-thread-2 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5080"
to="192.168.5.1:5060"
time="1223991098519"
isSender="true"
transactionId="z9hg4bk-9836-1-0"
callId="1-9...@127.0.1.1"
firstLine="SIP/2.0 100 Trying"
>
<![CDATA[SIP/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]]>
</message>
2008-10-14 15:31:38,526 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:335) [TransactionTimer() : z9hg4bk-9836-1-0]
2008-10-14 15:31:38,527 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.MessageOut.sendResponse(MessageOut.java:28) - Sending SIP 100 Trying for Initial SUBSCRIBE
2008-10-14 15:31:38,539 INFO pool-1-thread-2 za.ac.uct.ee.crg.sipservlet.SignalServlet.doSubscribe(SignalServlet.java:211) - getInvalidateWhenReady: true
2008-10-14 15:31:38,539 INFO pool-1-thread-2 za.ac.uct.ee.crg.sipservlet.SignalServlet.doSubscribe(SignalServlet.java:212) - Session start time is 1223991098487, extension time is 30 minute(s), SipApplicationSession expiry set to 1799999
2008-10-14 15:31:38,558 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.PresentityMap.returnPresentityToMap(PresentityMap.java:64) - presentity.getPresentityURI is sip:A...@127.0.0.1:5071
2008-10-14 15:31:38,560 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.PresentityMap.returnPresentityToMap(PresentityMap.java:64) - presentity.getPresentityURI is sip:A...@127.0.0.1:5072
2008-10-14 15:31:38,563 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.PresentityMap.returnPresentityToMap(PresentityMap.java:64) - presentity.getPresentityURI is sip:A...@127.0.0.1:5073
2008-10-14 15:31:38,565 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.PresentityMap.returnPresentityToMap(PresentityMap.java:64) - presentity.getPresentityURI is sip:A...@127.0.0.1:5074
2008-10-14 15:31:38,570 INFO pool-1-thread-2 org.mobicents.servlet.sip.message.SipServletResponseImpl.send(SipServletResponseImpl.java:381) - sending response SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 60
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
2008-10-14 15:31:38,571 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : SUBSCRIBE returning true]
2008-10-14 15:31:38,572 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-9...@127.0.1.1:1) : returning null]
2008-10-14 15:31:38,596 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:444) [settingRemoteParty "Subs1" <sip:su...@127.0.1.1:5060>]
2008-10-14 15:31:38,599 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1269) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@1dafbaf/1]
2008-10-14 15:31:38,602 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1173) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@1dafbafnull/1]
2008-10-14 15:31:38,603 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1175) [TID = z9hg4bk-9836-1-0/true]
2008-10-14 15:31:38,604 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1178][SIPDialog.java:328][SIPTransactionStack.java:566][SipProviderImpl.java:821][SipServletResponseImpl.java:398][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,605 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:330) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,606 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:331) [provider port = 5080]
2008-10-14 15:31:38,607 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:333][SIPTransactionStack.java:566][SipProviderImpl.java:821][SipServletResponseImpl.java:398][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,608 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1269) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@1dafbaf/1]
2008-10-14 15:31:38,610 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1173) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@1dafbafnull/1]
2008-10-14 15:31:38,611 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1175) [TID = z9hg4bk-9836-1-0/true]
2008-10-14 15:31:38,612 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1178][SipProviderImpl.java:823][SipServletResponseImpl.java:398][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,615 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:973) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@1dafbafstate = null]
2008-10-14 15:31:38,616 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1559) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 dialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,617 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : SUBSCRIBE returning true]
2008-10-14 15:31:38,618 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : SUBSCRIBE returning true]
2008-10-14 15:31:38,619 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2244) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@1dafbaf lastResponse = SIP/2.0 200 OK
]
2008-10-14 15:31:38,623 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2259][SIPServerTransaction.java:1429][SipServletResponseImpl.java:423][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,624 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2260) [cseqMethod = SUBSCRIBE]
2008-10-14 15:31:38,625 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2261) [dialogState = null]
2008-10-14 15:31:38,626 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2263) [method = SUBSCRIBE]
2008-10-14 15:31:38,627 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2264) [statusCode = 200]
2008-10-14 15:31:38,629 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2265) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,630 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : SUBSCRIBE returning true]
2008-10-14 15:31:38,631 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLocalTag(SIPDialog.java:1363) [set Local tag 7423943 null]
2008-10-14 15:31:38,634 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1365][SIPDialog.java:2405][SIPServerTransaction.java:1429][SipServletResponseImpl.java:423][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,635 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:872) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@1dafbafnewState = 1]
2008-10-14 15:31:38,636 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:874][SIPDialog.java:2454][SIPServerTransaction.java:1429][SipServletResponseImpl.java:423][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,637 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:877) [gov.nist.javax.sip.stack.SIPDialog@1dafbaf old dialog state is null]
2008-10-14 15:31:38,637 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:879) [gov.nist.javax.sip.stack.SIPDialog@1dafbaf New dialog state is Confirmed Dialog]
2008-10-14 15:31:38,639 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:530) [putDialog dialogId=1-9...@127.0.1.1:7423943:1 dialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,640 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransactionStack.java:535][SIPDialog.java:2459][SIPServerTransaction.java:1429][SipServletResponseImpl.java:423][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,642 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 branchID = z9hG4bK-9836-1-0 isClient = false]
2008-10-14 15:31:38,643 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPServerTransaction.java:1513][SIPServerTransaction.java:1089][SIPServerTransaction.java:1459][SipServletResponseImpl.java:423][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,644 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:606) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 tickCount 64 currentTickCount = -1]
2008-10-14 15:31:38,647 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1113) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@220fe97 getState = Completed Transaction]
2008-10-14 15:31:38,648 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:196) [Creating message channel 192.168.5.1/5060]
2008-10-14 15:31:38,649 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[UDPMessageChannel.java:595][SIPServerTransaction.java:466][SIPServerTransaction.java:1118][SIPServerTransaction.java:1459][SipServletResponseImpl.java:423][MessageOut.java:34][SignalServlet.java:248][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,650 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:728) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.5.1/5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 60
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]
2008-10-14 15:31:38,651 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:731) [*******************
]
2008-10-14 15:31:38,654 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:748) [sendMessage 192.168.5.1/5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 60
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]
2008-10-14 15:31:38,494 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,655 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1733][UDPMessageChannel.java:481][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,658 DEBUG Thread-11 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processMessage(UDPMessageChannel.java:486) [Done processing SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
/gov.nist.javax.sip.stack.SIPServerTransaction@220fe97]
2008-10-14 15:31:38,659 INFO pool-1-thread-2 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5080"
to="192.168.5.1:5060"
time="1223991098650"
isSender="true"
transactionId="z9hg4bk-9836-1-0"
callId="1-9...@127.0.1.1"
firstLine="SIP/2.0 200 OK"
>
<![CDATA[SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-9836-1-0;received=192.168.5.1
From: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
Call-ID: 1-9...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 60
Record-Route: <sip:192.168.5.1:5080;transport=udp;appname=SignalServlet;final_response=true;lr>
Content-Length: 0
]]>
</message>
2008-10-14 15:31:38,660 INFO pool-1-thread-2 za.ac.uct.ee.crg.domain.MessageOut.sendResponse(MessageOut.java:35) - Sending SIP 200 OK response
2008-10-14 15:31:38,666 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,667 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:624) [----- ]
2008-10-14 15:31:38,670 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:625) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,673 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:627) [RouteList = ]
2008-10-14 15:31:38,674 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:629) [myRouteList = ]
2008-10-14 15:31:38,675 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:631) [----- ]
2008-10-14 15:31:38,683 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:333) [could not find existing transaction for NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
creating a new one ]
2008-10-14 15:31:38,684 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:235) [Used request-URI for nextHop = 127.0.1.1:5060/udp]
2008-10-14 15:31:38,685 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-9...@127.0.1.1:7423943:1) : returning gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,688 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:196) [Creating message channel 127.0.1.1/5060]
2008-10-14 15:31:38,697 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:302) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff]
2008-10-14 15:31:38,698 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPClientTransaction.java:303][SIPTransactionStack.java:1253][SIPTransactionStack.java:1231][SipProviderImpl.java:379][SipServletRequestImpl.java:833][MessageOut.java:51][SignalServlet.java:250][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,705 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK78a66e61f36165f61928e9d7f66c68e9]
2008-10-14 15:31:38,706 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1417) [ putTransactionHash : key = z9hg4bk78a66e61f36165f61928e9d7f66c68e9]
2008-10-14 15:31:38,707 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK78a66e61f36165f61928e9d7f66c68e9]
2008-10-14 15:31:38,708 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-10-14 15:31:38,709 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1530) [setDialog: 1-9...@127.0.1.1:7423943:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,710 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1502) [ sipDialogs = {1-9...@127.0.1.1:7423943:1=gov.nist.javax.sip.stack.SIPDialog@1dafbaf} default dialog gov.nist.javax.sip.stack.SIPDialog@1dafbaf retval gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,711 INFO pool-1-thread-2 org.mobicents.servlet.sip.message.SipServletRequestImpl.send(SipServletRequestImpl.java:904) - Sending the in dialog request NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 1 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Expires: 60
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
Content-Length: 0
2008-10-14 15:31:38,712 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1655) [dialog.sendRequest dialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf
dialogRequest =
NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 1 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Expires: 60
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
Content-Length: 0
]
2008-10-14 15:31:38,713 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1530) [setDialog: 1-9...@127.0.1.1:7423943:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,714 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1173) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@1dafbaf7423943/1]
2008-10-14 15:31:38,719 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1175) [TID = z9hg4bk78a66e61f36165f61928e9d7f66c68e9/false]
2008-10-14 15:31:38,720 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1178][SIPDialog.java:1703][SipServletRequestImpl.java:906][MessageOut.java:51][SignalServlet.java:250][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,721 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1750) [Using hop = 127.0.1.1 : 5060]
2008-10-14 15:31:38,723 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:196) [Creating message channel 127.0.1.1/5060]
2008-10-14 15:31:38,725 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1839) [using message channel gov.nist.javax.sip.stack.UDPMessageChannel@104e28b]
2008-10-14 15:31:38,727 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [Sending Message NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 1 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Expires: 60
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
Content-Length: 0
]
2008-10-14 15:31:38,729 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:427) [TransactionState null]
2008-10-14 15:31:38,731 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK78a66e61f36165f61928e9d7f66c68e9]
2008-10-14 15:31:38,732 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e branchID = z9hG4bK78a66e61f36165f61928e9d7f66c68e9 isClient = true]
2008-10-14 15:31:38,735 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPClientTransaction.java:1317][SIPClientTransaction.java:472][SIPDialog.java:1874][SipServletRequestImpl.java:906][MessageOut.java:51][SignalServlet.java:250][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,736 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:606) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e tickCount 64 currentTickCount = -1]
2008-10-14 15:31:38,737 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[UDPMessageChannel.java:654][MessageChannel.java:233][SIPTransaction.java:738][SIPClientTransaction.java:486][SIPDialog.java:1874][SipServletRequestImpl.java:906][MessageOut.java:51][SignalServlet.java:250][SipServlet.java:237][SipServlet.java:325][MessageDispatcher.java:189][InitialRequestDispatcher.java:275][InitialRequestDispatcher.java:184][SipApplicationDispatcherImpl.java:168][ThreadPoolExecutor.java:650][ThreadPoolExecutor.java:675][Thread.java:595]]
2008-10-14 15:31:38,738 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:663) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.1.1/5060
NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 1 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Expires: 60
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
Content-Length: 0
]
2008-10-14 15:31:38,739 DEBUG pool-1-thread-2 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:666) [*******************
]
2008-10-14 15:31:38,742 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:287) [UDPMessageChannel: peerAddress = 192.168.5.1/5060]
2008-10-14 15:31:38,743 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:291) [Length = 343]
2008-10-14 15:31:38,744 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:293) [SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-10-14 15:31:38,748 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1141) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e]
2008-10-14 15:31:38,751 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1142][SIPTransactionStack.java:1171][UDPMessageChannel.java:507][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,751 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true]
2008-10-14 15:31:38,753 INFO Thread-12 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="127.0.1.1:5060"
to="192.168.5.1:5080"
time="1223991098752"
isSender="false"
transactionId="z9hg4bk78a66e61f36165f61928e9d7f66c68e9"
callId="1-9...@127.0.1.1"
firstLine="SIP/2.0 200 OK"
>
<![CDATA[SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]]>
</message>
2008-10-14 15:31:38,753 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:819) [clientTx: looking for key z9hg4bk78a66e61f36165f61928e9d7f66c68e9]
2008-10-14 15:31:38,754 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e for SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-10-14 15:31:38,755 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:317) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e to gov.nist.javax.sip.DialogFilter@ff9053]
2008-10-14 15:31:38,756 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2244) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@1dafbaf lastResponse = SIP/2.0 200 OK
]
2008-10-14 15:31:38,757 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2259][SIPClientTransaction.java:1477][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,757 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2260) [cseqMethod = NOTIFY]
2008-10-14 15:31:38,758 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2261) [dialogState = Confirmed Dialog]
2008-10-14 15:31:38,759 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2263) [method = SUBSCRIBE]
2008-10-14 15:31:38,761 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2264) [statusCode = 200]
2008-10-14 15:31:38,762 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2265) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e]
2008-10-14 15:31:38,766 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-10-14 15:31:38,767 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [processing SIP/2.0 200 OK
current state = Trying Transaction]
2008-10-14 15:31:38,768 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:531) [dialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,768 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:930) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-10-14 15:31:38,769 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:958) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e]
2008-10-14 15:31:38,770 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2244) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@1dafbaf lastResponse = SIP/2.0 200 OK
]
2008-10-14 15:31:38,771 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2259][DialogFilter.java:1031][SIPClientTransaction.java:643][SIPClientTransaction.java:551][SIPClientTransaction.java:1479][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,772 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2260) [cseqMethod = NOTIFY]
2008-10-14 15:31:38,772 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2261) [dialogState = Confirmed Dialog]
2008-10-14 15:31:38,773 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2263) [method = SUBSCRIBE]
2008-10-14 15:31:38,774 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2264) [statusCode = 200]
2008-10-14 15:31:38,774 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2265) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e]
2008-10-14 15:31:38,775 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-10-14 15:31:38,778 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1530) [setDialog: 1-9...@127.0.1.1:7423943:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,779 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:135) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@2016b0]currentTransaction = gov.nist.javax.sip.sta...@a10ae37ethis.sipListener = org.mobicents.servlet.sip.cor...@d6b059sipEvent.source = gov.nist.javax.sip.SipProviderImpl@2016b0]
2008-10-14 15:31:38,780 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:145) [Dialog = gov.nist.javax.sip.stack.SIPDialog@1dafbaf]
2008-10-14 15:31:38,780 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SipProviderImpl.java:147][DialogFilter.java:1035][SIPClientTransaction.java:643][SIPClientTransaction.java:551][SIPClientTransaction.java:1479][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-10-14 15:31:38,781 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@96212a]
2008-10-14 15:31:38,782 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@96212anevents 1]
2008-10-14 15:31:38,782 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@2016b0]source = gov.nist.javax.sip.SipProviderImpl@2016b0]
2008-10-14 15:31:38,783 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK
]
2008-10-14 15:31:38,783 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()]
2008-10-14 15:31:38,784 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processResponse(SipApplicationDispatcherImpl.java:545) - Response SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;branch=z9hG4bK78a66e61f36165f61928e9d7f66c68e9;appname=SignalServlet
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=7423943
To: "Subs1" <sip:su...@127.0.1.1:5060>;tag=1
Call-ID: 1-9...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
2008-10-14 15:31:38,787 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:546) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@a10ae37e branchID = z9hG4bK78a66e61f36165f61928e9d7f66c68e9 isClient = true]
2008-10-14 15:31:38,788 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPClientTransaction.java:1317][SIPClientTransaction.java:649][SIPClientTransaction.java:551][SIPClientTransaction.java:1479][UDPMessageChannel.java:521][UDPMessageChannel.java:41
narfice
Oct 15, 2008, 5:18:10 PM10/15/08
to mobicents-public
Hi Jean
I implemented the changes you suggested, with great results.
The Event: header was catered for in the sipp scenario [last_Event],
but was ignored because of the way I had structured the scenario. I've
used regex to extract it now, and inject it into the message, so I
know that it works.
I'm using sipp 3.1 (the sipp in the Ubuntu repositories doesn't
support regex) and use a loop to send the NOTIFY messages. I've
appended the [clock_tick] value to the branch id, which makes each
request unique. I'm not sure of the granularity of the clock_tick, but
if it's a second, it's enough for my needs.
The unique branch id seems to have solved the retransmission problem
entirely - I've been running my test for almost 30 minutes, without a
single retransmission. I'll try hit it with a much bigger test
tomorrow, but if it works now, it'll work tomorrow I'm sure.
So basically it's a massive thanks for all the help - I'm really sorry
so much of it has been my poor SIP syntax and formatting and
omissions. Thank you for the awesome product!
mike
On Oct 15, 2:34 pm, "Jean Deruelle" <jean.derue...@gmail.com> wrote:
> Your NOTIFY requests don't contain the Event header. That is wrong, not sure
> if this is related but you want to fix it and retry.
> I need to check also but maybe the container should generate an error
> response if the NOTIFY doesn't contain an Event header matching the
> SUBSCRIBE one...
> Also I suspect your problem stems from the fact that the branch id is the
> same in all your incoming NOTIFY requests (I suspect it is a sipp script
> issue), it should be different as per RFC 3261, Section 8.1.1.7 Via
>
> See extracted requests below
> 2008-10-14 15:32:00,076
> NOTIFY sip:192.168.5.1:5080 SIP/2.0
> Call-ID: 7d90980d4ec0b7937335921f7807d...@192.168.5.1
> ...
>
> read more »
I implemented the changes you suggested, with great results.
The Event: header was catered for in the sipp scenario [last_Event],
but was ignored because of the way I had structured the scenario. I've
used regex to extract it now, and inject it into the message, so I
know that it works.
I'm using sipp 3.1 (the sipp in the Ubuntu repositories doesn't
support regex) and use a loop to send the NOTIFY messages. I've
appended the [clock_tick] value to the branch id, which makes each
request unique. I'm not sure of the granularity of the clock_tick, but
if it's a second, it's enough for my needs.
The unique branch id seems to have solved the retransmission problem
entirely - I've been running my test for almost 30 minutes, without a
single retransmission. I'll try hit it with a much bigger test
tomorrow, but if it works now, it'll work tomorrow I'm sure.
So basically it's a massive thanks for all the help - I'm really sorry
so much of it has been my poor SIP syntax and formatting and
omissions. Thank you for the awesome product!
mike
On Oct 15, 2:34 pm, "Jean Deruelle" <jean.derue...@gmail.com> wrote:
> Your NOTIFY requests don't contain the Event header. That is wrong, not sure
> if this is related but you want to fix it and retry.
> I need to check also but maybe the container should generate an error
> response if the NOTIFY doesn't contain an Event header matching the
> SUBSCRIBE one...
> Also I suspect your problem stems from the fact that the branch id is the
> same in all your incoming NOTIFY requests (I suspect it is a sipp script
> issue), it should be different as per RFC 3261, Section 8.1.1.7 Via
>
> See extracted requests below
> 2008-10-14 15:32:00,076
> NOTIFY sip:192.168.5.1:5080 SIP/2.0
> CSeq: 3 NOTIFY
> From: <sip:A...@127.0.0.1:5073>;tag=1
> To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
>
> Via: SIP/2.0/UDP 127.0.1.1:5073;*branch=z9hG4bK-9831-1-7*
> From: <sip:A...@127.0.0.1:5073>;tag=1
> To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
>
> Contact: <sip:127.0.1.1:5073;transport=UDP>
> Max-Forwards: 70
> Expires: 18000
> Subscription-State: active
> Content-Type: text/plain
> Content-Length: 315
>
> 2008-10-14 15:32:24,296
> NOTIFY sip:192.168.5.1:5080 SIP/2.0
> Call-ID: 7d90980d4ec0b7937335921f7807d...@192.168.5.1
> Max-Forwards: 70
> Expires: 18000
> Subscription-State: active
> Content-Type: text/plain
> Content-Length: 315
>
> 2008-10-14 15:32:24,296
> NOTIFY sip:192.168.5.1:5080 SIP/2.0
> CSeq: 4 NOTIFY
> From: <sip:A...@127.0.0.1:5073>;tag=1
> To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
>
> Via: SIP/2.0/UDP 127.0.1.1:5073;*branch=z9hG4bK-9831-1-7*
> From: <sip:A...@127.0.0.1:5073>;tag=1
> To: <sip:su...@127.0.1.1:5060>;tag=6356894824693778138_cc02fe1c29479f5f9f487636d8d9f47f975b05e8
>
> Contact: <sip:127.0.1.1:5073;transport=UDP>
> Max-Forwards: 70
> Expires: 18000
> Subscription-State: active
> Content-Type: text/plain
> Content-Length: 315
>
> Which version are you using ?
>
> Jean
>
> On Tue, Oct 14, 2008 at 5:49 PM, michael
> <ihatefillinginthisf...@gmail.com>wrote:
> Max-Forwards: 70
> Expires: 18000
> Subscription-State: active
> Content-Type: text/plain
> Content-Length: 315
>
> Which version are you using ?
>
> Jean
>
> On Tue, Oct 14, 2008 at 5:49 PM, michael
>
> > Hi
> > I'm getting a problem where the 200 OK response to an incoming NOTIFY
> > occasionally has the incorrect CSeq value. The scenario has a sequence
> > of NOTIFY -> 200 OK messages, and the problem arises when the 200 OK
> > response to a NOTIFY takes the CSeq value of the PREVIOUS NOTIFY
> > request, rather than the NOTIFY it is responding to. This seems to cause
> > retransmissions of the NOTIFY, and hence the (incorrect) 200 OK, until
> > the NOTIFY retransmissions time out, and treat the transaction/dialog as
> > dead because of no acknowledgement, or the correct 200 OK eventually
> > gets sent in response.
> > I don't know what triggers the 200 OK with the right CSeq to be sent
> > after a series of 200 OKs with the incorrect CSeq, but it does happen
> > sometimes. More importantly, I can't find a cause for the incorrect CSeq
> > to be used by the 200 OK.
>
> > I've managed to track the problem in the attached log file, but outlined
> > are the main points/events I've managed to identify. I don't know the
> > significance of all the logging, but I've included what I gather are
> > relatively important events. There are 5 SipSessions open in the test,
> > and I follow one (which exhibited the problem) with Call-ID:
> > 7d90980d4ec0b7937335921f7807d...@192.168.5.1. The time stamps are
> > Hi
> > I'm getting a problem where the 200 OK response to an incoming NOTIFY
> > occasionally has the incorrect CSeq value. The scenario has a sequence
> > of NOTIFY -> 200 OK messages, and the problem arises when the 200 OK
> > response to a NOTIFY takes the CSeq value of the PREVIOUS NOTIFY
> > request, rather than the NOTIFY it is responding to. This seems to cause
> > retransmissions of the NOTIFY, and hence the (incorrect) 200 OK, until
> > the NOTIFY retransmissions time out, and treat the transaction/dialog as
> > dead because of no acknowledgement, or the correct 200 OK eventually
> > gets sent in response.
> > I don't know what triggers the 200 OK with the right CSeq to be sent
> > after a series of 200 OKs with the incorrect CSeq, but it does happen
> > sometimes. More importantly, I can't find a cause for the incorrect CSeq
> > to be used by the 200 OK.
>
> > I've managed to track the problem in the attached log file, but outlined
> > are the main points/events I've managed to identify. I don't know the
> > significance of all the logging, but I've included what I gather are
> > relatively important events. There are 5 SipSessions open in the test,
> > and I follow one (which exhibited the problem) with Call-ID:
>
> read more »
Jean Deruelle
Oct 16, 2008, 3:45:45 AM10/16/08
to mobicent...@googlegroups.com
Hey no problem Mike, we are here to help the community in many ways :-)
I'm glad that it works fine and hope that it will continue to do so today ;-)
BTW as you are running sipp tests, if you could check to see if there is any memory leaks we could fix in the case of your SUBSCRIBE/NOTIFY scenario, that would be great too.
A massive thanks to you for using Mobicents Sip Servlets.
Jean
I'm glad that it works fine and hope that it will continue to do so today ;-)
BTW as you are running sipp tests, if you could check to see if there is any memory leaks we could fix in the case of your SUBSCRIBE/NOTIFY scenario, that would be great too.
A massive thanks to you for using Mobicents Sip Servlets.
Jean
narfice
Oct 16, 2008, 4:00:36 AM10/16/08
to mobicents-public
I'll check for leaks with pleasure - not exactly sure how, though. How
do I go about that? What exactly would I be looking for?
On Oct 16, 9:45 am, "Jean Deruelle" <jean.derue...@gmail.com> wrote:
> Hey no problem Mike, we are here to help the community in many ways :-)
> I'm glad that it works fine and hope that it will continue to do so today
> ;-)
> BTW as you are running sipp tests, if you could check to see if there is any
> memory leaks we could fix in the case of your SUBSCRIBE/NOTIFY scenario,
> that would be great too.
>
> A massive thanks to you for using Mobicents Sip Servlets.
> Jean
>
> On Wed, Oct 15, 2008 at 11:18 PM, narfice
> <ihatefillinginthisf...@gmail.com>wrote:
> ...
>
> read more »
do I go about that? What exactly would I be looking for?
On Oct 16, 9:45 am, "Jean Deruelle" <jean.derue...@gmail.com> wrote:
> Hey no problem Mike, we are here to help the community in many ways :-)
> I'm glad that it works fine and hope that it will continue to do so today
> ;-)
> BTW as you are running sipp tests, if you could check to see if there is any
> memory leaks we could fix in the case of your SUBSCRIBE/NOTIFY scenario,
> that would be great too.
>
> A massive thanks to you for using Mobicents Sip Servlets.
> Jean
>
> On Wed, Oct 15, 2008 at 11:18 PM, narfice
>
> read more »
Jean Deruelle
Oct 16, 2008, 4:56:33 AM10/16/08
to mobicent...@googlegroups.com
you can run you test steadily at a good call rate that the server can handle but without pushing too much (it always depends on the hardware you're using).
Try to find a call rate where the CPU is used at about 50% and then run the sipp script for a night or 24 hour and if it doesn't break it means that there is a good chance that there is no memory leaks. if it breaks with an out of memory error then there might be a memory leak and in this case profiling will be needed and this is where we enter in the game. you also need to make sure your application is correctly coded doesn't hold onto some references forever, invalidate the sesssions as soon as they are not needed anymore and so on...
You may want to look at the existing load tests here http://code.google.com/p/mobicents/source/browse/trunk/servers/sip-servlets/sip-servlets-test-suite/sipp-scenarios/performance/ also make sure to start your server with the good JVM parameters (
for tomcat : export CATALINA_OPTS="-Xms1536m -Xmx1536m -XX:PermSize=128M -XX:MaxPermSize=256M -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode"
for JBoss : export JAVA_OPTS="-Xms1536m -Xmx1536m -XX:PermSize=128M -XX:MaxPermSize=256M -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode" , tune the memory settings depending on your hardware, the settings here are for a 2GB RAM)
Jean
Try to find a call rate where the CPU is used at about 50% and then run the sipp script for a night or 24 hour and if it doesn't break it means that there is a good chance that there is no memory leaks. if it breaks with an out of memory error then there might be a memory leak and in this case profiling will be needed and this is where we enter in the game. you also need to make sure your application is correctly coded doesn't hold onto some references forever, invalidate the sesssions as soon as they are not needed anymore and so on...
You may want to look at the existing load tests here http://code.google.com/p/mobicents/source/browse/trunk/servers/sip-servlets/sip-servlets-test-suite/sipp-scenarios/performance/ also make sure to start your server with the good JVM parameters (
for tomcat : export CATALINA_OPTS="-Xms1536m -Xmx1536m -XX:PermSize=128M -XX:MaxPermSize=256M -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode"
for JBoss : export JAVA_OPTS="-Xms1536m -Xmx1536m -XX:PermSize=128M -XX:MaxPermSize=256M -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode" , tune the memory settings depending on your hardware, the settings here are for a 2GB RAM)
Jean
Reply all
Reply to author
Forward
0 new messages