(0 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent1_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent1_debug.txt, sipunit.test.port=5071} ] (11 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (12 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (14 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (16 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (55 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (233 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5071 transport = udp] (234 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@9845fb listeningPoint = gov.nist.javax.sip.ListeningPointImpl@1a791f] (234 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@1a791f] (242 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@48cd13] (246 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent2_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent2, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent2_debug.txt, sipunit.test.port=5072} ] (247 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (247 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (248 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (248 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (249 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (249 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (250 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5072 transport = udp] (250 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@5fa713 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@d1e07c] (252 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@d1e07c] (252 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@e90e23] (254 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent3_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent3, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent3_debug.txt, sipunit.test.port=5073} ] (254 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (255 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (255 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (256 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (256 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (258 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (258 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5073 transport = udp] (263 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@9f2588 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@590510] (264 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@590510] (264 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@5b6d00] (515 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 creating a new one ] (517 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:209) [NextHop based on Route:127.0.0.1:5060/udp] (518 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(c36d5277b3d547748733eb0f256e7aee@192.168.0.145:340633308) : returning null] (520 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (529 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (540 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipSession.java:1116][SipSession.java:999][TestBase.java:977][TestBase.java:664][TestBase.java:627][SipSessionListenerTest.java:44][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (542 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2] (547 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2] (547 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2] (550 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (552 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendRequest(SIPClientTransaction.java:918) [sendRequest() MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 ] (555 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 ] (558 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (559 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2] (559 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b branchID = z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 isClient = true] (559 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:470][SIPClientTransaction.java:977][SipSession.java:1197][SipSession.java:1116][SipSession.java:999][TestBase.java:977][TestBase.java:664][TestBase.java:627][SipSessionListenerTest.java:44][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (560 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b tickCount 64 currentTickCount = -1] (561 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPClientTransaction.java:977][SipSession.java:1197][SipSession.java:1116][SipSession.java:999][TestBase.java:977][TestBase.java:664][TestBase.java:627][SipSessionListenerTest.java:44][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (567 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.0.1/5060 MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 ] (568 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (570 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (571 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (571 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="127.0.0.1:5060" time="1223303200551" isSender="true" transactionId="z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2" callId="c36d5277b3d547748733eb0f256e7aee@192.168.0.145" firstLine="MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (571 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (573 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (894 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (895 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 315] (895 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 408 Request Timeout To: Bob <sip:bob@192.168.0.145:5072>;tag=n0xcr6 Content-Length: 0 CSeq: 1 INVITE Call-ID: 5bbb80f112d69ce3d9572cefc7de2277@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe70adf5124c39b16590d66062931df3c From: Alice <sip:alice@192.168.0.145:5071>;tag=1677572739 ] (900 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (900 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (901 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:62253" to="192.168.0.145:5071" time="1223303200890" isSender="false" transactionId="z9hg4bke70adf5124c39b16590d66062931df3c" callId="5bbb80f112d69ce3d9572cefc7de2277@192.168.0.145" firstLine="SIP/2.0 408 Request Timeout" > <![CDATA[SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=n0xcr6 CSeq: 1 INVITE Call-ID: 5bbb80f112d69ce3d9572cefc7de2277@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe70adf5124c39b16590d66062931df3c From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1677572739 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (901 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (903 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (903 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bke70adf5124c39b16590d66062931df3c] (908 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction null for SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=n0xcr6 CSeq: 1 INVITE Call-ID: 5bbb80f112d69ce3d9572cefc7de2277@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe70adf5124c39b16590d66062931df3c From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1677572739 Content-Length: 0 ] (912 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(5bbb80f112d69ce3d9572cefc7de2277@192.168.0.145:1677572739:n0xcr6) : returning null] (913 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1098) [PROCESSING INCOMING RESPONSE: SIP/2.0 408 Request Timeout To: "Bob" <sip:bob@192.168.0.145:5072>;tag=n0xcr6 CSeq: 1 INVITE Call-ID: 5bbb80f112d69ce3d9572cefc7de2277@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe70adf5124c39b16590d66062931df3c From: "Alice" <sip:alice@192.168.0.145:5071>;tag=1677572739 Content-Length: 0 ] (913 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1142) [Transaction = null sipDialog = null] (913 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (927 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2192a9 lastResponse = SIP/2.0 408 Request Timeout ] (928 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPDialog.java:345][DialogFilter.java:1173][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (934 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (934 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (934 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = null] (935 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 408] (935 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = null] (935 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (936 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:359) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@2192a9] (936 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:360][DialogFilter.java:1173][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (936 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:1224) [sending response to TU for processing ] (936 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@2192a9 lastResponse = SIP/2.0 408 Request Timeout ] (937 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1229][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (937 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (937 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (938 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (938 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 408] (939 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = null] (939 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (941 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@2192a9newState = 3] (941 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][DialogFilter.java:1229][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (941 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@2192a9 old dialog state is Early Dialog] (942 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@2192a9 New dialog state is Terminated Dialog] (942 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@c8c6d9]currentTransaction = nullthis.sipListener = org.cafesip.sipunit.SipStack@48cd13sipEvent.source = gov.nist.javax.sip.SipProviderImpl@c8c6d9] (942 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@2192a9] (942 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1235][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (943 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@a4effe] (948 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@a4effenevents 1] (949 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@c8c6d9]source = gov.nist.javax.sip.SipProviderImpl@c8c6d9] (949 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 408 Request Timeout ] (1076 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:1015][SIPTransaction.java:644][SIPClientTransaction.java:268][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (1077 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.0.1/5060 MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 ] (1077 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (1079 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (1079 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (1079 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="127.0.0.1:5060" time="1223303201067" isSender="true" transactionId="z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2" callId="c36d5277b3d547748733eb0f256e7aee@192.168.0.145" firstLine="MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (1080 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (1080 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (2077 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:1015][SIPTransaction.java:644][SIPClientTransaction.java:268][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (2080 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.0.1/5060 MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 ] (2080 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (2081 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (2082 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (2083 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="127.0.0.1:5060" time="1223303202068" isSender="true" transactionId="z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2" callId="c36d5277b3d547748733eb0f256e7aee@192.168.0.145" firstLine="MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[MESSAGE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 CSeq: 1 MESSAGE From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 Max-Forwards: 5 Route: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060;lr>,<sip:127.0.0.1:5060;lr;transport=udp> Application-Name: com.bea.sipservlet.tck.apps.apitestapp Servlet-Name: SipSessionListener Method-Name: testSessionCreated001 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (2084 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (2084 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (2575 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (2575 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 312] (2576 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: JSR289_TCK <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe Content-Length: 0 CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: Alice <sip:alice@192.168.0.145:5071>;tag=340633308 ] (2576 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (2576 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 312] (2576 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2577 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (2577 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (2578 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (2580 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (2577 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: JSR289_TCK <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe Content-Length: 0 CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: Alice <sip:alice@192.168.0.145:5071>;tag=340633308 ] (2581 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (2582 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223303202568" isSender="false" transactionId="z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2" callId="c36d5277b3d547748733eb0f256e7aee@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (2582 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (2582 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (2583 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2583 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (2581 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 312] (2583 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: JSR289_TCK <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe Content-Length: 0 CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: Alice <sip:alice@192.168.0.145:5071>;tag=340633308 ] (2583 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2] (2584 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 ] (2585 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b to gov.nist.javax.sip.DialogFilter@8bd37a] (2584 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2588 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (2589 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (2589 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 ] (2589 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2590 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@c8c6d9]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@950ce23bthis.sipListener = org.cafesip.sipunit.SipStack@48cd13sipEvent.source = gov.nist.javax.sip.SipProviderImpl@c8c6d9] (2590 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (2590 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:638][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (2590 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@e90906] (2591 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b branchID = z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 isClient = true] (2591 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:644][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (2591 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b tickCount 10 currentTickCount = 60] (2589 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (2593 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2593 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (2594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (2594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (2594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (2594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223303202585" isSender="false" transactionId="z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2" callId="c36d5277b3d547748733eb0f256e7aee@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (2595 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (2595 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (2595 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2] (2595 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 ] (2596 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b to gov.nist.javax.sip.DialogFilter@4f79cb] (2596 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Completed Transaction] (2593 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@e90906nevents 1] (2597 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@c8c6d9]source = gov.nist.javax.sip.SipProviderImpl@c8c6d9] (2598 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (2599 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (2599 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2599 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][EventScanner.java:362][EventScanner.java:492][Thread.java:613]] (2597 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (2600 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.nonInviteClientTransaction(SIPClientTransaction.java:676) [ Not sending response to TU! Completed Transaction] (2600 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2601 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPClientTransaction.java:679][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (2601 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2601 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (2602 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (2602 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (2602 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223303202592" isSender="false" transactionId="z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2" callId="c36d5277b3d547748733eb0f256e7aee@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (2603 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (2604 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (2604 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk40a1fdcb8198be1c3ff87481b2e331c2] (2604 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqd4fe CSeq: 1 MESSAGE Call-ID: c36d5277b3d547748733eb0f256e7aee@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK40a1fdcb8198be1c3ff87481b2e331c2 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=340633308 Content-Length: 0 ] (2603 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (2605 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b to gov.nist.javax.sip.DialogFilter@16e5d6] (2605 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Completed Transaction] (2605 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (2606 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.nonInviteClientTransaction(SIPClientTransaction.java:676) [ Not sending response to TU! Completed Transaction] (2606 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (2610 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2611 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPClientTransaction.java:679][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (2611 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@950ce23b] (2612 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (2606 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (2613 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (3614 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (3614 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (3615 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (4615 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (4615 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (4617 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (5621 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (5622 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (5623 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5071 transport = udp] (5624 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@29645a listeningPoint = gov.nist.javax.sip.ListeningPointImpl@7b7b5d] (5625 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@7b7b5d] (5625 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@e038c4] (5626 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (5626 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (5627 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5072 transport = udp] (5627 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@aee908 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@4510ac] (5628 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@4510ac] (5629 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@499616] (5629 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (5629 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (5630 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5073 transport = udp] (5631 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@1c8c58 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@422510] (5631 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@422510] (5631 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@8f5944] (5638 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 creating a new one ] (5639 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:209) [NextHop based on Route:127.0.0.1:5060/udp] (5639 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994) : returning null] (5640 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (5640 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (5642 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][TestBase.java:807][SipSessionListenerTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5642 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKf005b0081a8f134e1ba4043bb3a52830] (5642 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bkf005b0081a8f134e1ba4043bb3a52830] (5643 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKf005b0081a8f134e1ba4043bb3a52830] (5643 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (5643 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (5644 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (5644 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@7667bd1849850994/null] (5645 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkf005b0081a8f134e1ba4043bb3a52830/false] (5646 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][TestBase.java:807][SipSessionListenerTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5646 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@7667bd] (5646 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (5647 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][TestBase.java:807][SipSessionListenerTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5647 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994sipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5648 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendRequest(SIPClientTransaction.java:918) [sendRequest() INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1849850994 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 Max-Forwards: 70 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: SipSessionListener Method-Name: testSessionReadyToInvalidate001 Application-Name: com.bea.sipservlet.tck.apps.apitestapp Content-Length: 0 ] (5649 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1849850994 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 Max-Forwards: 70 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: SipSessionListener Method-Name: testSessionReadyToInvalidate001 Application-Name: com.bea.sipservlet.tck.apps.apitestapp Content-Length: 0 ] (5649 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (5649 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKf005b0081a8f134e1ba4043bb3a52830] (5650 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Calling Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474 branchID = z9hG4bKf005b0081a8f134e1ba4043bb3a52830 isClient = true] (5650 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:464][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][TestBase.java:807][SipSessionListenerTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5650 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474 tickCount 64 currentTickCount = -1] (5656 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][TestBase.java:807][SipSessionListenerTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5657 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.0.1/5060 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1849850994 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 Max-Forwards: 70 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: SipSessionListener Method-Name: testSessionReadyToInvalidate001 Application-Name: com.bea.sipservlet.tck.apps.apitestapp Content-Length: 0 ] (5657 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (5658 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:273) [Here are the stack configuration properties {sipunit.proxy.host=127.0.0.1, sipunit.test.protocol=udp, gov.nist.javax.sip.READ_TIMEOUT=1000, gov.nist.javax.sip.SERVER_LOG=testAgent1_log.txt, sipunit.proxy.port=5060, javax.sip.RETRANSMISSION_FILTER=true, gov.nist.javax.sip.TRACE_LEVEL=32, javax.sip.STACK_NAME=testAgent, sipunit.test.domain=192.168.0.145, sipunit.trace=true, gov.nist.javax.sip.DEBUG_LOG=testAgent1_debug.txt, sipunit.test.port=5071} ] (5658 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (5659 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (5660 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (5661 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (5661 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (5661 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (5661 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 339] (5662 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 From: <sip:alice@192.168.0.145>;tag=1849850994 ] (5662 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5662 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5663 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5663 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="127.0.0.1:5060" time="1223303205642" isSender="true" transactionId="z9hg4bkf005b0081a8f134e1ba4043bb3a52830" callId="531bea4128825f0baa1686c99148f6f4@192.168.0.145" firstLine="INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1849850994 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 Max-Forwards: 70 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: SipSessionListener Method-Name: testSessionReadyToInvalidate001 Application-Name: com.bea.sipservlet.tck.apps.apitestapp Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5663 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (5663 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5664 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (5664 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223303205656 INVITE after sending out through stack.......... SIPUNIT TRACE: 1223303205656 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1849850994 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 Max-Forwards: 70 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: SipSessionListener Method-Name: testSessionReadyToInvalidate001 Application-Name: com.bea.sipservlet.tck.apps.apitestapp Content-Length: 0 (5664 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] SIPUNIT TRACE: 1223303205656 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> (5665 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5665 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223303205655" isSender="false" transactionId="z9hg4bkf005b0081a8f134e1ba4043bb3a52830" callId="531bea4128825f0baa1686c99148f6f4@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5666 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5666 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5666 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bkf005b0081a8f134e1ba4043bb3a52830] (5667 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474 for SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 ] (5667 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474 to gov.nist.javax.sip.DialogFilter@7ee46a] (5667 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (5667 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@7667bd lastResponse = SIP/2.0 200 OK ] (5668 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5668 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (5668 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (5668 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (5669 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (5670 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5670 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (5670 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteTag(SIPDialog.java:1166) [setRemoteTag(): gov.nist.javax.sip.stack.SIPDialog@7667bd remoteTag = null new tag = 18oq2k] (5671 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2k dialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5671 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2186][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5671 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:533) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@7667bdstate = null] (5672 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:581][SIPDialog.java:2187][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5672 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@7667bdnewState = 1] (5672 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2189][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5672 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@7667bd old dialog state is null] (5673 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@7667bd New dialog state is Confirmed Dialog] (5673 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5673 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Calling Transaction] (5673 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5674 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@7667bd lastResponse = SIP/2.0 200 OK ] (5674 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5674 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (5674 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (5675 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (5675 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (5675 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5676 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (5676 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5676 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474 branchID = z9hG4bKf005b0081a8f134e1ba4043bb3a52830 isClient = true] (5677 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:787][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5677 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 ] (5677 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5677 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@7667bd lastResponse = SIP/2.0 200 OK ] (5678 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1065][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5678 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (5679 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (5679 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (5679 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (5679 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5680 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (5680 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5680 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@94d313]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474this.sipListener = org.cafesip.sipunit.SipStack@e038c4sipEvent.source = gov.nist.javax.sip.SipProviderImpl@94d313] (5680 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5680 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5681 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@749ebc] (5681 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5681 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@749ebcnevents 1] (5681 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (5682 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@94d313]source = gov.nist.javax.sip.SipProviderImpl@94d313] (5682 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (5682 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (5682 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:331) [Garbage collecting unacknowledged dialog] (5683 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b2c39474] (5683 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][EventScanner.java:362][EventScanner.java:492][Thread.java:613]] SIPUNIT TRACE: 1223303205675 Outgoing call response received: SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKf005b0081a8f134e1ba4043bb3a52830 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 (5685 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2k=gov.nist.javax.sip.stack.SIPDialog@7667bd} default dialog gov.nist.javax.sip.stack.SIPDialog@7667bd retval gov.nist.javax.sip.stack.SIPDialog@7667bd] (5787 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@7667bd] (5788 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (5788 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@7667bd] (5789 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (5790 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (5791 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (5791 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:633) [sendAckgov.nist.javax.sip.stack.SIPDialog@7667bd] (5792 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:658) [setting from tag For outgoing ACK= 1849850994] (5792 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:661) [setting To tag for outgoing ACK = 18oq2k] (5793 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:664) [ack = ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8c01f8e13f030b1782ff150455bc0e06 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 ] (5793 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:234) [Used request-URI for nextHop = 192.168.0.145:5060/udp] (5794 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:680) [hop = 192.168.0.145:5060/udp] (5795 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (5796 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPDialog.java:691][SIPDialog.java:1431][SipCall.java:3126][SipCall.java:3050][SipSessionListenerTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5797 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8c01f8e13f030b1782ff150455bc0e06 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 ] (5798 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (5799 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8c01f8e13f030b1782ff150455bc0e06 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 ] (5800 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5800 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5801 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223303205788" isSender="true" transactionId="z9hg4bk8c01f8e13f030b1782ff150455bc0e06" callId="531bea4128825f0baa1686c99148f6f4@192.168.0.145" firstLine="ACK sip:192.168.0.145:5060;transport=udp SIP/2.0" > <![CDATA[ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8c01f8e13f030b1782ff150455bc0e06 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5802 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5803 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5803 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@7667bd] (5804 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (5804 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@7667bd] (5805 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (5805 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (5806 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (5806 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 creating a new one ] (5808 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:234) [Used request-URI for nextHop = 192.168.0.145:5060/udp] (5810 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2k) : returning gov.nist.javax.sip.stack.SIPDialog@7667bd] (5811 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (5812 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (5813 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipCall.java:3605][SipCall.java:3547][SipSessionListenerTest.java:153][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5814 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK8b49526170e2ff1d61574e6512f0c832] (5816 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk8b49526170e2ff1d61574e6512f0c832] (5816 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK8b49526170e2ff1d61574e6512f0c832] (5819 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (5819 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5821 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1604) [dialog.sendRequest dialog = gov.nist.javax.sip.stack.SIPDialog@7667bd dialogRequest = BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 ] (5821 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5822 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@7667bd1849850994/18oq2k] (5823 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk8b49526170e2ff1d61574e6512f0c832/false] (5823 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:1652][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][SipSessionListenerTest.java:153][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5826 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (5828 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1785) [using message channel gov.nist.javax.sip.stack.UDPMessageChannel@347448] (5829 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 ] (5829 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (5829 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK8b49526170e2ff1d61574e6512f0c832] (5829 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb branchID = z9hG4bK8b49526170e2ff1d61574e6512f0c832 isClient = true] (5830 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:470][SIPDialog.java:1817][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][SipSessionListenerTest.java:153][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5830 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb tickCount 64 currentTickCount = -1] (5831 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPDialog.java:1817][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][SipSessionListenerTest.java:153][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5832 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 ] (5832 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (5833 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5833 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5833 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223303205821" isSender="true" transactionId="z9hg4bk8b49526170e2ff1d61574e6512f0c832" callId="531bea4128825f0baa1686c99148f6f4@192.168.0.145" firstLine="BYE sip:192.168.0.145:5060;transport=udp SIP/2.0" > <![CDATA[BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1849850994 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5834 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5834 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223303205826 SS.waitRequest() - about to block, waiting (5835 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (5836 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (5836 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 287] (5836 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 314] (5836 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k Content-Length: 0 CSeq: 2 BYE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 From: <sip:alice@192.168.0.145>;tag=1849850994 ] (5836 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 To: <sip:alice@192.168.0.145:5071;lr;transport=udp> Content-Length: 0 CSeq: 1 MESSAGE Test-Result: ok Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Max-Forwards: 70 ] (5839 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb] (5839 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (5839 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5839 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (5839 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5841 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223303205827" isSender="false" transactionId="z9hg4bktrmczh" callId="wk64ya" firstLine="MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0" > <![CDATA[MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Test-Result: ok Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5841 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5841 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5841 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5841 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5841 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223303205830" isSender="false" transactionId="z9hg4bk8b49526170e2ff1d61574e6512f0c832" callId="531bea4128825f0baa1686c99148f6f4@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k CSeq: 2 BYE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5841 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bktrmczh] (5842 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5842 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5842 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk8b49526170e2ff1d61574e6512f0c832] (5842 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb for SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k CSeq: 2 BYE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 ] (5842 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb to gov.nist.javax.sip.DialogFilter@284ac3] (5843 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (5844 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5844 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@7667bd lastResponse = SIP/2.0 200 OK ] (5844 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5845 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = BYE] (5845 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (5845 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (5845 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (5845 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb] (5845 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (5846 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@7667bdnewState = 3] (5846 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2254][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5846 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@7667bd old dialog state is Confirmed Dialog] (5846 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@7667bd New dialog state is Terminated Dialog] (5846 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (5846 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5847 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (5847 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k CSeq: 2 BYE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 ] (5847 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKtrmczh] (5847 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb] (5848 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( MESSAGE:z9hG4bKtrmczh):gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5848 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@7667bd lastResponse = SIP/2.0 200 OK ] (5848 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 gov.nist.javax.sip.DialogFilter@d35bf2 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5848 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (5848 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5848 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 531bea4128825f0baa1686c99148f6f4@192.168.0.145:1849850994:18oq2ksipDialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5849 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (5849 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@94d313]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@2837b0ebthis.sipListener = org.cafesip.sipunit.SipStack@e038c4sipEvent.source = gov.nist.javax.sip.SipProviderImpl@94d313] (5849 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (5849 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@7667bd] (5850 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5850 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:638][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5850 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (5850 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@398044] (5850 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (5851 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb branchID = z9hG4bK8b49526170e2ff1d61574e6512f0c832 isClient = true] (5851 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@398044nevents 1] (5851 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKtrmczh] (5851 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:644][SIPClientTransaction.java:547][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5851 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@94d313]source = gov.nist.javax.sip.SipProviderImpl@94d313] (5851 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01 branchID = z9hG4bKtrmczh isClient = false] (5851 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb tickCount 10 currentTickCount = 64] (5852 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (5852 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (5852 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb] (5852 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (5853 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] SIPUNIT TRACE: 1223303205846 Asynchronous response received: SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=18oq2k CSeq: 2 BYE Call-ID: 531bea4128825f0baa1686c99148f6f4@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK8b49526170e2ff1d61574e6512f0c832 From: <sip:alice@192.168.0.145>;tag=1849850994 Content-Length: 0 (5854 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (5855 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Test-Result: ok Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01 listening point = 192.168.0.145:5071] (5855 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@2837b0eb] (5855 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (5855 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][EventScanner.java:362][EventScanner.java:492][Thread.java:613]] (5856 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(wk64ya:112zd0) : returning null] (5856 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = wk64ya:112zd0] (5856 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (5856 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [MESSAGE transaction.isMapped = false] (5857 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@94d313]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01this.sipListener = org.cafesip.sipunit.SipStack@e038c4sipEvent.source = gov.nist.javax.sip.SipProviderImpl@94d313] (5857 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (5857 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (5858 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@141d19] (5858 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5858 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@141d19nevents 1] (5859 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@94d313]source = gov.nist.javax.sip.SipProviderImpl@94d313] (5859 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01 sipEvent.serverTx = null] (5859 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bktrmczh existing={}] (5859 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bktrmczh] (5859 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5860 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (5860 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] SIPUNIT TRACE: 1223303205851 SipStack: request received ! SIPUNIT TRACE: 1223303205851 SipStack: calling listener SIPUNIT TRACE: 1223303205851 SipSession: request received ! SIPUNIT TRACE: 1223303205851 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223303205851 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223303205851 MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Test-Result: ok Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223303205851 SipSession: notifying block object SIPUNIT TRACE: 1223303205851 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223303205851 SS.waitRequest() - either we got the request, or timed out (5860 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (5860 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message MESSAGE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (5861 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5861 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : MESSAGE returning false] (5861 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][EventScanner.java:254][EventScanner.java:492][Thread.java:613]] (5861 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bktrmczh existing={}] (5865 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bktrmczh] (5865 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01] (5866 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bktrmczh] (5867 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bktrmczh] (5867 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(wk64ya:112zd0) : returning null] SIPUNIT TRACE: 1223303205859 Response before sending out through stack.......... SIPUNIT TRACE: 1223303205859 SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Content-Length: 0 (5868 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01 branchID = z9hG4bKtrmczh isClient = false] (5869 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSessionListenerTest.java:184][SipSessionListenerTest.java:165][SipSessionListenerTest.java:155][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5869 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01 tickCount 64 currentTickCount = -1] (5870 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@f2343a01 getState = Completed Transaction] (5870 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (5871 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPServerTransaction.java:464][SIPServerTransaction.java:1099][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1657][SipSessionListenerTest.java:184][SipSessionListenerTest.java:165][SipSessionListenerTest.java:155][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5872 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Content-Length: 0 ] (5873 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (5873 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Content-Length: 0 ] (5873 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5874 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5875 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223303205863" isSender="true" transactionId="z9hg4bktrmczh" callId="wk64ya" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:alice@192.168.0.145:5071;lr;transport=udp> CSeq: 1 MESSAGE Call-ID: wk64ya Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKtrmczh From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=112zd0 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5875 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5875 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5876 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bktrmczh] (5876 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@7667bdnewState = 3] (5876 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:1334][SipCall.java:158][SipPhone.java:1231][TestBase.java:249][TestCase.java:130][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (5877 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (5877 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (5878 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (6878 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (6878 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (6879 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (7879 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (7879 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (7881 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]