files for thread " Extensions SUBSCRIBE/NOTIFY in Mobicents Sip Servlets 0.4.1" from 'narfice'
23 views
Skip to first unread message
michael
Sep 5, 2008, 8:46:20 AM9/5/08
to mobicent...@googlegroups.com
Hi
I've attached the wireshark trace (libpcap file format - wirshark
doesn't append it, and I don't know the .extension), the Catalina log
file, and the sipp scenario that I interact on the interface with.
I'll put the general description of the problem on the forum.
regards,
mike
I've attached the wireshark trace (libpcap file format - wirshark
doesn't append it, and I don't know the .extension), the Catalina log
file, and the sipp scenario that I interact on the interface with.
I'll put the general description of the problem on the forum.
regards,
mike
aayush bhatnagar
Sep 5, 2008, 1:25:29 PM9/5/08
to mobicent...@googlegroups.com
just curious,
In this trace, how come the event header is missing. Also the Supported: event list header is not there. How do u identify that the subscription is for a resource list ? Notifications seem to be having the event header though.
[SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: sip:mi...@127.0.1.1:5060
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists>]
Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: sip:mi...@127.0.1.1:5060
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists>]
Regards
Aayush
2008/09/05 2:35:45 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/09/05 2:35:45 PM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
2008-09-05 14:35:46,130 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.init(SipApplicationDispatcherImpl.java:170) - Using the Service Provider Framework to load the application router provider
2008-09-05 14:35:46,176 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.init(SipApplicationDispatcherImpl.java:183) - Using the following Application Router : org.mobicents.servlet.sip.router.DefaultApplicationRouter
2008-09-05 14:35:46,195 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.init(SipApplicationDispatcherImpl.java:193) - Sip Application dispatcher registered under following name Catalina:type=SipApplicationDispatcher
2008/09/05 2:35:46 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 2057 ms
2008/09/05 2:35:46 PM org.apache.catalina.core.StandardService start
INFO: Starting service Sip-Servlets
2008/09/05 2:35:46 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.14
2008/09/05 2:35:46 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive signal-servlet.war
2008-09-05 14:35:47,141 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:182) - Starting the sip context
2008-09-05 14:35:47,189 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:133) - Initializing the sip context
2008-09-05 14:35:47,429 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:175) - sip context Initialized
2008-09-05 14:35:49,971 INFO main za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:54) - The chat room sip servlet has been started !
2008-09-05 14:35:49,978 INFO main za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:62) - Sip Factory ref from JNDI : org.mobicents.servlet.sip.message.SipFactoryFacade@125844f
2008-09-05 14:35:49,980 INFO main za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:70) - serverAddress is : sip:sig...@127.0.0.1:5080
2008-09-05 14:35:50,159 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:319) - the following sip servlet application has been added : SignalServlet
2008-09-05 14:35:50,160 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:265) - sip context started
2008/09/05 2:35:50 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive sip-servlets-management.war
2008-09-05 14:35:50,196 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:182) - Starting the sip context
2008-09-05 14:35:50,197 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:133) - Initializing the sip context
2008-09-05 14:35:50,202 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.init(SipStandardContext.java:175) - sip context Initialized
2008-09-05 14:35:51,750 INFO main org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:319) - the following sip servlet application has been added : DummyServlet
2008-09-05 14:35:51,752 INFO main org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:265) - sip context started
2008/09/05 2:35:52 PM org.apache.catalina.core.ApplicationContext log
INFO: ContextListener: contextInitialized()
2008/09/05 2:35:52 PM org.apache.catalina.core.ApplicationContext log
INFO: SessionListener: contextInitialized()
2008/09/05 2:35:53 PM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
2008/09/05 2:35:53 PM org.apache.jk.common.ChannelSocket init
INFO: Port busy 8009 java.net.BindException: Address already in use
2008/09/05 2:35:53 PM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8010
2008/09/05 2:35:53 PM org.apache.jk.server.JkMain start
INFO: Jk running ID=1 time=0/49 config=null
2008-09-05 14:35:53,935 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.SERVER_LOG=/home/mike/mss-0.5-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.5-apache-tomcat-6.0.14//logs/debuglog.txt}
]
2008-09-05 14:35:53,936 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:266) [ ]]>]
2008-09-05 14:35:53,937 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:267) [</debug>]
2008-09-05 14:35:53,938 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-09-05 14:35:53,939 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:274) [<debug>]
2008-09-05 14:35:53,941 DEBUG main gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:275) [<![CDATA[ ]
2008-09-05 14:35:53,970 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-09-05 14:35:54,235 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-09-05 14:35:54,236 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@131c89c listeningPoint = gov.nist.javax.sip.ListeningPointImpl@1697b67]
2008-09-05 14:35:54,239 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@1697b67]
2008-09-05 14:35:54,327 INFO main org.mobicents.servlet.sip.startup.SipProtocolHandler.start(SipProtocolHandler.java:375) - Sip Connector started on ip address : 192.168.5.1,port 5080, useStun false, stunAddress null, stunPort : 0
2008-09-05 14:35:54,356 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@1202d69]
2008/09/05 2:35:54 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 8243 ms
2008-09-05 14:36:38,621 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-09-05 14:36:38,622 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:291) [Length = 853]
2008-09-05 14:36:38,625 DEBUG Thread-10 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-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: sip:mi...@127.0.1.1:5060
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists>]
2008-09-05 14:36:38,941 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="1220618198626"
isSender="false"
transactionId="z9hg4bk-8752-1-0"
callId="1-8...@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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists>]]>
</message>
2008-09-05 14:36:38,942 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-8752-1-0]
2008-09-05 14:36:38,962 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-09-05 14:36:38,963 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-09-05 14:36:38,965 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-8752-1-0]
2008-09-05 14:36:38,966 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1083) [newSIPServerRequest( SUBSCRIBE:z9hG4bK-8752-1-0):gov.nist.javax.sip.stack.SIPServerTransaction@688ae9b1]
2008-09-05 14:36:38,991 DEBUG Thread-10 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@29c204 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@688ae9b1]
2008-09-05 14:36:38,992 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@688ae9b1]
2008-09-05 14:36:38,993 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-09-05 14:36:38,994 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-09-05 14:36:38,994 DEBUG Thread-10 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@688ae9b1]
2008-09-05 14:36:38,995 DEBUG Thread-10 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-09-05 14:36:38,996 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-09-05 14:36:38,997 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-8752-1-0]
2008-09-05 14:36:38,998 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@688ae9b1 branchID = z9hG4bK-8752-1-0 isClient = false]
2008-09-05 14:36:39,007 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-09-05 14:36:39,007 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()]
2008-09-05 14:36:39,009 DEBUG Thread-10 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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists> transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@688ae9b1 listening point = 192.168.5.1:5080]
2008-09-05 14:36:39,011 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-09-05 14:36:39,012 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-8...@127.0.1.1:1) : returning null]
2008-09-05 14:36:39,013 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:209) [dialogId = 1-8...@127.0.1.1:1]
2008-09-05 14:36:39,014 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:210) [dialog = null]
2008-09-05 14:36:39,015 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@688ae9b1]
2008-09-05 14:36:39,017 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:722) [SUBSCRIBE transaction.isMapped = false]
2008-09-05 14:36:39,020 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@180cf2a]currentTransaction = gov.nist.javax.sip.sta...@688ae9b1this.sipListener = org.mobicents.servlet.sip.cor...@1202d69sipEvent.source = gov.nist.javax.sip.SipProviderImpl@180cf2a]
2008-09-05 14:36:39,022 DEBUG Thread-10 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:142) [Dialog = null]
2008-09-05 14:36:39,024 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-09-05 14:36:39,032 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@df48c4]
2008-09-05 14:36:39,033 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@df48c4nevents 1]
2008-09-05 14:36:39,034 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@180cf2a]source = gov.nist.javax.sip.SipProviderImpl@180cf2a]
2008-09-05 14:36:39,036 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@688ae9b1 sipEvent.serverTx = null]
2008-09-05 14:36:39,037 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-8752-1-0 existing={}]
2008-09-05 14:36:39,038 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-8752-1-0]
2008-09-05 14:36:39,039 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@688ae9b1]
2008-09-05 14:36:39,039 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-09-05 14:36:39,040 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@688ae9b1]
2008-09-05 14:36:39,041 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:357) - 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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists>
2008-09-05 14:36:39,043 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-09-05 14:36:39,044 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-8752-1-0 existing={}]
2008-09-05 14:36:39,045 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@688ae9b1]
2008-09-05 14:36:39,046 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:946) [removePendingTx: z9hg4bk-8752-1-0]
2008-09-05 14:36:39,046 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1423) [ putTransactionHash : key = z9hg4bk-8752-1-0]
2008-09-05 14:36:39,054 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:376) - ServerTx ref gov.nist.javax.sip.stack.SIPServerTransaction@688ae9b1
2008-09-05 14:36:39,054 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:377) - Dialog ref null
2008-09-05 14:36:39,073 INFO EventScannerThread org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.processRequest(SipApplicationDispatcherImpl.java:415) - Routing State INITIAL
2008-09-05 14:36:39,093 INFO EventScannerThread org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchMessage(InitialRequestDispatcher.java:96) - 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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists>
2008-09-05 14:36:39,094 INFO EventScannerThread org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchMessage(InitialRequestDispatcher.java:102) - popped route : null
2008-09-05 14:36:39,102 DEBUG Thread-10 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@688ae9b1]
2008-09-05 14:36:39,112 INFO EventScannerThread org.mobicents.servlet.sip.core.dispatchers.InitialRequestDispatcher.dispatchInsideContainer(InitialRequestDispatcher.java:196) - Dispatching the request event to SignalServlet
2008-09-05 14:36:39,169 INFO EventScannerThread org.mobicents.servlet.sip.core.dispatchers.MessageDispatcher.callServlet(MessageDispatcher.java:164) - Dispatching request SUBSCRIBE sip:subs...@127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5060;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:mi...@127.0.1.1:5060>
Max-Forwards: 70
Expires: 18000
Subject: Performance Testing
Content-Type: text/plain
Content-Length: 457
<?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:bi...@127.0.0.1:5071" />
<entry uri="sip:cl...@127.0.0.1:5071" />
<entry uri="sip:j...@127.0.0.1:5071" />
<entry uri="sip:os...@127.0.0.1:5071" />
<entry uri="sip:t...@127.0.0.1:5071" />
<entry uri="sip:wi...@127.0.0.1:5071" />
</list>
</resource-lists> to following App/servlet => SignalServlet/SignalServlet
2008-09-05 14:36:39,198 INFO EventScannerThread za.ac.uct.ee.crg.sipservlet.SignalServlet.doSubscribe(SignalServlet.java:97) - Timer thread has started
2008-09-05 14:36:39,217 INFO EventScannerThread org.mobicents.servlet.sip.message.SipServletResponseImpl.send(SipServletResponseImpl.java:363) - sending response SIP/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.1.1:5060;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
2008-09-05 14:36:39,218 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-09-05 14:36:39,219 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-8...@127.0.1.1:1) : returning null]
2008-09-05 14:36:39,257 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:444) [settingRemoteParty "Mike" <sip:mi...@127.0.1.1:5060>]
2008-09-05 14:36:39,258 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1265) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@2016b0/1]
2008-09-05 14:36:39,259 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1169) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@2016b0null/1]
2008-09-05 14:36:39,260 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1171) [TID = z9hg4bk-8752-1-0/true]
2008-09-05 14:36:39,261 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1174][SIPDialog.java:328][SIPTransactionStack.java:566][SipProviderImpl.java:821][SipServletResponseImpl.java:376][MessageOut.java:26][SignalServlet.java:100][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:39,262 DEBUG EventScannerThread 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@2016b0]
2008-09-05 14:36:39,263 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:331) [provider port = 5080]
2008-09-05 14:36:39,267 DEBUG EventScannerThread 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:376][MessageOut.java:26][SignalServlet.java:100][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:39,268 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1265) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@2016b0/1]
2008-09-05 14:36:39,269 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1169) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@2016b0null/1]
2008-09-05 14:36:39,270 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1171) [TID = z9hg4bk-8752-1-0/true]
2008-09-05 14:36:39,271 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1174][SipProviderImpl.java:823][SipServletResponseImpl.java:376][MessageOut.java:26][SignalServlet.java:100][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:39,272 DEBUG EventScannerThread 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@2016b0state = null]
2008-09-05 14:36:39,273 DEBUG EventScannerThread 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@688ae9b1 dialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:39,274 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-09-05 14:36:39,275 DEBUG EventScannerThread 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@688ae9b1 branchID = z9hG4bK-8752-1-0 isClient = false]
2008-09-05 14:36:39,276 DEBUG EventScannerThread 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:400][MessageOut.java:26][SignalServlet.java:100][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:39,279 DEBUG EventScannerThread 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@688ae9b1 getState = Proceeding Transaction]
2008-09-05 14:36:39,281 DEBUG EventScannerThread 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-09-05 14:36:39,282 DEBUG EventScannerThread 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:400][MessageOut.java:26][SignalServlet.java:100][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:39,287 DEBUG EventScannerThread 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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
]
2008-09-05 14:36:39,288 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:731) [*******************
]
2008-09-05 14:36:39,289 DEBUG EventScannerThread 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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
]
2008-09-05 14:36:39,314 INFO EventScannerThread gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5080"
to="192.168.5.1:5060"
time="1220618199283"
isSender="true"
transactionId="z9hg4bk-8752-1-0"
callId="1-8...@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;received=192.168.5.1;branch=z9hG4bK-8752-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-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
]]>
</message>
2008-09-05 14:36:39,320 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:335) [TransactionTimer() : z9hg4bk-8752-1-0]
2008-09-05 14:36:39,321 INFO EventScannerThread za.ac.uct.ee.crg.domain.MessageOut.sendResponse(MessageOut.java:27) - Sending SIP 100 Trying for Initial SUBSCRIBE
2008-09-05 14:36:39,324 INFO EventScannerThread za.ac.uct.ee.crg.sipservlet.SignalServlet.doSubscribe(SignalServlet.java:108) - New subscription received - creating new Subscriber object
2008-09-05 14:36:39,330 INFO EventScannerThread za.ac.uct.ee.crg.sipservlet.SignalServlet.doSubscribe(SignalServlet.java:112) - Content length for Subscribe message is non-zero!
2008-09-05 14:36:39,909 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:78) - List made of elements from document. Size: 6
2008-09-05 14:36:39,935 INFO EventScannerThread za.ac.uct.ee.crg.domain.Presentity.appendSubscriber(Presentity.java:57) - sip:mi...@127.0.1.1:5060 added to Watcher list of sip:bi...@127.0.0.1:5071
2008-09-05 14:36:39,940 INFO EventScannerThread za.ac.uct.ee.crg.domain.Subscriber.pushPresentity(Subscriber.java:141) - Presentity sip:bi...@127.0.0.1:5071 added to sip:mi...@127.0.1.1:5060's PresentityMap. Size: 1
2008-09-05 14:36:39,941 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:110) - Presentity sip:bi...@127.0.0.1:5071 was added - map size is 1
2008-09-05 14:36:39,942 INFO EventScannerThread za.ac.uct.ee.crg.domain.Presentity.appendSubscriber(Presentity.java:57) - sip:mi...@127.0.1.1:5060 added to Watcher list of sip:cl...@127.0.0.1:5071
2008-09-05 14:36:39,943 INFO EventScannerThread za.ac.uct.ee.crg.domain.Subscriber.pushPresentity(Subscriber.java:141) - Presentity sip:cl...@127.0.0.1:5071 added to sip:mi...@127.0.1.1:5060's PresentityMap. Size: 2
2008-09-05 14:36:39,944 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:110) - Presentity sip:cl...@127.0.0.1:5071 was added - map size is 2
2008-09-05 14:36:39,945 INFO EventScannerThread za.ac.uct.ee.crg.domain.Presentity.appendSubscriber(Presentity.java:57) - sip:mi...@127.0.1.1:5060 added to Watcher list of sip:j...@127.0.0.1:5071
2008-09-05 14:36:39,946 INFO EventScannerThread za.ac.uct.ee.crg.domain.Subscriber.pushPresentity(Subscriber.java:141) - Presentity sip:j...@127.0.0.1:5071 added to sip:mi...@127.0.1.1:5060's PresentityMap. Size: 3
2008-09-05 14:36:39,946 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:110) - Presentity sip:j...@127.0.0.1:5071 was added - map size is 3
2008-09-05 14:36:39,948 INFO EventScannerThread za.ac.uct.ee.crg.domain.Presentity.appendSubscriber(Presentity.java:57) - sip:mi...@127.0.1.1:5060 added to Watcher list of sip:os...@127.0.0.1:5071
2008-09-05 14:36:39,949 INFO EventScannerThread za.ac.uct.ee.crg.domain.Subscriber.pushPresentity(Subscriber.java:141) - Presentity sip:os...@127.0.0.1:5071 added to sip:mi...@127.0.1.1:5060's PresentityMap. Size: 4
2008-09-05 14:36:39,950 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:110) - Presentity sip:os...@127.0.0.1:5071 was added - map size is 4
2008-09-05 14:36:39,951 INFO EventScannerThread za.ac.uct.ee.crg.domain.Presentity.appendSubscriber(Presentity.java:57) - sip:mi...@127.0.1.1:5060 added to Watcher list of sip:t...@127.0.0.1:5071
2008-09-05 14:36:39,955 INFO EventScannerThread za.ac.uct.ee.crg.domain.Subscriber.pushPresentity(Subscriber.java:141) - Presentity sip:t...@127.0.0.1:5071 added to sip:mi...@127.0.1.1:5060's PresentityMap. Size: 5
2008-09-05 14:36:39,956 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:110) - Presentity sip:t...@127.0.0.1:5071 was added - map size is 5
2008-09-05 14:36:39,957 INFO EventScannerThread za.ac.uct.ee.crg.domain.Presentity.appendSubscriber(Presentity.java:57) - sip:mi...@127.0.1.1:5060 added to Watcher list of sip:wi...@127.0.0.1:5071
2008-09-05 14:36:39,958 INFO EventScannerThread za.ac.uct.ee.crg.domain.Subscriber.pushPresentity(Subscriber.java:141) - Presentity sip:wi...@127.0.0.1:5071 added to sip:mi...@127.0.1.1:5060's PresentityMap. Size: 6
2008-09-05 14:36:39,958 INFO EventScannerThread za.ac.uct.ee.crg.domain.ResourceListOperations.parseResourceList(ResourceListOperations.java:110) - Presentity sip:wi...@127.0.0.1:5071 was added - map size is 6
2008-09-05 14:36:39,959 INFO EventScannerThread za.ac.uct.ee.crg.sipservlet.SignalServlet.doSubscribe(SignalServlet.java:127) - New subscriberMap object added: sip:mi...@127.0.1.1:5060
2008-09-05 14:36:39,973 INFO EventScannerThread org.mobicents.servlet.sip.message.SipServletResponseImpl.send(SipServletResponseImpl.java:363) - sending response SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.1.1:5060;received=192.168.5.1;branch=z9hG4bK-8752-1-0
From: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
Call-ID: 1-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 18000
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
2008-09-05 14:36:39,974 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-09-05 14:36:39,980 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2235) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2016b0 lastResponse = SIP/2.0 200 OK
]
2008-09-05 14:36:39,982 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2250][SIPServerTransaction.java:1429][SipServletResponseImpl.java:400][MessageOut.java:33][SignalServlet.java:136][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:39,985 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2251) [cseqMethod = SUBSCRIBE]
2008-09-05 14:36:39,993 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2252) [dialogState = null]
2008-09-05 14:36:39,993 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2254) [method = SUBSCRIBE]
2008-09-05 14:36:39,995 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2255) [statusCode = 200]
2008-09-05 14:36:39,996 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2256) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@688ae9b1]
2008-09-05 14:36:39,997 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-09-05 14:36:39,998 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLocalTag(SIPDialog.java:1359) [set Local tag 3082234 null]
2008-09-05 14:36:39,999 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1361][SIPDialog.java:2393][SIPServerTransaction.java:1429][SipServletResponseImpl.java:400][MessageOut.java:33][SignalServlet.java:136][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,004 DEBUG EventScannerThread 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@2016b0newState = 1]
2008-09-05 14:36:40,006 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:874][SIPDialog.java:2439][SIPServerTransaction.java:1429][SipServletResponseImpl.java:400][MessageOut.java:33][SignalServlet.java:136][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,006 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:877) [gov.nist.javax.sip.stack.SIPDialog@2016b0 old dialog state is null]
2008-09-05 14:36:40,011 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:879) [gov.nist.javax.sip.stack.SIPDialog@2016b0 New dialog state is Confirmed Dialog]
2008-09-05 14:36:40,012 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:530) [putDialog dialogId=1-8...@127.0.1.1:3082234:1 dialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,013 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransactionStack.java:535][SIPDialog.java:2444][SIPServerTransaction.java:1429][SipServletResponseImpl.java:400][MessageOut.java:33][SignalServlet.java:136][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,014 DEBUG EventScannerThread 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@688ae9b1 branchID = z9hG4bK-8752-1-0 isClient = false]
2008-09-05 14:36:40,015 DEBUG EventScannerThread 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:400][MessageOut.java:33][SignalServlet.java:136][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,016 DEBUG EventScannerThread 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@688ae9b1 tickCount 64 currentTickCount = -1]
2008-09-05 14:36:40,017 DEBUG EventScannerThread 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@688ae9b1 getState = Completed Transaction]
2008-09-05 14:36:40,018 DEBUG EventScannerThread 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-09-05 14:36:40,020 DEBUG EventScannerThread 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:400][MessageOut.java:33][SignalServlet.java:136][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,025 DEBUG EventScannerThread 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;received=192.168.5.1;branch=z9hG4bK-8752-1-0
From: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
Call-ID: 1-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 18000
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
]
2008-09-05 14:36:40,026 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:731) [*******************
]
2008-09-05 14:36:40,027 DEBUG EventScannerThread 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;received=192.168.5.1;branch=z9hG4bK-8752-1-0
From: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
Call-ID: 1-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 18000
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
]
2008-09-05 14:36:40,032 INFO EventScannerThread gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5080"
to="192.168.5.1:5060"
time="1220618200024"
isSender="true"
transactionId="z9hg4bk-8752-1-0"
callId="1-8...@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;received=192.168.5.1;branch=z9hG4bK-8752-1-0
From: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
To: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
Call-ID: 1-8...@127.0.1.1
CSeq: 1 SUBSCRIBE
Contact: <sip:192.168.5.1:5080;transport=udp>
Expires: 18000
Record-Route: <sip:192.168.5.1:5080;appname=SignalServlet;final_response=true;lr;transport=udp>
Content-Length: 0
]]>
</message>
2008-09-05 14:36:40,033 INFO EventScannerThread za.ac.uct.ee.crg.domain.MessageOut.sendResponse(MessageOut.java:34) - Sending SIP 200 OK response
2008-09-05 14:36:40,039 DEBUG EventScannerThread 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@2016b0]
2008-09-05 14:36:40,040 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:624) [----- ]
2008-09-05 14:36:40,045 DEBUG EventScannerThread 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@2016b0]
2008-09-05 14:36:40,046 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:627) [RouteList = ]
2008-09-05 14:36:40,047 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:629) [myRouteList = ]
2008-09-05 14:36:40,047 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:631) [----- ]
2008-09-05 14:36:40,054 DEBUG EventScannerThread 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-09-05 14:36:40,056 DEBUG EventScannerThread 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-09-05 14:36:40,057 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-8...@127.0.1.1:3082234:1) : returning gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,060 DEBUG EventScannerThread 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-09-05 14:36:40,066 DEBUG EventScannerThread 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-09-05 14:36:40,071 DEBUG EventScannerThread 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:767][MessageOut.java:49][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,072 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK22e0aab078e9e04659ac4240ed41c4ba]
2008-09-05 14:36:40,073 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1417) [ putTransactionHash : key = z9hg4bk22e0aab078e9e04659ac4240ed41c4ba]
2008-09-05 14:36:40,074 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK22e0aab078e9e04659ac4240ed41c4ba]
2008-09-05 14:36:40,075 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-09-05 14:36:40,076 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1524) [setDialog: 1-8...@127.0.1.1:3082234:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,077 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,078 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,079 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,080 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,084 INFO EventScannerThread org.mobicents.servlet.sip.message.SipServletRequestImpl.send(SipServletRequestImpl.java:838) - 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=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Expires: 18000
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
Content-Length: 0
2008-09-05 14:36:40,085 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,086 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1651) [dialog.sendRequest dialog = gov.nist.javax.sip.stack.SIPDialog@2016b0
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=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Expires: 18000
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
Content-Length: 0
]
2008-09-05 14:36:40,087 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1524) [setDialog: 1-8...@127.0.1.1:3082234:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,088 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1169) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@2016b03082234/1]
2008-09-05 14:36:40,089 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1171) [TID = z9hg4bk22e0aab078e9e04659ac4240ed41c4ba/false]
2008-09-05 14:36:40,094 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1174][SIPDialog.java:1699][SipServletRequestImpl.java:840][MessageOut.java:49][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,095 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1746) [Using hop = 127.0.1.1 : 5060]
2008-09-05 14:36:40,096 DEBUG EventScannerThread 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-09-05 14:36:40,132 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1835) [using message channel gov.nist.javax.sip.stack.UDPMessageChannel@132ae7]
2008-09-05 14:36:40,134 DEBUG EventScannerThread 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=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Expires: 18000
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
Content-Length: 0
]
2008-09-05 14:36:40,135 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:427) [TransactionState null]
2008-09-05 14:36:40,136 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bK22e0aab078e9e04659ac4240ed41c4ba]
2008-09-05 14:36:40,137 DEBUG EventScannerThread 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@fee59766 branchID = z9hG4bK22e0aab078e9e04659ac4240ed41c4ba isClient = true]
2008-09-05 14:36:40,139 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPClientTransaction.java:1311][SIPClientTransaction.java:472][SIPDialog.java:1870][SipServletRequestImpl.java:840][MessageOut.java:49][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,140 DEBUG EventScannerThread 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@fee59766 tickCount 64 currentTickCount = -1]
2008-09-05 14:36:40,142 DEBUG EventScannerThread 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:1870][SipServletRequestImpl.java:840][MessageOut.java:49][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,143 DEBUG EventScannerThread 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=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Expires: 18000
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
Content-Length: 0
]
2008-09-05 14:36:40,148 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:666) [*******************
]
2008-09-05 14:36:40,150 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-09-05 14:36:40,151 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:291) [Length = 341]
2008-09-05 14:36:40,153 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;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-09-05 14:36:40,158 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@fee59766]
2008-09-05 14:36:40,159 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-09-05 14:36:40,159 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-09-05 14:36:40,162 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="1220618200161"
isSender="false"
transactionId="z9hg4bk22e0aab078e9e04659ac4240ed41c4ba"
callId="1-8...@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;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]]>
</message>
2008-09-05 14:36:40,162 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 z9hg4bk22e0aab078e9e04659ac4240ed41c4ba]
2008-09-05 14:36:40,163 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@fee59766 for SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-09-05 14:36:40,167 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@fee59766 to gov.nist.javax.sip.DialogFilter@1dfd868]
2008-09-05 14:36:40,168 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2235) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2016b0 lastResponse = SIP/2.0 200 OK
]
2008-09-05 14:36:40,169 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2250][SIPClientTransaction.java:1471][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,170 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2251) [cseqMethod = NOTIFY]
2008-09-05 14:36:40,170 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2252) [dialogState = Confirmed Dialog]
2008-09-05 14:36:40,171 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2254) [method = SUBSCRIBE]
2008-09-05 14:36:40,171 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2255) [statusCode = 200]
2008-09-05 14:36:40,172 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2256) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@fee59766]
2008-09-05 14:36:40,173 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-09-05 14:36:40,174 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-09-05 14:36:40,174 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@2016b0]
2008-09-05 14:36:40,175 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;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 1 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-09-05 14:36:40,176 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@fee59766]
2008-09-05 14:36:40,177 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2235) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2016b0 lastResponse = SIP/2.0 200 OK
]
2008-09-05 14:36:40,182 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2250][DialogFilter.java:1031][SIPClientTransaction.java:643][SIPClientTransaction.java:551][SIPClientTransaction.java:1473][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,183 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2251) [cseqMethod = NOTIFY]
2008-09-05 14:36:40,184 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2252) [dialogState = Confirmed Dialog]
2008-09-05 14:36:40,185 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2254) [method = SUBSCRIBE]
2008-09-05 14:36:40,186 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2255) [statusCode = 200]
2008-09-05 14:36:40,187 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2256) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@fee59766]
2008-09-05 14:36:40,187 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-09-05 14:36:40,188 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1524) [setDialog: 1-8...@127.0.1.1:3082234:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,189 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@180cf2a]currentTransaction = gov.nist.javax.sip.sta...@fee59766this.sipListener = org.mobicents.servlet.sip.cor...@1202d69sipEvent.source = gov.nist.javax.sip.SipProviderImpl@180cf2a]
2008-09-05 14:36:40,190 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@2016b0]
2008-09-05 14:36:40,194 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:1473][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,194 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@f894ce]
2008-09-05 14:36:40,195 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@fee59766 branchID = z9hG4bK22e0aab078e9e04659ac4240ed41c4ba isClient = true]
2008-09-05 14:36:40,199 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPClientTransaction.java:1311][SIPClientTransaction.java:649][SIPClientTransaction.java:551][SIPClientTransaction.java:1473][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,200 DEBUG Thread-12 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@fee59766 tickCount 10 currentTickCount = 64]
2008-09-05 14:36:40,201 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@fee59766]
2008-09-05 14:36:40,201 DEBUG Thread-12 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:526][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,203 INFO EventScannerThread gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="192.168.5.1:5080"
to="127.0.1.1:5060"
time="1220618200141"
isSender="true"
transactionId="z9hg4bk22e0aab078e9e04659ac4240ed41c4ba"
callId="1-8...@127.0.1.1"
firstLine="NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0"
>
<![CDATA[NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 1 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Expires: 18000
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: pending
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bK22e0aab078e9e04659ac4240ed41c4ba
Content-Length: 0
]]>
</message>
2008-09-05 14:36:40,206 DEBUG EventScannerThread 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@2016b0]
2008-09-05 14:36:40,207 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:624) [----- ]
2008-09-05 14:36:40,208 DEBUG EventScannerThread 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@2016b0]
2008-09-05 14:36:40,209 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:627) [RouteList = ]
2008-09-05 14:36:40,210 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:629) [myRouteList = ]
2008-09-05 14:36:40,214 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:631) [----- ]
2008-09-05 14:36:40,215 INFO EventScannerThread za.ac.uct.ee.crg.domain.MessageOut.initialNotify(MessageOut.java:51) - Initial request, Subscription-State set to 'pending'
2008-09-05 14:36:40,216 INFO EventScannerThread za.ac.uct.ee.crg.domain.MessageOut.initialNotify(MessageOut.java:61) - Subscription state set to 'active'
2008-09-05 14:36:40,217 DEBUG EventScannerThread 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-09-05 14:36:40,218 DEBUG EventScannerThread 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-09-05 14:36:40,219 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:657) [getDialog(1-8...@127.0.1.1:3082234:1) : returning gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,220 DEBUG EventScannerThread 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-09-05 14:36:40,221 DEBUG EventScannerThread 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-09-05 14:36:40,222 DEBUG EventScannerThread 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:767][MessageOut.java:64][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,223 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1]
2008-09-05 14:36:40,225 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1417) [ putTransactionHash : key = z9hg4bkeb7e6d36e5facc2d49b7122c07ee86b1]
2008-09-05 14:36:40,229 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1]
2008-09-05 14:36:40,229 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-09-05 14:36:40,230 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1524) [setDialog: 1-8...@127.0.1.1:3082234:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,232 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,233 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,234 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,235 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,236 INFO EventScannerThread org.mobicents.servlet.sip.message.SipServletRequestImpl.send(SipServletRequestImpl.java:838) - Sending the in dialog request NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 2 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: active
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
Content-Length: 0
2008-09-05 14:36:40,236 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1496) [ sipDialogs = {1-8...@127.0.1.1:3082234:1=gov.nist.javax.sip.stack.SIPDialog@2016b0} default dialog gov.nist.javax.sip.stack.SIPDialog@2016b0 retval gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,240 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1651) [dialog.sendRequest dialog = gov.nist.javax.sip.stack.SIPDialog@2016b0
dialogRequest =
NOTIFY sip:mi...@127.0.1.1:5060 SIP/2.0
CSeq: 2 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: active
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
Content-Length: 0
]
2008-09-05 14:36:40,241 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1524) [setDialog: 1-8...@127.0.1.1:3082234:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,242 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1169) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@2016b03082234/1]
2008-09-05 14:36:40,243 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1171) [TID = z9hg4bkeb7e6d36e5facc2d49b7122c07ee86b1/false]
2008-09-05 14:36:40,244 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:1174][SIPDialog.java:1699][SipServletRequestImpl.java:840][MessageOut.java:64][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,246 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1746) [Using hop = 127.0.1.1 : 5060]
2008-09-05 14:36:40,247 DEBUG EventScannerThread 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-09-05 14:36:40,248 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1835) [using message channel gov.nist.javax.sip.stack.UDPMessageChannel@1e6e305]
2008-09-05 14:36:40,249 DEBUG EventScannerThread 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: 2 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: active
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
Content-Length: 0
]
2008-09-05 14:36:40,250 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:427) [TransactionState null]
2008-09-05 14:36:40,250 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:412) [Setting Branch id : z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1]
2008-09-05 14:36:40,253 DEBUG EventScannerThread 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@90fdd558 branchID = z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1 isClient = true]
2008-09-05 14:36:40,254 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPClientTransaction.java:1311][SIPClientTransaction.java:472][SIPDialog.java:1870][SipServletRequestImpl.java:840][MessageOut.java:64][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,255 DEBUG EventScannerThread 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@90fdd558 tickCount 64 currentTickCount = -1]
2008-09-05 14:36:40,257 DEBUG EventScannerThread 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:1870][SipServletRequestImpl.java:840][MessageOut.java:64][SignalServlet.java:137][SipServlet.java:237][SipServlet.java:324][MessageDispatcher.java:185][InitialRequestDispatcher.java:270][InitialRequestDispatcher.java:183][SipApplicationDispatcherImpl.java:418][EventScanner.java:223][EventScanner.java:492][Thread.java:595]]
2008-09-05 14:36:40,258 DEBUG EventScannerThread 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: 2 NOTIFY
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
Max-Forwards: 70
Contact: <sip:192.168.5.1:5080;transport=udp>
Subscription-State: active
Event: presence
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
Content-Length: 0
]
2008-09-05 14:36:40,259 DEBUG EventScannerThread gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:666) [*******************
]
2008-09-05 14:36:40,260 DEBUG Thread-13 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-09-05 14:36:40,261 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:291) [Length = 341]
2008-09-05 14:36:40,261 DEBUG Thread-13 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;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 2 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-09-05 14:36:40,267 DEBUG Thread-13 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@90fdd558]
2008-09-05 14:36:40,268 DEBUG Thread-13 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-09-05 14:36:40,269 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true]
2008-09-05 14:36:40,270 INFO Thread-13 gov.nist.core.LogWriter.logInfo(LogWriter.java:405) - <message
from="127.0.1.1:5060"
to="192.168.5.1:5080"
time="1220618200269"
isSender="false"
transactionId="z9hg4bkeb7e6d36e5facc2d49b7122c07ee86b1"
callId="1-8...@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;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 2 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]]>
</message>
2008-09-05 14:36:40,271 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:819) [clientTx: looking for key z9hg4bkeb7e6d36e5facc2d49b7122c07ee86b1]
2008-09-05 14:36:40,272 DEBUG Thread-13 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@90fdd558 for SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.5.1:5080;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 2 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-09-05 14:36:40,272 DEBUG Thread-13 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@90fdd558 to gov.nist.javax.sip.DialogFilter@45e228]
2008-09-05 14:36:40,273 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2235) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2016b0 lastResponse = SIP/2.0 200 OK
]
2008-09-05 14:36:40,274 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2250][SIPClientTransaction.java:1471][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,274 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2251) [cseqMethod = NOTIFY]
2008-09-05 14:36:40,275 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2252) [dialogState = Confirmed Dialog]
2008-09-05 14:36:40,276 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2254) [method = SUBSCRIBE]
2008-09-05 14:36:40,278 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2255) [statusCode = 200]
2008-09-05 14:36:40,279 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2256) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@90fdd558]
2008-09-05 14:36:40,279 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-09-05 14:36:40,280 DEBUG Thread-13 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-09-05 14:36:40,281 DEBUG Thread-13 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@2016b0]
2008-09-05 14:36:40,282 DEBUG Thread-13 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;appname=SignalServlet;branch=z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1
From: "SubscribeTester" <sip:subs...@127.0.0.1:5080>;tag=3082234
To: "Mike" <sip:mi...@127.0.1.1:5060>;tag=1
Call-ID: 1-8...@127.0.1.1
CSeq: 2 NOTIFY
Contact: <sip:127.0.1.1:5060;transport=UDP>
Content-Length: 0
]
2008-09-05 14:36:40,282 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:958) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@90fdd558]
2008-09-05 14:36:40,283 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2235) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2016b0 lastResponse = SIP/2.0 200 OK
]
2008-09-05 14:36:40,284 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPDialog.java:2250][DialogFilter.java:1031][SIPClientTransaction.java:643][SIPClientTransaction.java:551][SIPClientTransaction.java:1473][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,285 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2251) [cseqMethod = NOTIFY]
2008-09-05 14:36:40,285 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2252) [dialogState = Confirmed Dialog]
2008-09-05 14:36:40,286 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2254) [method = SUBSCRIBE]
2008-09-05 14:36:40,287 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2255) [statusCode = 200]
2008-09-05 14:36:40,289 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2256) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@90fdd558]
2008-09-05 14:36:40,294 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:490) [isDialogCreated : NOTIFY returning false]
2008-09-05 14:36:40,295 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1524) [setDialog: 1-8...@127.0.1.1:3082234:1sipDialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,296 DEBUG Thread-13 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@180cf2a]currentTransaction = gov.nist.javax.sip.sta...@90fdd558this.sipListener = org.mobicents.servlet.sip.cor...@1202d69sipEvent.source = gov.nist.javax.sip.SipProviderImpl@180cf2a]
2008-09-05 14:36:40,296 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:145) [Dialog = gov.nist.javax.sip.stack.SIPDialog@2016b0]
2008-09-05 14:36:40,297 DEBUG Thread-13 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:1473][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,298 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@2b249]
2008-09-05 14:36:40,298 DEBUG Thread-13 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@90fdd558 branchID = z9hG4bKeb7e6d36e5facc2d49b7122c07ee86b1 isClient = true]
2008-09-05 14:36:40,299 DEBUG Thread-13 gov.nist.core.LogWriter.logDebug(LogWriter.java:222) - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:123) [[SIPTransaction.java:549][SIPClientTransaction.java:1311][SIPClientTransaction.java:649][SIPClientTransaction.java:551][SIPClientTransaction.java:1473][UDPMessageChannel.java:521][UDPMessageChannel.java:419][UDPMessageChannel.java:257][Thread.java:595]]
2008-09-05 14:36:40,300 DEBUG Thread-13 gov.nist.core
narfice
Sep 6, 2008, 6:01:35 AM9/6/08
to mobicents-public
That would probably be an omission on my part, in the sipp subscriber
scenario. Thanks for pointing it out though, I'll rectify it soon.
On Sep 5, 7:25 pm, "aayush bhatnagar" <abhatnagar192...@gmail.com>
wrote:
> To: SubscribeTester <sip:subscr...@127.0.0.1:5080>
> Contact: sip:m...@127.0.1.1:5060
> </list>
> </resource-lists>]
>
> Regards
> Aayush
> > [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@131c89clisteningPoint = gov.nist.javax.sip.ListeningPointImpl@1697b67
> ...
>
> read more »
scenario. Thanks for pointing it out though, I'll rectify it soon.
On Sep 5, 7:25 pm, "aayush bhatnagar" <abhatnagar192...@gmail.com>
wrote:
> just curious,
> In this trace, how come the event header is missing. Also the Supported:
> event list header is not there. How do u identify that the subscription is
> for a resource list ? Notifications seem to be having the event header
> though.
>
> [SUBSCRIBE sip:subscr...@127.0.0.1:5080 SIP/2.0
> In this trace, how come the event header is missing. Also the Supported:
> event list header is not there. How do u identify that the subscription is
> for a resource list ? Notifications seem to be having the event header
> though.
>
> Via: SIP/2.0/UDP 127.0.1.1:5060;branch=z9hG4bK-8752-1-0
> From: Mike <sip:m...@127.0.1.1:5060>;tag=1
> To: SubscribeTester <sip:subscr...@127.0.0.1:5080>
> Contact: sip:m...@127.0.1.1:5060
> Max-Forwards: 70
> Expires: 18000
> Subject: Performance Testing
> Content-Type: text/plain
> Content-Length: 457
>
> <?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:b...@127.0.0.1:5071" />
> Expires: 18000
> Subject: Performance Testing
> Content-Type: text/plain
> Content-Length: 457
>
> <?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:cl...@127.0.0.1:5071" />
> <entry uri="sip:j...@127.0.0.1:5071" />
> <entry uri="sip:os...@127.0.0.1:5071" />
> <entry uri="sip:t...@127.0.0.1:5071" />
> <entry uri="sip:w...@127.0.0.1:5071" />
> <entry uri="sip:j...@127.0.0.1:5071" />
> <entry uri="sip:os...@127.0.0.1:5071" />
> <entry uri="sip:t...@127.0.0.1:5071" />
> </list>
> </resource-lists>]
>
> Regards
> Aayush
>
> read more »
Jean Deruelle
Sep 12, 2008, 10:21:45 AM9/12/08
to mobicent...@googlegroups.com
Hi,
It seems that the underlying jain sip stack cannot create a new server
transaction for your notify and that you goes into this line
(http://code.google.com/p/mobicents/source/browse/tags/sip-servlets/release-0.5/sip-servlets-impl/src/main/java/org/mobicents/servlet/sip/core/SipApplicationDispatcherImpl.java#368)
that send a 500 back since no transaction could be created. You can
notice in the logs you sent me that logging line
(http://code.google.com/p/mobicents/source/browse/tags/sip-servlets/release-0.5/sip-servlets-impl/src/main/java/org/mobicents/servlet/sip/core/SipApplicationDispatcherImpl.java#376)
displayed for the failing incoming NOTIFY but you can see it for other
successful incoming NOTIFY.
When looking through the log I can also see this "could not find
subscribe tx", which comes from the underlying jain sip stack which
lead to another piece of code (DialogFilter:742 ->
SipTransactionStack:706) in jain sip stack looking for the Event
header.
Actually it seems to be a race condition for the dialog creation it
seems that the NOTIFY arrives faster that dialog is created (in
response to the 200 OK to subscribe) so since the dialog is not
created yet, jsip stack looks for the corresponding subscribe
transaction to the NOTIFY but since no event header is present it
cannot get it.
So as mentionned by aayush, if you add the Event header that might
lead to a well behaving application.
Best regards
Jean
Jean Deruelle
Sep 12, 2008, 10:22:07 AM9/12/08
to mobicent...@googlegroups.com
and sorry for the long delayed anwser....
aayush bhatnagar
Sep 12, 2008, 11:04:47 AM9/12/08
to mobicent...@googlegroups.com
Another thing...that i find interesting...in the JAIN SIP stack code.
There is a class SipDialog.java, where a dialog initiated by a
SUBSCRIBE is being created only when the NOTIFY is received by the
stack. Should this be another possible reason for the race condition?
I might sound confused :( sorry for that.
There is a class SipDialog.java, where a dialog initiated by a
SUBSCRIBE is being created only when the NOTIFY is received by the
stack. Should this be another possible reason for the race condition?
I might sound confused :( sorry for that.
Jean Deruelle
Sep 12, 2008, 11:12:10 AM9/12/08
to mobicent...@googlegroups.com
I think this is exactly in the case of where the Notify came in before
a response could be assigned to the subscribe.
It grabs the default dialog and assign it to the tags in the notify.
But in this case it could find the original subscribe transaction
(that is the Event Header is present in the NOTIFY and matches the oen
from the SUBSCRIBE)
a response could be assigned to the subscribe.
It grabs the default dialog and assign it to the tags in the notify.
But in this case it could find the original subscribe transaction
(that is the Event Header is present in the NOTIFY and matches the oen
from the SUBSCRIBE)
aayush bhatnagar
Sep 12, 2008, 11:30:26 AM9/12/08
to mobicent...@googlegroups.com
Hmmm. But if i remember correctly from rfc 3265..the dialog should be
created as soon as the 200 ok from the SUBSCRIBE is received.
created as soon as the 200 ok from the SUBSCRIBE is received.
I dont get why the stack waits for the NOTIFY to come for dialog creation.
Suppose..the 200 ok for the SUBSCRIBE was lost in transit, but the
NOTIFY reached the client...then the client will keep retransmitting
the SUBSCRIBE until Timer F fires. I dont know what will happen to the
dialog related behaviour of the stack then :)
Jean Deruelle
Sep 12, 2008, 11:34:42 AM9/12/08
to mobicent...@googlegroups.com
In this case the 200 OK has not yet been processed by the stack
From RFC 3265 : "3.3.4. Dialog creation and termination
From RFC 3265 : "3.3.4. Dialog creation and termination
If an initial SUBSCRIBE request is not sent on a pre-existing dialog,
the subscriber will wait for a response to the SUBSCRIBE request or a
matching NOTIFY."
Please note the "or a matching notify" part.
On Fri, Sep 12, 2008 at 5:30 PM, aayush bhatnagar
aayush bhatnagar
Sep 12, 2008, 11:39:00 AM9/12/08
to mobicent...@googlegroups.com
Yes :)
Matching notify does the trick.
Matching notify does the trick.
narfice
Sep 14, 2008, 1:34:47 PM9/14/08
to mobicents-public
Hi
Thanks for the responses! I added the Event: header, which I think may
have solved it - I wasn't able to test it thoroughly only with that
change. It does however seem to run perfectly now, the 500 Server
Internal Errors have disappeared entirely, judging by the tests I've
managed to throw at it.
With regard to the possible "race condition" - I have been running all
entities together on the same machine, so responses would have been
very quick sometimes - should I possibly build a slight delay into the
sipp scenarios, for tests on the same machine? I guess running them on
separate machines would probably remove that problem?
I'm running on mobicents tomcat 5.0 still - I tried out mobicents
tomcat 5.1 (with the same .war file) and got initialisation errors for
my server. I've included two of the error traces below, and can send
through the full log file if you need. The initialisation code for my
server I think I took from one of the example applications, but added
mine to the end of this as well.
Wireshark also shows numerous repeated frames for SUBSCRIBE messages
from the server - the dialogs get handled successfully (they cause
errors on sipp, which receives messages for 'dead' threads), and they
aren't generated by my code - is there any reason they would carry on
being sent? Are they likely to be from the container, or something
possibly misbehaving in the container?
Thanks for the reply, it finally looks like it may 100% finished now!
mike
2008/09/14 6:22:08 PM org.apache.catalina.core.StandardContext
loadOnStartup
SEVERE: Servlet /signal-servlet threw load() exception
javax.naming.NameNotFoundException: Name SipFactory is not bound in
this Context
at org.apache.naming.NamingContext.lookup(NamingContext.java:770)
at org.apache.naming.NamingContext.lookup(NamingContext.java:140)
at org.apache.naming.NamingContext.lookup(NamingContext.java:781)
at org.apache.naming.NamingContext.lookup(NamingContext.java:153)
at za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:
65)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:
1161)
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:
981)
at
org.mobicents.servlet.sip.startup.loading.SipServletImpl.load(SipServletImpl.java:
42)
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:
4045)
at
org.mobicents.servlet.sip.startup.SipStandardContext.loadOnStartup(SipStandardContext.java:
501)
at
org.apache.catalina.core.StandardContext.start(StandardContext.java:
4351)
at
org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:
253)
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:
791)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:
771)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:
525)
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:
825)
at
org.mobicents.servlet.sip.startup.SipHostConfig.deploySAR(SipHostConfig.java:
79)
at
org.mobicents.servlet.sip.startup.SipHostConfig.deployWARs(SipHostConfig.java:
145)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:
490)
at
org.mobicents.servlet.sip.startup.SipHostConfig.deployApps(SipHostConfig.java:
50)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1138)
at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:
311)
at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:
117)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:
1053)
at org.apache.catalina.core.StandardHost.start(StandardHost.java:719)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:
1045)
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:
443)
at
org.apache.catalina.core.StandardService.start(StandardService.java:
516)
at
org.mobicents.servlet.sip.startup.SipStandardService.start(SipStandardService.java:
127)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:
710)
at org.apache.catalina.startup.Catalina.start(Catalina.java:566)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
2008-09-14 18:22:08,239 INFO main
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:
326) - the following sip servlet application has been added :
SignalServlet
and
(SipApplicationDispatcherImpl.java:264) - Cannot allocate the servlet
za.ac.uct.ee.crg.sipservlet.SignalServlet for notifying the listener
that it has been initialized
javax.servlet.ServletException: Uh oh -- JNDI problem !
at za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:
69)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:
1161)
at
org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:
806)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.notifySipServletsListeners(SipApplicationDispatcherImpl.java:
255)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.start(SipApplicationDispatcherImpl.java:
226)
at
org.mobicents.servlet.sip.startup.SipStandardService.start(SipStandardService.java:
166)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:
710)
at org.apache.catalina.startup.Catalina.start(Catalina.java:566)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
Caused by: javax.naming.NameNotFoundException: Name comp is not bound
in this Context
at org.apache.naming.NamingContext.lookup(NamingContext.java:770)
at org.apache.naming.NamingContext.lookup(NamingContext.java:153)
at org.apache.naming.SelectorContext.lookup(SelectorContext.java:137)
at javax.naming.InitialContext.lookup(InitialContext.java:351)
at za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:
64)
... 13 more
2008/09/14 6:22:15 PM org.apache.catalina.startup.Catalina start
Initialisation from my code:
public class SignalServlet extends SipServlet {
private static Log logger =
LogFactory.getLog(SignalServlet.class);
public SipFactory factory;
// These declarations included to allow logging of server address
public static String SERVER_ADDRESS = "serverAddress";
public String serverAddress;
TimeAggregationPeriodicThread timer = new
TimeAggregationPeriodicThread();
String aggregationMethodIndicator = "time";
int maxPresenceSize = 1200; // Upper bound for presence size
for size aggregation
int maxPresentitiesReceived = 3; // Upper bound for number of
presentities received for quantity aggregation
int threadDelay = 10000;
int threadPeriod = 20000;
/* aggregationMethodIndicator determines the aggregation method used
in the server. The options to use are:
"time"
"quantity"
"size"
*/
// TODO RFC 3265 Section 3.1.1 --> 3.3.6
@Override
public void init(ServletConfig servletConfig) throws
javax.servlet.ServletException {
super.init(servletConfig);
logger.info("The chat room sip servlet has been started ! ");
try {
// Getting the Sip factory from the JNDI Context
Properties jndiProps = new Properties();
Context initCtx = new InitialContext(jndiProps);
Context envCtx = (Context) initCtx.lookup("java:comp/
env");
factory = (SipFactory) envCtx.lookup("sip/SipFactory");
// resource.setFactory(factory);
logger.info("Sip Factory ref from JNDI : " + factory);
} catch (NamingException e) {
throw new ServletException("Uh oh -- JNDI problem !", e);
}
// TODO make a way to set the aggregation method using an
incoming message, and clear all data
serverAddress =
getServletConfig().getInitParameter(SERVER_ADDRESS);
logger.info("serverAddress is : " + serverAddress);
}
On Sep 12, 5:39 pm, "aayush bhatnagar" <abhatnagar192...@gmail.com>
wrote:
> ...
>
> read more »
Thanks for the responses! I added the Event: header, which I think may
have solved it - I wasn't able to test it thoroughly only with that
change. It does however seem to run perfectly now, the 500 Server
Internal Errors have disappeared entirely, judging by the tests I've
managed to throw at it.
With regard to the possible "race condition" - I have been running all
entities together on the same machine, so responses would have been
very quick sometimes - should I possibly build a slight delay into the
sipp scenarios, for tests on the same machine? I guess running them on
separate machines would probably remove that problem?
I'm running on mobicents tomcat 5.0 still - I tried out mobicents
tomcat 5.1 (with the same .war file) and got initialisation errors for
my server. I've included two of the error traces below, and can send
through the full log file if you need. The initialisation code for my
server I think I took from one of the example applications, but added
mine to the end of this as well.
Wireshark also shows numerous repeated frames for SUBSCRIBE messages
from the server - the dialogs get handled successfully (they cause
errors on sipp, which receives messages for 'dead' threads), and they
aren't generated by my code - is there any reason they would carry on
being sent? Are they likely to be from the container, or something
possibly misbehaving in the container?
Thanks for the reply, it finally looks like it may 100% finished now!
mike
2008/09/14 6:22:08 PM org.apache.catalina.core.StandardContext
loadOnStartup
SEVERE: Servlet /signal-servlet threw load() exception
javax.naming.NameNotFoundException: Name SipFactory is not bound in
this Context
at org.apache.naming.NamingContext.lookup(NamingContext.java:770)
at org.apache.naming.NamingContext.lookup(NamingContext.java:140)
at org.apache.naming.NamingContext.lookup(NamingContext.java:781)
at org.apache.naming.NamingContext.lookup(NamingContext.java:153)
at za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:
65)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:
1161)
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:
981)
at
org.mobicents.servlet.sip.startup.loading.SipServletImpl.load(SipServletImpl.java:
42)
at
org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:
4045)
at
org.mobicents.servlet.sip.startup.SipStandardContext.loadOnStartup(SipStandardContext.java:
501)
at
org.apache.catalina.core.StandardContext.start(StandardContext.java:
4351)
at
org.mobicents.servlet.sip.startup.SipStandardContext.start(SipStandardContext.java:
253)
at
org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:
791)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:
771)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:
525)
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:
825)
at
org.mobicents.servlet.sip.startup.SipHostConfig.deploySAR(SipHostConfig.java:
79)
at
org.mobicents.servlet.sip.startup.SipHostConfig.deployWARs(SipHostConfig.java:
145)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:
490)
at
org.mobicents.servlet.sip.startup.SipHostConfig.deployApps(SipHostConfig.java:
50)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1138)
at
org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:
311)
at
org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:
117)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:
1053)
at org.apache.catalina.core.StandardHost.start(StandardHost.java:719)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:
1045)
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:
443)
at
org.apache.catalina.core.StandardService.start(StandardService.java:
516)
at
org.mobicents.servlet.sip.startup.SipStandardService.start(SipStandardService.java:
127)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:
710)
at org.apache.catalina.startup.Catalina.start(Catalina.java:566)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
2008-09-14 18:22:08,239 INFO main
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.addSipApplication(SipApplicationDispatcherImpl.java:
326) - the following sip servlet application has been added :
SignalServlet
and
(SipApplicationDispatcherImpl.java:264) - Cannot allocate the servlet
za.ac.uct.ee.crg.sipservlet.SignalServlet for notifying the listener
that it has been initialized
javax.servlet.ServletException: Uh oh -- JNDI problem !
at za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:
69)
at
org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:
1161)
at
org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:
806)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.notifySipServletsListeners(SipApplicationDispatcherImpl.java:
255)
at
org.mobicents.servlet.sip.core.SipApplicationDispatcherImpl.start(SipApplicationDispatcherImpl.java:
226)
at
org.mobicents.servlet.sip.startup.SipStandardService.start(SipStandardService.java:
166)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:
710)
at org.apache.catalina.startup.Catalina.start(Catalina.java:566)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
Caused by: javax.naming.NameNotFoundException: Name comp is not bound
in this Context
at org.apache.naming.NamingContext.lookup(NamingContext.java:770)
at org.apache.naming.NamingContext.lookup(NamingContext.java:153)
at org.apache.naming.SelectorContext.lookup(SelectorContext.java:137)
at javax.naming.InitialContext.lookup(InitialContext.java:351)
at za.ac.uct.ee.crg.sipservlet.SignalServlet.init(SignalServlet.java:
64)
... 13 more
2008/09/14 6:22:15 PM org.apache.catalina.startup.Catalina start
Initialisation from my code:
public class SignalServlet extends SipServlet {
private static Log logger =
LogFactory.getLog(SignalServlet.class);
public SipFactory factory;
// These declarations included to allow logging of server address
public static String SERVER_ADDRESS = "serverAddress";
public String serverAddress;
TimeAggregationPeriodicThread timer = new
TimeAggregationPeriodicThread();
String aggregationMethodIndicator = "time";
int maxPresenceSize = 1200; // Upper bound for presence size
for size aggregation
int maxPresentitiesReceived = 3; // Upper bound for number of
presentities received for quantity aggregation
int threadDelay = 10000;
int threadPeriod = 20000;
/* aggregationMethodIndicator determines the aggregation method used
in the server. The options to use are:
"time"
"quantity"
"size"
*/
// TODO RFC 3265 Section 3.1.1 --> 3.3.6
@Override
public void init(ServletConfig servletConfig) throws
javax.servlet.ServletException {
super.init(servletConfig);
logger.info("The chat room sip servlet has been started ! ");
try {
// Getting the Sip factory from the JNDI Context
Properties jndiProps = new Properties();
Context initCtx = new InitialContext(jndiProps);
Context envCtx = (Context) initCtx.lookup("java:comp/
env");
factory = (SipFactory) envCtx.lookup("sip/SipFactory");
// resource.setFactory(factory);
logger.info("Sip Factory ref from JNDI : " + factory);
} catch (NamingException e) {
throw new ServletException("Uh oh -- JNDI problem !", e);
}
// TODO make a way to set the aggregation method using an
incoming message, and clear all data
serverAddress =
getServletConfig().getInitParameter(SERVER_ADDRESS);
logger.info("serverAddress is : " + serverAddress);
}
On Sep 12, 5:39 pm, "aayush bhatnagar" <abhatnagar192...@gmail.com>
wrote:
> Yes :)
> Matching notify does the trick.
>
> Matching notify does the trick.
>
> On 9/12/08, Jean Deruelle <jean.derue...@gmail.com> wrote:
>
>
>
> > In this case the 200 OK has not yet been processed by the stack
> > From RFC 3265 : "3.3.4. Dialog creation and termination
>
> > If an initial SUBSCRIBE request is not sent on a pre-existing dialog,
> > the subscriber will wait for a response to the SUBSCRIBE request or a
> > matching NOTIFY."
>
> > Please note the "or a matching notify" part.
>
> > On Fri, Sep 12, 2008 at 5:30 PM, aayush bhatnagar
> > <abhatnagar192...@gmail.com> wrote:
>
> >> Hmmm. But if i remember correctly from rfc 3265..the dialog should be
> >> created as soon as the 200 ok from the SUBSCRIBE is received.
>
> >> I dont get why the stack waits for the NOTIFY to come for dialog creation.
>
> >> Suppose..the 200 ok for the SUBSCRIBE was lost in transit, but the
> >> NOTIFY reached the client...then the client will keep retransmitting
> >> the SUBSCRIBE until Timer F fires. I dont know what will happen to the
> >> dialog related behaviour of the stack then :)
>
>
>
>
> > In this case the 200 OK has not yet been processed by the stack
> > From RFC 3265 : "3.3.4. Dialog creation and termination
>
> > If an initial SUBSCRIBE request is not sent on a pre-existing dialog,
> > the subscriber will wait for a response to the SUBSCRIBE request or a
> > matching NOTIFY."
>
> > Please note the "or a matching notify" part.
>
> > On Fri, Sep 12, 2008 at 5:30 PM, aayush bhatnagar
> > <abhatnagar192...@gmail.com> wrote:
>
> >> Hmmm. But if i remember correctly from rfc 3265..the dialog should be
> >> created as soon as the 200 ok from the SUBSCRIBE is received.
>
> >> I dont get why the stack waits for the NOTIFY to come for dialog creation.
>
> >> Suppose..the 200 ok for the SUBSCRIBE was lost in transit, but the
> >> NOTIFY reached the client...then the client will keep retransmitting
> >> the SUBSCRIBE until Timer F fires. I dont know what will happen to the
> >> dialog related behaviour of the stack then :)
>
> >> On 9/12/08, Jean Deruelle <jean.derue...@gmail.com> wrote:
>
> >>> I think this is exactly in the case of where the Notify came in before
> >>> a response could be assigned to the subscribe.
> >>> It grabs the default dialog and assign it to the tags in the notify.
> >>> But in this case it could find the original subscribe transaction
> >>> (that is the Event Header is present in the NOTIFY and matches the oen
> >>> from the SUBSCRIBE)
>
> >>> On Fri, Sep 12, 2008 at 5:04 PM, aayush bhatnagar
> >>> <abhatnagar192...@gmail.com> wrote:
>
> >>>> Another thing...that i find interesting...in the JAIN SIP stack code.
> >>>> There is a class SipDialog.java, where a dialog initiated by a
> >>>> SUBSCRIBE is being created only when the NOTIFY is received by the
> >>>> stack. Should this be another possible reason for the race condition?
> >>>> I might sound confused :( sorry for that.
>
>
> >>> I think this is exactly in the case of where the Notify came in before
> >>> a response could be assigned to the subscribe.
> >>> It grabs the default dialog and assign it to the tags in the notify.
> >>> But in this case it could find the original subscribe transaction
> >>> (that is the Event Header is present in the NOTIFY and matches the oen
> >>> from the SUBSCRIBE)
>
> >>> On Fri, Sep 12, 2008 at 5:04 PM, aayush bhatnagar
> >>> <abhatnagar192...@gmail.com> wrote:
>
> >>>> Another thing...that i find interesting...in the JAIN SIP stack code.
> >>>> There is a class SipDialog.java, where a dialog initiated by a
> >>>> SUBSCRIBE is being created only when the NOTIFY is received by the
> >>>> stack. Should this be another possible reason for the race condition?
> >>>> I might sound confused :( sorry for that.
>
> >>>> On 9/12/08, Jean Deruelle <jean.derue...@gmail.com> wrote:
>
> >>>>> and sorry for the long delayed anwser....
>
> >>>>> On Fri, Sep 12, 2008 at 4:21 PM, Jean Deruelle
> >>>>> <jean.derue...@gmail.com>
>
> >>>>> and sorry for the long delayed anwser....
>
> >>>>> On Fri, Sep 12, 2008 at 4:21 PM, Jean Deruelle
> >>>>> wrote:
> >>>>>> Hi,
>
> >>>>>> It seems that the underlying jain sip stack cannot create a new server
> >>>>>> transaction for your notify and that you goes into this line
> >>>>>> (http://code.google.com/p/mobicents/source/browse/tags/sip-servlets/re...)
> >>>>>> Hi,
>
> >>>>>> It seems that the underlying jain sip stack cannot create a new server
> >>>>>> transaction for your notify and that you goes into this line
> >>>>>> that send a 500 back since no transaction could be created. You can
> >>>>>> notice in the logs you sent me that logging line
> >>>>>> (http://code.google.com/p/mobicents/source/browse/tags/sip-servlets/re...)
> >>>>>> notice in the logs you sent me that logging line
>
> read more »
Vladimir Ralev
Sep 14, 2008, 3:38:40 PM9/14/08
to mobicent...@googlegroups.com
There's been a change in the JNDI location of the sip factory for 0.5.1. I think it is in sip/appname/SipFactory now, however it's much better if you just use resource injection by declaring your sipFactory like this:
@Resource
private static SipFactory sipFactory;
Nothing else is required.
@Resource
private static SipFactory sipFactory;
Nothing else is required.
Jean Deruelle
Sep 15, 2008, 3:52:33 AM9/15/08
to mobicent...@googlegroups.com
Vlad is right. JNDI has changed to be more JSR 289 compliant.
Regarding the sipp delay you can add this after the lines that send
the 200 OK in your sipp script : <pause milliseconds="500"/>
Regarding the sipp delay you can add this after the lines that send
the 200 OK in your sipp script : <pause milliseconds="500"/>
Jean
Reply all
Reply to author
Forward
0 new messages