(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} ] (9 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (9 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (10 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (10 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (13 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (47 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (240 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] (306 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@7aa2a8 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@4ce427] (307 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@4ce427] (316 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@e5c339] (319 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} ] (320 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (321 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (322 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (322 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (322 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (323 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (324 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] (325 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@162a9c listeningPoint = gov.nist.javax.sip.ListeningPointImpl@47a8f3] (325 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@47a8f3] (325 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@a4edc4] (327 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} ] (328 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (328 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (329 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (329 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (330 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (331 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (332 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] (332 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@f5eb7f listeningPoint = gov.nist.javax.sip.ListeningPointImpl@381a53] (332 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@381a53] (333 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@484a8a] (516 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for REGISTER sip:127.0.0.1 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(cba7a9e0e54090a60770e993c9896c4a@192.168.0.145:164206694) : 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] (527 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (529 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][ContactHeaderTest.java:166][ContactHeaderTest.java:76][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]] (530 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK2a74759911c6ca32b365d20b1560792b] (531 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk2a74759911c6ca32b365d20b1560792b] (531 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK2a74759911c6ca32b365d20b1560792b] (533 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : REGISTER returning false] (536 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendRequest(SIPClientTransaction.java:918) [sendRequest() REGISTER sip:127.0.0.1 SIP/2.0 Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 CSeq: 1 REGISTER From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 To: "Alice" <sip:alice@192.168.0.145:5071> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b Max-Forwards: 5 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 7200 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 ] (537 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message REGISTER sip:127.0.0.1 SIP/2.0 Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 CSeq: 1 REGISTER From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 To: "Alice" <sip:alice@192.168.0.145:5071> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b Max-Forwards: 5 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 7200 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 ] (538 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (538 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK2a74759911c6ca32b365d20b1560792b] (539 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@46ea41d9 branchID = z9hG4bK2a74759911c6ca32b365d20b1560792b isClient = true] (539 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][ContactHeaderTest.java:166][ContactHeaderTest.java:76][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]] (539 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9 tickCount 64 currentTickCount = -1] (541 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][ContactHeaderTest.java:166][ContactHeaderTest.java:76][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]] (543 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 REGISTER sip:127.0.0.1 SIP/2.0 Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 CSeq: 1 REGISTER From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 To: "Alice" <sip:alice@192.168.0.145:5071> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b Max-Forwards: 5 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 7200 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 ] (543 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (545 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (545 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (546 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="1223304433048" isSender="true" transactionId="z9hg4bk2a74759911c6ca32b365d20b1560792b" callId="cba7a9e0e54090a60770e993c9896c4a@192.168.0.145" firstLine="REGISTER sip:127.0.0.1 SIP/2.0" > <![CDATA[REGISTER sip:127.0.0.1 SIP/2.0 Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 CSeq: 1 REGISTER From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 To: "Alice" <sip:alice@192.168.0.145:5071> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b Max-Forwards: 5 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 7200 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (546 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (548 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (550 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (550 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 426] (551 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: Alice <sip:alice@192.168.0.145:5071>;tag=cujw0h Content-Length: 0 Contact: <sip:tck@sipservlet.com>;expires=3600 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 REGISTER Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b From: Alice <sip:alice@192.168.0.145:5071>;tag=164206694 ] (554 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9] (555 ms) [Thread-9] 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]] (555 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (557 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (557 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (557 ms) [Thread-9] 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="1223304433063" isSender="false" transactionId="z9hg4bk2a74759911c6ca32b365d20b1560792b" callId="cba7a9e0e54090a60770e993c9896c4a@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: "Alice" <sip:alice@192.168.0.145:5071>;tag=cujw0h Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 REGISTER Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (560 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (560 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (560 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk2a74759911c6ca32b365d20b1560792b] (560 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9 for SIP/2.0 200 OK To: "Alice" <sip:alice@192.168.0.145:5071>;tag=cujw0h Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 REGISTER Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 Content-Length: 0 ] (564 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9 to gov.nist.javax.sip.DialogFilter@154024] (565 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (565 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (565 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: "Alice" <sip:alice@192.168.0.145:5071>;tag=cujw0h Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 REGISTER Call-ID: cba7a9e0e54090a60770e993c9896c4a@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2a74759911c6ca32b365d20b1560792b From: "Alice" <sip:alice@192.168.0.145:5071>;tag=164206694 Content-Length: 0 ] (565 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9] (566 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@f32dde]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9this.sipListener = org.cafesip.sipunit.SipStack@e5c339sipEvent.source = gov.nist.javax.sip.SipProviderImpl@f32dde] (567 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (568 ms) [Thread-9] 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]] (568 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@a9192b] (569 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9 branchID = z9hG4bK2a74759911c6ca32b365d20b1560792b isClient = true] (569 ms) [Thread-9] 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]] (569 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9 tickCount 10 currentTickCount = 64] (570 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9] (569 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@a9192bnevents 1] (571 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@f32dde]source = gov.nist.javax.sip.SipProviderImpl@f32dde] (571 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (571 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (571 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@46ea41d9] (572 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]] (570 ms) [Thread-9] 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]] (575 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for OPTIONS sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 creating a new one ] (575 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] (576 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(9db23d125114773b4dd0165f4fcebb46@192.168.0.145:548321037) : returning null] (576 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (577 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (577 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][ContactHeaderTest.java:107][ContactHeaderTest.java:77][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]] (577 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKa5b5ba181eba92891926f43619b8c083] (578 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bka5b5ba181eba92891926f43619b8c083] (579 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKa5b5ba181eba92891926f43619b8c083] (579 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : OPTIONS returning false] (579 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendRequest(SIPClientTransaction.java:918) [sendRequest() OPTIONS sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 CSeq: 1 OPTIONS From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 ] (580 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message OPTIONS sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 CSeq: 1 OPTIONS From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 ] (580 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (581 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKa5b5ba181eba92891926f43619b8c083] (581 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@b0ca1b9c branchID = z9hG4bKa5b5ba181eba92891926f43619b8c083 isClient = true] (583 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][ContactHeaderTest.java:107][ContactHeaderTest.java:77][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]] (585 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c tickCount 64 currentTickCount = -1] (586 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][ContactHeaderTest.java:107][ContactHeaderTest.java:77][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]] (587 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 OPTIONS sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 CSeq: 1 OPTIONS From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 ] (588 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (589 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (590 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (590 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="1223304433093" isSender="true" transactionId="z9hg4bka5b5ba181eba92891926f43619b8c083" callId="9db23d125114773b4dd0165f4fcebb46@192.168.0.145" firstLine="OPTIONS sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[OPTIONS sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 CSeq: 1 OPTIONS From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 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.spectestapp.uas Servlet-Name: ContactHeader Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (590 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (591 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (598 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (598 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 431] (601 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=3dwoii Content-Length: 0 Contact: <sip:tck@sipservlet.com>;expires=3600 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 OPTIONS Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 From: Alice <sip:alice@192.168.0.145:5071>;tag=548321037 ] (603 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c] (604 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]] (604 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (605 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (605 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (606 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="1223304433113" isSender="false" transactionId="z9hg4bka5b5ba181eba92891926f43619b8c083" callId="9db23d125114773b4dd0165f4fcebb46@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=3dwoii Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 OPTIONS Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (606 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (606 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (606 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bka5b5ba181eba92891926f43619b8c083] (607 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c for SIP/2.0 200 OK To: "JSR289_TCK" <sip:JSR289_TCK@127.0.0.1:5060>;tag=3dwoii Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 OPTIONS Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 Content-Length: 0 ] (607 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@b0ca1b9c to gov.nist.javax.sip.DialogFilter@7946a2] (607 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] (608 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = null] (608 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=3dwoii Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 OPTIONS Call-ID: 9db23d125114773b4dd0165f4fcebb46@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa5b5ba181eba92891926f43619b8c083 From: "Alice" <sip:alice@192.168.0.145:5071>;tag=548321037 Content-Length: 0 ] (609 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c] (609 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@f32dde]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9cthis.sipListener = org.cafesip.sipunit.SipStack@e5c339sipEvent.source = gov.nist.javax.sip.SipProviderImpl@f32dde] (609 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = null] (610 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]] (610 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@c7272] (610 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@b0ca1b9c branchID = z9hG4bKa5b5ba181eba92891926f43619b8c083 isClient = true] (610 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]] (611 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c tickCount 10 currentTickCount = 64] (611 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c] (611 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]] (612 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@c7272nevents 1] (612 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@f32dde]source = gov.nist.javax.sip.SipProviderImpl@f32dde] (613 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (613 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (613 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b0ca1b9c] (613 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]] (620 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 ] (620 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] (620 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(2c88b20b7e47a001c8d55846ca135655@192.168.0.145:1988747485) : returning null] (621 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (621 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (623 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][ContactHeaderTest.java:220][ContactHeaderTest.java:78][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]] (625 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2] (626 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk3f1f3812c7d9aa2927bb1c47291478d2] (626 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2] (626 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (652 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (654 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (655 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@e038c41988747485/null] (655 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk3f1f3812c7d9aa2927bb1c47291478d2/false] (656 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][ContactHeaderTest.java:220][ContactHeaderTest.java:78][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]] (656 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@e038c4] (656 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (657 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][ContactHeaderTest.java:220][ContactHeaderTest.java:78][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]] (658 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145:1988747485sipDialog = gov.nist.javax.sip.stack.SIPDialog@e038c4] (659 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: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite301 Content-Length: 0 ] (659 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: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite301 Content-Length: 0 ] (660 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (660 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2] (660 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@b3cd8310 branchID = z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 isClient = true] (661 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][ContactHeaderTest.java:220][ContactHeaderTest.java:78][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]] (662 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310 tickCount 64 currentTickCount = -1] (663 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][ContactHeaderTest.java:220][ContactHeaderTest.java:78][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]] (663 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: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite301 Content-Length: 0 ] (664 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (664 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (664 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (666 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="1223304433170" isSender="true" transactionId="z9hg4bk3f1f3812c7d9aa2927bb1c47291478d2" callId="2c88b20b7e47a001c8d55846ca135655@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: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite301 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (667 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (667 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304433175 INVITE after sending out through stack.......... SIPUNIT TRACE: 1223304433176 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite301 Content-Length: 0 SIPUNIT TRACE: 1223304433176 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> (669 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (688 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 424] (688 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 301 Moved Permanently To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Content-Length: 0 Contact: <sip:tck@sipservlet.com>;expires=3600 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 From: <sip:alice@192.168.0.145>;tag=1988747485 ] (691 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310] (691 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]] (692 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (864 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (864 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (864 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="1223304433371" isSender="false" transactionId="z9hg4bk3f1f3812c7d9aa2927bb1c47291478d2" callId="2c88b20b7e47a001c8d55846ca135655@192.168.0.145" firstLine="SIP/2.0 301 Moved Permanently" > <![CDATA[SIP/2.0 301 Moved Permanently To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 From: <sip:alice@192.168.0.145>;tag=1988747485 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (869 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (869 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (869 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk3f1f3812c7d9aa2927bb1c47291478d2] (870 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310 for SIP/2.0 301 Moved Permanently To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 From: <sip:alice@192.168.0.145>;tag=1988747485 Content-Length: 0 ] (870 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@b3cd8310 to gov.nist.javax.sip.DialogFilter@2d9844] (870 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (871 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@e038c4 lastResponse = SIP/2.0 301 Moved Permanently ] (872 ms) [Thread-11] 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]] (872 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (879 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (879 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (879 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 301] (880 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310] (880 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (880 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@e038c4newState = 3] (881 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (881 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@e038c4 old dialog state is null] (881 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@e038c4 New dialog state is Terminated Dialog] (881 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145:1988747485:s3z4zesipDialog = gov.nist.javax.sip.stack.SIPDialog@e038c4] (882 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 301 Moved Permanently current state = Calling Transaction] (882 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@e038c4] (882 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@e038c4 lastResponse = SIP/2.0 301 Moved Permanently ] (882 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (882 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145:1988747485:s3z4zesipDialog = gov.nist.javax.sip.stack.SIPDialog@e038c4] (883 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (884 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState Calling Transaction] (884 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310 branchID = z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 isClient = true] (885 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:440][SIPClientTransaction.java:813][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (889 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:446][SIPClientTransaction.java:813][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (890 ms) [Thread-11] 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 ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (890 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (890 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (891 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (891 ms) [Thread-11] 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="1223304433393" isSender="true" transactionId="z9hg4bk3f1f3812c7d9aa2927bb1c47291478d2" callId="2c88b20b7e47a001c8d55846ca135655@192.168.0.145" firstLine="ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=1988747485 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (891 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (892 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (892 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 301 Moved Permanently To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 From: <sip:alice@192.168.0.145>;tag=1988747485 Content-Length: 0 ] (893 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310] (893 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@e038c4 lastResponse = SIP/2.0 301 Moved Permanently ] (893 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (893 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145:1988747485:s3z4zesipDialog = gov.nist.javax.sip.stack.SIPDialog@e038c4] (894 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@f32dde]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310this.sipListener = org.cafesip.sipunit.SipStack@e5c339sipEvent.source = gov.nist.javax.sip.SipProviderImpl@f32dde] (894 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@e038c4] (894 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:832][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (895 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@dc5434] (895 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310 branchID = z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 isClient = true] (895 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:839][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (897 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310 tickCount 64 currentTickCount = 64] (897 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310] (897 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]] (898 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@dc5434nevents 1] (898 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@f32dde]source = gov.nist.javax.sip.SipProviderImpl@f32dde] (898 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 301 Moved Permanently ] (898 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (898 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b3cd8310] (899 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: 1223304433408 Outgoing call response received: SIP/2.0 301 Moved Permanently To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=s3z4ze Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2c88b20b7e47a001c8d55846ca135655@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK3f1f3812c7d9aa2927bb1c47291478d2 From: <sip:alice@192.168.0.145>;tag=1988747485 Content-Length: 0 (901 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {2c88b20b7e47a001c8d55846ca135655@192.168.0.145:1988747485:s3z4ze=gov.nist.javax.sip.stack.SIPDialog@e038c4} default dialog gov.nist.javax.sip.stack.SIPDialog@e038c4 retval gov.nist.javax.sip.stack.SIPDialog@e038c4] (902 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 ] (902 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] (904 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145:207755679) : returning null] (905 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (905 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (906 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][ContactHeaderTest.java:263][ContactHeaderTest.java:79][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]] (906 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK27420909b3b619f7ce18129ca96e93c9] (906 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk27420909b3b619f7ce18129ca96e93c9] (907 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK27420909b3b619f7ce18129ca96e93c9] (908 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (908 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (908 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (909 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@83df14207755679/null] (909 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk27420909b3b619f7ce18129ca96e93c9/false] (909 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][ContactHeaderTest.java:263][ContactHeaderTest.java:79][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]] (911 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@83df14] (911 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (912 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][ContactHeaderTest.java:263][ContactHeaderTest.java:79][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]] (912 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145:207755679sipDialog = gov.nist.javax.sip.stack.SIPDialog@83df14] (913 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: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite485 Content-Length: 0 ] (913 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: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite485 Content-Length: 0 ] (914 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (915 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK27420909b3b619f7ce18129ca96e93c9] (916 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@2d20125d branchID = z9hG4bK27420909b3b619f7ce18129ca96e93c9 isClient = true] (916 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][ContactHeaderTest.java:263][ContactHeaderTest.java:79][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]] (916 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d tickCount 64 currentTickCount = -1] (917 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][ContactHeaderTest.java:263][ContactHeaderTest.java:79][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]] (917 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: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite485 Content-Length: 0 ] (918 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (919 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (919 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (919 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="1223304433425" isSender="true" transactionId="z9hg4bk27420909b3b619f7ce18129ca96e93c9" callId="2a13277c54a64cd1dfa1a9f404f446c7@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: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite485 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (920 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (920 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304433429 INVITE after sending out through stack.......... SIPUNIT TRACE: 1223304433429 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 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: ContactHeader Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas x-wlss-spec-test-contact-header: Invite485 Content-Length: 0 SIPUNIT TRACE: 1223304433429 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> (923 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (924 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 415] (924 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 485 Ambiguous To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Content-Length: 0 Contact: <sip:tck@sipservlet.com>;expires=3600 Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 From: <sip:alice@192.168.0.145>;tag=207755679 ] (925 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d] (925 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]] (926 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (926 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (926 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (930 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="1223304433434" isSender="false" transactionId="z9hg4bk27420909b3b619f7ce18129ca96e93c9" callId="2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145" firstLine="SIP/2.0 485 Ambiguous" > <![CDATA[SIP/2.0 485 Ambiguous To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 From: <sip:alice@192.168.0.145>;tag=207755679 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (930 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (931 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (931 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk27420909b3b619f7ce18129ca96e93c9] (931 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d for SIP/2.0 485 Ambiguous To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 From: <sip:alice@192.168.0.145>;tag=207755679 Content-Length: 0 ] (933 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@2d20125d to gov.nist.javax.sip.DialogFilter@2758d0] (934 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (934 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@83df14 lastResponse = SIP/2.0 485 Ambiguous ] (934 ms) [Thread-12] 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]] (934 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (938 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (938 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (938 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 485] (938 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d] (939 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (939 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@83df14newState = 3] (939 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (939 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@83df14 old dialog state is null] (939 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@83df14 New dialog state is Terminated Dialog] (940 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145:207755679:beayvesipDialog = gov.nist.javax.sip.stack.SIPDialog@83df14] (940 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 485 Ambiguous current state = Calling Transaction] (944 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@83df14] (945 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@83df14 lastResponse = SIP/2.0 485 Ambiguous ] (945 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (945 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145:207755679:beayvesipDialog = gov.nist.javax.sip.stack.SIPDialog@83df14] (946 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (946 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState Calling Transaction] (946 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d branchID = z9hG4bK27420909b3b619f7ce18129ca96e93c9 isClient = true] (947 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:440][SIPClientTransaction.java:813][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (948 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:446][SIPClientTransaction.java:813][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (948 ms) [Thread-12] 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 ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (948 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (950 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (951 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (951 ms) [Thread-12] 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="1223304433455" isSender="true" transactionId="z9hg4bk27420909b3b619f7ce18129ca96e93c9" callId="2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145" firstLine="ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=207755679 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (951 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (951 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (952 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 485 Ambiguous To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 From: <sip:alice@192.168.0.145>;tag=207755679 Content-Length: 0 ] (954 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d] (954 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@83df14 lastResponse = SIP/2.0 485 Ambiguous ] (954 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (955 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145:207755679:beayvesipDialog = gov.nist.javax.sip.stack.SIPDialog@83df14] (956 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@f32dde]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@2d20125dthis.sipListener = org.cafesip.sipunit.SipStack@e5c339sipEvent.source = gov.nist.javax.sip.SipProviderImpl@f32dde] (956 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@83df14] (958 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:832][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (958 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@37e19e] (958 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d branchID = z9hG4bK27420909b3b619f7ce18129ca96e93c9 isClient = true] (959 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:839][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (959 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d tickCount 64 currentTickCount = 64] (959 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@37e19enevents 1] (960 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@f32dde]source = gov.nist.javax.sip.SipProviderImpl@f32dde] (961 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 485 Ambiguous ] (961 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (961 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d] (962 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]] (960 ms) [Thread-12] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@2d20125d] (962 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]] SIPUNIT TRACE: 1223304433471 Outgoing call response received: SIP/2.0 485 Ambiguous To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=beayve Contact: <sip:tck@sipservlet.com>;expires=3600,<sip:alice@192.168.0.145:5071;lr;transport=udp>;expires=3600 CSeq: 1 INVITE Call-ID: 2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK27420909b3b619f7ce18129ca96e93c9 From: <sip:alice@192.168.0.145>;tag=207755679 Content-Length: 0 (963 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {2a13277c54a64cd1dfa1a9f404f446c7@192.168.0.145:207755679:beayve=gov.nist.javax.sip.stack.SIPDialog@83df14} default dialog gov.nist.javax.sip.stack.SIPDialog@83df14 retval gov.nist.javax.sip.stack.SIPDialog@83df14] (965 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@e038c4newState = 3] (966 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]] (966 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@83df14newState = 3] (967 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]] (968 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (968 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (969 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (1969 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (1969 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (1973 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (2973 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (2974 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (2975 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]