(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} ] (8 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (8 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (9 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>] (11 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (44 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (227 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] (335 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@b11164 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@ecf608] (335 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@ecf608] (342 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@12d7ae] (344 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} ] (345 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (345 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (346 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (346 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (347 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (347 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (348 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] (348 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@786b98 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@dff0ea] (353 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@dff0ea] (353 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@41c977] (356 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} ] (357 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (357 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (358 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (359 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (359 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (361 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (361 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] (361 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@11ae04 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@b7bf86] (362 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@b7bf86] (362 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@7f2261] (542 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 ] (543 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] (544 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919) : returning null] (546 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (553 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (555 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:58][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]] (556 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK7bff583e533050dc42ff9fe4a1d78cee] (557 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk7bff583e533050dc42ff9fe4a1d78cee] (559 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK7bff583e533050dc42ff9fe4a1d78cee] (561 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (574 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (577 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (577 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@9ed5d655623919/null] (577 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk7bff583e533050dc42ff9fe4a1d78cee/false] (578 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:58][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]] (578 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (578 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (579 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:58][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]] (580 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919sipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (582 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: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=55623919 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee 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: UasPassive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (583 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: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=55623919 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee 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: UasPassive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (583 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (584 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK7bff583e533050dc42ff9fe4a1d78cee] (584 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@b7b8ffdc branchID = z9hG4bK7bff583e533050dc42ff9fe4a1d78cee isClient = true] (585 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:464][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:58][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]] (586 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc 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][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:58][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 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=55623919 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee 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: UasPassive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (587 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (591 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (595 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (596 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="1223304850040" isSender="true" transactionId="z9hg4bk7bff583e533050dc42ff9fe4a1d78cee" callId="0e35d5625e2f373192ddb03ce36f8495@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: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=55623919 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee 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: UasPassive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (597 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (597 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304850052 INVITE after sending out through stack.......... (595 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (599 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 337] (599 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee From: <sip:alice@192.168.0.145>;tag=55623919 ] SIPUNIT TRACE: 1223304850053 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=55623919 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee 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: UasPassive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 SIPUNIT TRACE: 1223304850053 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> (604 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (604 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]] (605 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (606 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (607 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (607 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="1223304850059" isSender="false" transactionId="z9hg4bk7bff583e533050dc42ff9fe4a1d78cee" callId="0e35d5625e2f373192ddb03ce36f8495@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (607 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (607 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (608 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk7bff583e533050dc42ff9fe4a1d78cee] (608 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc for SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 ] (612 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@b7b8ffdc to gov.nist.javax.sip.DialogFilter@c0ae76] (612 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (613 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@9ed5d6 lastResponse = SIP/2.0 200 OK ] (613 ms) [Thread-9] 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]] (614 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (614 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (615 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (615 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (615 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (616 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (616 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteTag(SIPDialog.java:1166) [setRemoteTag(): gov.nist.javax.sip.stack.SIPDialog@9ed5d6 remoteTag = null new tag = au4sws] (616 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4sws dialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (616 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2186][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (617 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:533) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@9ed5d6state = null] (617 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:581][SIPDialog.java:2187][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (620 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@9ed5d6newState = 1] (620 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2189][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (620 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@9ed5d6 old dialog state is null] (620 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@9ed5d6 New dialog state is Confirmed Dialog] (620 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (621 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Calling Transaction] (621 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (621 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@9ed5d6 lastResponse = SIP/2.0 200 OK ] (622 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (622 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (622 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (622 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (622 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (623 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (623 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (623 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (625 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc branchID = z9hG4bK7bff583e533050dc42ff9fe4a1d78cee isClient = true] (626 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:787][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (627 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 ] (627 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (628 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@9ed5d6 lastResponse = SIP/2.0 200 OK ] (628 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1065][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (628 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (628 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (629 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (629 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (634 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (635 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (635 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (636 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@e91485]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdcthis.sipListener = org.cafesip.sipunit.SipStack@12d7aesipEvent.source = gov.nist.javax.sip.SipProviderImpl@e91485] (636 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (636 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (637 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@979a36] (637 ms) [Thread-9] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (637 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]] (638 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@979a36nevents 1] (638 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]source = gov.nist.javax.sip.SipProviderImpl@e91485] (638 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (638 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (639 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:331) [Garbage collecting unacknowledged dialog] (639 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (639 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: 1223304850094 Outgoing call response received: SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7bff583e533050dc42ff9fe4a1d78cee From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 (641 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4sws=gov.nist.javax.sip.stack.SIPDialog@9ed5d6} default dialog gov.nist.javax.sip.stack.SIPDialog@9ed5d6 retval gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (743 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (744 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (744 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (744 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (744 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (745 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (745 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:633) [sendAckgov.nist.javax.sip.stack.SIPDialog@9ed5d6] (746 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:658) [setting from tag For outgoing ACK= 55623919] (747 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:661) [setting To tag for outgoing ACK = au4sws] (747 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:664) [ack = ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa0f3a0f5170e0e9b0a0d0d9c0393be51 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 ] (748 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:234) [Used request-URI for nextHop = 192.168.0.145:5060/udp] (748 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:680) [hop = 192.168.0.145:5060/udp] (748 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (749 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPDialog.java:691][SIPDialog.java:1431][SipCall.java:3126][SipCall.java:3050][UasTest.java:71][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]] (749 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa0f3a0f5170e0e9b0a0d0d9c0393be51 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 ] (788 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (790 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa0f3a0f5170e0e9b0a0d0d9c0393be51 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 ] (794 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (794 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (795 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223304850203" isSender="true" transactionId="z9hg4bka0f3a0f5170e0e9b0a0d0d9c0393be51" callId="0e35d5625e2f373192ddb03ce36f8495@192.168.0.145" firstLine="ACK sip:192.168.0.145:5060;transport=udp SIP/2.0" > <![CDATA[ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKa0f3a0f5170e0e9b0a0d0d9c0393be51 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (795 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (795 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (1102 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction$TransactionTimer.runTask(SIPClientTransaction.java:201) [removing = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc isReliable false] (1102 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bk7bff583e533050dc42ff9fe4a1d78cee transaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (1104 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1288) [REMOVED client tx gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc KEY = z9hg4bk7bff583e533050dc42ff9fe4a1d78cee] (1104 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdcthis.sipListener = org.cafesip.sipunit.SipStack@12d7aesipEvent.source = gov.nist.javax.sip.SipProviderImpl@e91485] (1104 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:1300][SIPClientTransaction.java:206][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (1105 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@dc5434] (1107 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@dc5434nevents 1] (1108 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]source = gov.nist.javax.sip.SipProviderImpl@e91485] (1108 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (1109 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = gov.nist.javax.sip.stack.SIPClientTransaction@b7b8ffdc] (1109 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = null] (5197 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5197 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (5197 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5198 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (5199 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (5199 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (5199 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.getNewClientTransaction(SipProviderImpl.java:328) [could not find existing transaction for BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 creating a new one ] (5200 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:234) [Used request-URI for nextHop = 192.168.0.145:5060/udp] (5200 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4sws) : returning gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5204 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (5204 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (5205 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipCall.java:3605][SipCall.java:3547][UasTest.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]] (5205 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK64fa364d6dce710904c14b9fd878cb9e] (5206 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk64fa364d6dce710904c14b9fd878cb9e] (5207 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK64fa364d6dce710904c14b9fd878cb9e] (5207 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (5207 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5208 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1604) [dialog.sendRequest dialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6 dialogRequest = BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 ] (5208 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5208 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@9ed5d655623919/au4sws] (5209 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk64fa364d6dce710904c14b9fd878cb9e/false] (5210 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:1652][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][UasTest.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]] (5211 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (5212 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1785) [using message channel gov.nist.javax.sip.stack.UDPMessageChannel@2758d0] (5212 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 ] (5213 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (5213 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK64fa364d6dce710904c14b9fd878cb9e] (5214 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@42e517cb branchID = z9hG4bK64fa364d6dce710904c14b9fd878cb9e isClient = true] (5215 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:470][SIPDialog.java:1817][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][UasTest.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]] (5215 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb tickCount 64 currentTickCount = -1] (5216 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPDialog.java:1817][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][UasTest.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]] (5217 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 ] (5217 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (5218 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5218 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5220 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223304854670" isSender="true" transactionId="z9hg4bk64fa364d6dce710904c14b9fd878cb9e" callId="0e35d5625e2f373192ddb03ce36f8495@192.168.0.145" firstLine="BYE sip:192.168.0.145:5060;transport=udp SIP/2.0" > <![CDATA[BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e CSeq: 2 BYE To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=55623919 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5220 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5220 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5221 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (5221 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 285] (5222 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws Content-Length: 0 CSeq: 2 BYE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e From: <sip:alice@192.168.0.145>;tag=55623919 ] (5223 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (5223 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]] (5223 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (5223 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (5224 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (5226 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223304854677" isSender="false" transactionId="z9hg4bk64fa364d6dce710904c14b9fd878cb9e" callId="0e35d5625e2f373192ddb03ce36f8495@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws CSeq: 2 BYE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (5226 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (5226 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (5226 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk64fa364d6dce710904c14b9fd878cb9e] (5227 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb for SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws CSeq: 2 BYE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 ] (5227 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@42e517cb to gov.nist.javax.sip.DialogFilter@baa8d8] (5227 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] (5227 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5228 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@9ed5d6 lastResponse = SIP/2.0 200 OK ] (5228 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5228 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = BYE] (5228 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (5228 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (5229 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (5231 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (5231 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (5231 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@9ed5d6newState = 3] (5232 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2254][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (5232 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@9ed5d6 old dialog state is Confirmed Dialog] (5232 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@9ed5d6 New dialog state is Terminated Dialog] (5232 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5233 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws CSeq: 2 BYE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 ] (5233 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (5233 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@9ed5d6 lastResponse = SIP/2.0 200 OK ] (5233 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (5234 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4swssipDialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5234 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@e91485]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cbthis.sipListener = org.cafesip.sipunit.SipStack@12d7aesipEvent.source = gov.nist.javax.sip.SipProviderImpl@e91485] (5234 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (5235 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]] (5235 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@a30706] (5236 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@42e517cb branchID = z9hG4bK64fa364d6dce710904c14b9fd878cb9e isClient = true] (5236 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]] (5236 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb tickCount 10 currentTickCount = 64] (5237 ms) [Thread-10] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (5237 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@a30706nevents 1] (5237 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]source = gov.nist.javax.sip.SipProviderImpl@e91485] (5238 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (5238 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] SIPUNIT TRACE: 1223304854692 Asynchronous response received: SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=au4sws CSeq: 2 BYE Call-ID: 0e35d5625e2f373192ddb03ce36f8495@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK64fa364d6dce710904c14b9fd878cb9e From: <sip:alice@192.168.0.145>;tag=55623919 Content-Length: 0 (5238 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (5238 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]] (5237 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]] (10223 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.fireTimeoutTimer(SIPClientTransaction.java:1037) [fireTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (10224 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {0e35d5625e2f373192ddb03ce36f8495@192.168.0.145:55623919:au4sws=gov.nist.javax.sip.stack.SIPDialog@9ed5d6} default dialog gov.nist.javax.sip.stack.SIPDialog@9ed5d6 retval gov.nist.javax.sip.stack.SIPDialog@9ed5d6] (10225 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb branchID = z9hG4bK64fa364d6dce710904c14b9fd878cb9e isClient = true] (10226 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:1088][SIPTransaction.java:632][SIPClientTransaction.java:268][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (10724 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction$TransactionTimer.runTask(SIPClientTransaction.java:201) [removing = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb isReliable false] (10725 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bk64fa364d6dce710904c14b9fd878cb9e transaction = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (10725 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1288) [REMOVED client tx gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb KEY = z9hg4bk64fa364d6dce710904c14b9fd878cb9e] (10725 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cbthis.sipListener = org.cafesip.sipunit.SipStack@12d7aesipEvent.source = gov.nist.javax.sip.SipProviderImpl@e91485] (10726 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:1300][SIPClientTransaction.java:206][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (10726 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@223d9b] (10727 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@223d9bnevents 1] (10727 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]source = gov.nist.javax.sip.SipProviderImpl@e91485] (10727 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (10728 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = gov.nist.javax.sip.stack.SIPClientTransaction@42e517cb] (10728 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = null] (13232 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]currentTransaction = nullthis.sipListener = org.cafesip.sipunit.SipStack@12d7aesipEvent.source = gov.nist.javax.sip.SipProviderImpl@e91485] (13233 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:590][SIPDialog.java:178][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (13234 ms) [Timer-0] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@fa8d3b] (13235 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@fa8d3bnevents 1] (13235 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@e91485]source = gov.nist.javax.sip.SipProviderImpl@e91485] (27221 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@9ed5d6newState = 3] (27222 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]] (27223 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (27223 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (27224 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (28225 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (28225 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (28225 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (29227 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (29227 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (29228 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (30232 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (30233 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (30234 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] (30234 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@845568 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@32cf5] (30234 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@32cf5] (30235 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@7c8f7f] (30235 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (30236 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (30237 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] (30238 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@b10190 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@ddc581] (30238 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@ddc581] (30238 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@d1b44b] (30239 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (30239 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (30240 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] (30240 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@93b52b listeningPoint = gov.nist.javax.sip.ListeningPointImpl@5b25a1] (30241 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@5b25a1] (30242 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@38b78] (30244 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 ] (30245 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] (30245 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357) : returning null] (30246 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (30247 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (30247 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:109][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]] (30247 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK4cf7b659354e53efd14fafd313f8d93d] (30248 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk4cf7b659354e53efd14fafd313f8d93d] (30249 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK4cf7b659354e53efd14fafd313f8d93d] (30249 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (30249 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (30250 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (30250 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@b9a2fd2055233357/null] (30250 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk4cf7b659354e53efd14fafd313f8d93d/false] (30251 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:109][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]] (30252 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30252 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (30252 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:109][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]] (30253 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357sipDialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30253 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: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2055233357 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d 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: UasActive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (30254 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: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2055233357 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d 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: UasActive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (30255 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (30256 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK4cf7b659354e53efd14fafd313f8d93d] (30256 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@1c86e4d6 branchID = z9hG4bK4cf7b659354e53efd14fafd313f8d93d isClient = true] (30257 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:464][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:109][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]] (30257 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 tickCount 64 currentTickCount = -1] (30258 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:109][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]] (30258 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: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2055233357 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d 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: UasActive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (30259 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (30259 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} ] (30260 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (30260 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (30261 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (30261 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (30261 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (30263 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (30263 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (30263 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="1223304879711" isSender="true" transactionId="z9hg4bk4cf7b659354e53efd14fafd313f8d93d" callId="0054ea66a06ba1322cc63707ef39ae97@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: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2055233357 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d 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: UasActive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (30264 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (30264 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (30264 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304879720 INVITE after sending out through stack.......... SIPUNIT TRACE: 1223304879720 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2055233357 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d 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: UasActive Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 SIPUNIT TRACE: 1223304879720 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> (30265 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 388] (30266 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 180 no particular reason Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Length: 10 CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Active UAS] (30264 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (30268 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 419] (30268 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:192.168.0.145:5060;transport=udp> Content-Length: 10 CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Active UAS] (30270 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30270 ms) [Thread-21] 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]] (30271 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (30271 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (30272 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (30272 ms) [Thread-21] 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="1223304879725" isSender="false" transactionId="z9hg4bk4cf7b659354e53efd14fafd313f8d93d" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Content-Length: 10 &#x5d;&#x5d;&gt; </message> ] (30272 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (30274 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (30274 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk4cf7b659354e53efd14fafd313f8d93d] (30275 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 for SIP/2.0 200 OK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Content-Length: 10 Active UAS] (30276 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30276 ms) [Thread-20] 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]] (30276 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 to gov.nist.javax.sip.DialogFilter@7d093a] (30278 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (30278 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@b9a2fd lastResponse = SIP/2.0 200 OK ] (30278 ms) [Thread-21] 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]] (30279 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (30280 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (30280 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (30280 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (30281 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30281 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (30284 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteTag(SIPDialog.java:1166) [setRemoteTag(): gov.nist.javax.sip.stack.SIPDialog@b9a2fd remoteTag = null new tag = sqt7zm] (30284 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zm dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30285 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2186][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30285 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:533) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@b9a2fdstate = null] (30285 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:581][SIPDialog.java:2187][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30286 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@b9a2fdnewState = 1] (30286 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2189][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30286 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@b9a2fd old dialog state is null] (30286 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@b9a2fd New dialog state is Confirmed Dialog] (30286 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zmsipDialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30286 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Calling Transaction] (30287 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30287 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@b9a2fd lastResponse = SIP/2.0 200 OK ] (30287 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30287 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (30288 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (30288 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (30288 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (30289 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30289 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (30289 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zmsipDialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30289 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 branchID = z9hG4bK4cf7b659354e53efd14fafd313f8d93d isClient = true] (30289 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:787][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30290 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Content-Length: 10 ] (30290 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30290 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@b9a2fd lastResponse = SIP/2.0 200 OK ] (30291 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1065][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30291 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (30291 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (30291 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (30292 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (30292 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30292 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (30293 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zmsipDialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30293 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6this.sipListener = org.cafesip.sipunit.SipStack@7c8f7fsipEvent.source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (30293 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30294 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (30294 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@a896a4] (30294 ms) [Thread-21] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30294 ms) [Thread-21] 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]] (30295 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (30295 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (30296 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (30296 ms) [Thread-20] 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="1223304879749" isSender="false" transactionId="z9hg4bk4cf7b659354e53efd14fafd313f8d93d" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="SIP/2.0 180 no particular reason" > <![CDATA[SIP/2.0 180 no particular reason Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Content-Length: 10 &#x5d;&#x5d;&gt; </message> ] (30297 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (30297 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (30297 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk4cf7b659354e53efd14fafd313f8d93d] (30298 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 for SIP/2.0 180 no particular reason Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Content-Length: 10 Active UAS] (30298 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@a896a4nevents 1] (30298 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (30298 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (30298 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (30299 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:331) [Garbage collecting unacknowledged dialog] (30299 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30299 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]] (30298 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 to gov.nist.javax.sip.DialogFilter@3a0067] (30304 ms) [Thread-20] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30304 ms) [Thread-20] 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: 1223304879759 Outgoing call response received: SIP/2.0 200 OK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK4cf7b659354e53efd14fafd313f8d93d From: <sip:alice@192.168.0.145>;tag=2055233357 Content-Type: text/plain Content-Length: 10 Active UAS (30305 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zm=gov.nist.javax.sip.stack.SIPDialog@b9a2fd} default dialog gov.nist.javax.sip.stack.SIPDialog@b9a2fd retval gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30407 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30407 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (30407 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30408 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (30408 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (30409 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (30410 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:633) [sendAckgov.nist.javax.sip.stack.SIPDialog@b9a2fd] (30410 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:658) [setting from tag For outgoing ACK= 2055233357] (30413 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:661) [setting To tag for outgoing ACK = sqt7zm] (30414 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:664) [ack = ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2531d0483b69cb720ef9f615639c2211 CSeq: 1 ACK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive From: <sip:alice@192.168.0.145>;tag=2055233357 Max-Forwards: 70 Content-Length: 0 ] (30414 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:234) [Used request-URI for nextHop = 192.168.0.145:5060/udp] (30415 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:680) [hop = 192.168.0.145:5060/udp] (30415 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (30417 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPDialog.java:691][SIPDialog.java:1431][SipCall.java:3126][SipCall.java:3050][UasTest.java:129][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]] (30423 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2531d0483b69cb720ef9f615639c2211 CSeq: 1 ACK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive From: <sip:alice@192.168.0.145>;tag=2055233357 Max-Forwards: 70 Content-Length: 0 ] (30423 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (30424 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2531d0483b69cb720ef9f615639c2211 CSeq: 1 ACK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive From: <sip:alice@192.168.0.145>;tag=2055233357 Max-Forwards: 70 Content-Length: 0 ] (30425 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (30426 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (30426 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223304879876" isSender="true" transactionId="z9hg4bk2531d0483b69cb720ef9f615639c2211" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="ACK sip:192.168.0.145:5060;transport=udp SIP/2.0" > <![CDATA[ACK sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK2531d0483b69cb720ef9f615639c2211 CSeq: 1 ACK Foo: bar Foo: baz To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive From: <sip:alice@192.168.0.145>;tag=2055233357 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (30426 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (30427 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304879881 SS.waitRequest() - about to block, waiting (30766 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction$TransactionTimer.runTask(SIPClientTransaction.java:201) [removing = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 isReliable false] (30766 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bk4cf7b659354e53efd14fafd313f8d93d transaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30767 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1288) [REMOVED client tx gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6 KEY = z9hg4bk4cf7b659354e53efd14fafd313f8d93d] (30767 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6this.sipListener = org.cafesip.sipunit.SipStack@7c8f7fsipEvent.source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (30768 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:1300][SIPClientTransaction.java:206][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (30768 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@9e4f7c] (30768 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@9e4f7cnevents 1] (30768 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (30768 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (30769 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = gov.nist.javax.sip.stack.SIPClientTransaction@1c86e4d6] (30769 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = null] (32265 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (32265 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 486] (32265 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 Content-Length: 10 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrhawcg;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Active UAS] (32267 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (32267 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (32268 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223304881719" isSender="false" transactionId="z9hg4bkrhawcg" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0" > <![CDATA[INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Content-Length: 10 &#x5d;&#x5d;&gt; </message> ] (32269 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (32269 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (32270 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkrhawcg] (32274 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (32274 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (32275 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKrhawcg] (32275 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( INFO:z9hG4bKrhawcg):gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32275 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 gov.nist.javax.sip.DialogFilter@f9aeda messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32275 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32276 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (32276 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (32276 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32276 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (32277 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (32278 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKrhawcg] (32278 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f branchID = z9hG4bKrhawcg isClient = false] (32278 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (32278 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (32279 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Content-Length: 10 Active UAS transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f listening point = 192.168.0.145:5071] (32279 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (32279 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zm) : returning gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (32279 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zm] (32280 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (32280 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32280 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkrhawcg] (32280 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkrhawcg] (32281 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@b9a2fd/1] (32282 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@b9a2fd2055233357/sqt7zm] (32283 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkrhawcg/true] (32284 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][DialogFilter.java:703][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (32284 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@b9a2fdstate = Confirmed Dialog] (32284 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (32284 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [INFO transaction.isMapped = true] (32285 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@ee38718fthis.sipListener = org.cafesip.sipunit.SipStack@7c8f7fsipEvent.source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (32285 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (32285 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (32285 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@a5e4e4] (32286 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32286 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@a5e4e4nevents 1] (32286 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (32286 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f sipEvent.serverTx = gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32286 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkrhawcg existing={z9hg4bkrhawcg=gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f}] (32286 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkrhawcg] (32288 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32288 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (32288 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] SIPUNIT TRACE: 1223304881742 SipStack: request received ! SIPUNIT TRACE: 1223304881742 SipStack: calling listener SIPUNIT TRACE: 1223304881742 SipSession: request received ! SIPUNIT TRACE: 1223304881742 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223304881742 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223304881742 INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Content-Length: 10 Active UAS SIPUNIT TRACE: 1223304881742 SipSession: notifying block object SIPUNIT TRACE: 1223304881742 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304881742 SS.waitRequest() - either we got the request, or timed out (32288 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (32289 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:803) [Request Consumed -- next consumable Request Seqno = 2] SIPUNIT TRACE: 1223304881744 Response before sending out through stack.......... (32289 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message INFO sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] SIPUNIT TRACE: 1223304881744 SIP/2.0 200 INFO To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 22000 Content-Length: 0 (32290 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32290 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INFO returning false] (32290 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@b9a2fd lastResponse = SIP/2.0 200 INFO ] (32290 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1081][SipCall.java:1040][UasTest.java:138][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]] (32291 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INFO] (32290 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][EventScanner.java:254][EventScanner.java:492][Thread.java:613]] (32293 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkrhawcg] (32293 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (32293 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (32294 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (32294 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f] (32294 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f branchID = z9hG4bKrhawcg isClient = false] (32295 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1081][SipCall.java:1040][UasTest.java:138][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]] (32295 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f tickCount 64 currentTickCount = -1] (32296 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f getState = Completed Transaction] (32296 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (32303 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPServerTransaction.java:464][SIPServerTransaction.java:1099][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1081][SipCall.java:1040][UasTest.java:138][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]] (32303 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 200 INFO To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 22000 Content-Length: 0 ] (32304 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (32306 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 INFO To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 22000 Content-Length: 0 ] (32307 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (32308 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (32308 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223304881757" isSender="true" transactionId="z9hg4bkrhawcg" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="SIP/2.0 200 INFO" > <![CDATA[SIP/2.0 200 INFO To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 1 INFO Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKrhawcg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Contact: <sip:alice@192.168.0.145:5071;lr;transport=udp> Expires: 22000 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (32308 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (32309 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (32309 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkrhawcg] SIPUNIT TRACE: 1223304881763 SS.waitRequest() - about to block, waiting (34265 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (34265 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 484] (34265 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 Content-Length: 10 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKvb6rlg;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Active UAS] (34269 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (34269 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (34270 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223304883720" isSender="false" transactionId="z9hg4bkvb6rlg" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0" > <![CDATA[BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Content-Length: 10 &#x5d;&#x5d;&gt; </message> ] (34270 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (34270 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (34270 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkvb6rlg] (34271 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (34271 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (34272 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKvb6rlg] (34272 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( BYE:z9hG4bKvb6rlg):gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34272 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 gov.nist.javax.sip.DialogFilter@7df42c messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34273 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34273 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (34273 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (34273 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34274 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (34274 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (34275 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKvb6rlg] (34275 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 branchID = z9hG4bKvb6rlg isClient = false] (34275 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (34275 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (34275 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Content-Length: 10 Active UAS transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 listening point = 192.168.0.145:5071] (34276 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (34276 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zm) : returning gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (34276 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145:2055233357:sqt7zm] (34276 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (34277 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34277 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkvb6rlg] (34277 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkvb6rlg] (34277 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@b9a2fd/2] (34278 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@b9a2fd2055233357/sqt7zm] (34278 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkvb6rlg/true] (34279 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][DialogFilter.java:440][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (34279 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (34279 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:449) [BYE Tx = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 isMapped =true] (34279 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [BYE transaction.isMapped = true] (34279 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962this.sipListener = org.cafesip.sipunit.SipStack@7c8f7fsipEvent.source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (34280 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = gov.nist.javax.sip.stack.SIPDialog@b9a2fd] (34280 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (34280 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@29b073] (34280 ms) [Thread-23] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34281 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@29b073nevents 1] (34281 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@7b9a29]source = gov.nist.javax.sip.SipProviderImpl@7b9a29] (34281 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 sipEvent.serverTx = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34281 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkvb6rlg existing={z9hg4bkrhawcg=gov.nist.javax.sip.stack.SIPServerTransaction@ee38718f, z9hg4bkvb6rlg=gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962}] (34283 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkvb6rlg] (34283 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34283 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (34284 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] SIPUNIT TRACE: 1223304883738 SipStack: request received ! SIPUNIT TRACE: 1223304883738 SipStack: calling listener SIPUNIT TRACE: 1223304883738 SipSession: request received ! SIPUNIT TRACE: 1223304883738 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223304883738 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223304883738 BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 Foo: bar Foo: baz To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 User-Agent: UasActive Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Type: text/plain Max-Forwards: 70 Content-Length: 10 Active UAS SIPUNIT TRACE: 1223304883738 SipSession: notifying block object (34284 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (34284 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:803) [Request Consumed -- next consumable Request Seqno = 3] (34284 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 ] (34285 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34285 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][EventScanner.java:254][EventScanner.java:492][Thread.java:613]] (34285 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkvb6rlg] SIPUNIT TRACE: 1223304883739 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304883739 SS.waitRequest() - either we got the request, or timed out SIPUNIT TRACE: 1223304883739 Response before sending out through stack.......... SIPUNIT TRACE: 1223304883739 SIP/2.0 200 OK To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Length: 0 (34285 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (34286 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@b9a2fd lastResponse = SIP/2.0 200 OK ] (34286 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipSession.java:1694][SipCall.java:1651][SipCall.java:1634][UasTest.java:145][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]] (34287 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = BYE] (34287 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (34288 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (34288 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (34288 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962] (34289 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@b9a2fdnewState = 3] (34289 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2274][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipSession.java:1694][SipCall.java:1651][SipCall.java:1634][UasTest.java:145][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]] (34289 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@b9a2fd old dialog state is Confirmed Dialog] (34290 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@b9a2fd New dialog state is Terminated Dialog] (34290 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 branchID = z9hG4bKvb6rlg isClient = false] (34291 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:936][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipSession.java:1694][SipCall.java:1651][SipCall.java:1634][UasTest.java:145][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]] (34291 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 tickCount 64 currentTickCount = -1] (34291 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@f4a3a962 getState = Completed Transaction] (34292 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (34292 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:576][SIPServerTransaction.java:464][SIPServerTransaction.java:1099][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipSession.java:1694][SipCall.java:1651][SipCall.java:1634][UasTest.java:145][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]] (34293 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:678) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Length: 0 ] (34293 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (34294 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Length: 0 ] (34294 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (34294 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (34295 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="192.168.0.145:5060" time="1223304883747" isSender="true" transactionId="z9hg4bkvb6rlg" callId="0054ea66a06ba1322cc63707ef39ae97@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:alice@192.168.0.145>;tag=2055233357 CSeq: 2 BYE Call-ID: 0054ea66a06ba1322cc63707ef39ae97@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.uas;branch=z9hG4bKvb6rlg From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=sqt7zm Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (34295 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (34296 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (34296 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkvb6rlg] (34301 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@b9a2fdnewState = 3] (34302 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]] (34303 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (34303 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (34304 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (35304 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (35304 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (35305 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (36305 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (36306 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (36306 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (37307 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (37307 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (37308 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] (37308 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@fee225 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@b0edb2] (37309 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@b0edb2] (37309 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@c57f88] (37309 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (37310 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (37310 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] (37310 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@37e21f listeningPoint = gov.nist.javax.sip.ListeningPointImpl@de6570] (37311 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@de6570] (37312 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@d5a2a9] (37312 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (37313 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (37313 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] (37314 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@aa34dc listeningPoint = gov.nist.javax.sip.ListeningPointImpl@747f59] (37314 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@747f59] (37314 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@54de0b] (37316 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 ] (37316 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] (37317 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508) : returning null] (37318 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (37318 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (37319 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SIPTransactionStack.java:1167][SipProviderImpl.java:374][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:173][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]] (37319 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3] (37319 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3] (37320 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3] (37320 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (37321 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (37321 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (37321 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@bdb8592078061508/null] (37322 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3/false] (37322 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:173][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]] (37322 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@bdb859] (37323 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (37323 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:393][SipSession.java:1181][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:173][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]] (37324 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508sipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37324 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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 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: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (37324 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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 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: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (37325 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (37325 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3] (37325 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@bac3faa branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (37326 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:464][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:173][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]] (37326 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa tickCount 64 currentTickCount = -1] (37327 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:484][SIPClientTransaction.java:977][SipSession.java:1197][SipCall.java:2046][SipCall.java:1870][TestBase.java:881][TestBase.java:814][UasTest.java:173][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]] (37327 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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 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: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (37328 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (37328 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} ] (37329 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (37329 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (37330 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (37330 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (37330 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (37331 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (37331 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (37332 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="1223304886781" isSender="true" transactionId="z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3" callId="bb713af1f5b3c3fe0ab24d866c097479@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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 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: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (37333 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (37333 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (37333 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304886787 INVITE after sending out through stack.......... SIPUNIT TRACE: 1223304886788 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 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: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 SIPUNIT TRACE: 1223304886788 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> (37333 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 295] (37334 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 180 Ringing To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t Content-Length: 0 CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 ] (37335 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37335 ms) [Thread-33] 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]] (37335 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (37336 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (37336 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (37337 ms) [Thread-33] 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="1223304886790" isSender="false" transactionId="z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3" callId="bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145" firstLine="SIP/2.0 180 Ringing" > <![CDATA[SIP/2.0 180 Ringing To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (37337 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (37337 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (37337 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3] (37337 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa for SIP/2.0 180 Ringing To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 ] (37338 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa to gov.nist.javax.sip.DialogFilter@260829] (37338 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (37340 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@bdb859 lastResponse = SIP/2.0 180 Ringing ] (37341 ms) [Thread-33] 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]] (37341 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (37341 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (37341 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (37341 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 180] (37342 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37342 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (37343 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@bdb859newState = 0] (37343 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2166][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37343 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@bdb859 old dialog state is null] (37343 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@bdb859 New dialog state is Early Dialog] (37344 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteTag(SIPDialog.java:1166) [setRemoteTag(): gov.nist.javax.sip.stack.SIPDialog@bdb859 remoteTag = null new tag = dfbz9t] (37344 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9t dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37344 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2171][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37344 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:533) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@bdb859state = Early Dialog] (37344 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:581][SIPDialog.java:2172][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37345 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9tsipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37345 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 180 Ringing current state = Calling Transaction] (37345 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37345 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@bdb859 lastResponse = SIP/2.0 180 Ringing ] (37345 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37345 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (37347 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (37347 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (37347 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 180] (37347 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37347 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (37348 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9tsipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37348 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Proceeding Transaction gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (37348 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:800][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37349 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 180 Ringing To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 ] (37349 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37351 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@bdb859 lastResponse = SIP/2.0 180 Ringing ] (37351 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1065][SIPClientTransaction.java:803][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37352 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (37352 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (37353 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (37353 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 180] (37353 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37353 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (37354 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9tsipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37354 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faathis.sipListener = org.cafesip.sipunit.SipStack@c57f88sipEvent.source = gov.nist.javax.sip.SipProviderImpl@91f61c] (37354 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (37354 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:803][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (37355 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@41cd01] (37355 ms) [Thread-33] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37355 ms) [Thread-33] 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]] (37355 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@41cd01nevents 1] (37356 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]source = gov.nist.javax.sip.SipProviderImpl@91f61c] (37356 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 180 Ringing ] (37356 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (37357 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (37357 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: 1223304886811 Outgoing call response received: SIP/2.0 180 Ringing To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 (37357 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9t=gov.nist.javax.sip.stack.SIPDialog@bdb859} default dialog gov.nist.javax.sip.stack.SIPDialog@bdb859 retval gov.nist.javax.sip.stack.SIPDialog@bdb859] (41760 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel] (41760 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findCancelTransaction(SIPTransactionStack.java:785) [findCancelTransaction request= CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 CANCEL From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 Max-Forwards: 70 Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 findCancelRequest isServer=false] (41761 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.doesCancelMatchTransaction(SIPTransaction.java:982) [returning true] (41761 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (41761 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (41762 ms) [main] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPClientTransaction.java:302][SIPTransactionStack.java:1189][SipProviderImpl.java:313][SipSession.java:1181][SipCall.java:2957][SipCall.java:2900][UasTest.java:188][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]] (41768 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3] (41769 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1244) [added transaction gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (41769 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel] (41770 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9t=gov.nist.javax.sip.stack.SIPDialog@bdb859} default dialog gov.nist.javax.sip.stack.SIPDialog@bdb859 retval gov.nist.javax.sip.stack.SIPDialog@bdb859] (41770 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9t=gov.nist.javax.sip.stack.SIPDialog@bdb859} default dialog gov.nist.javax.sip.stack.SIPDialog@bdb859 retval gov.nist.javax.sip.stack.SIPDialog@bdb859] (41770 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508sipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41771 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendRequest(SIPClientTransaction.java:918) [sendRequest() CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 CANCEL From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 Max-Forwards: 70 Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (41772 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findCancelTransaction(SIPTransactionStack.java:785) [findCancelTransaction request= CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 CANCEL From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 Max-Forwards: 70 Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 findCancelRequest isServer=false] (41772 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.doesCancelMatchTransaction(SIPTransaction.java:982) [returning true] (41772 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (41773 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 CANCEL From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 Max-Forwards: 70 Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (41773 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (41773 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3] (41774 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@cb0a484a branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (41774 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][SipCall.java:2957][SipCall.java:2900][UasTest.java:188][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]] (41776 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a tickCount 64 currentTickCount = -1] (41776 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:2957][SipCall.java:2900][UasTest.java:188][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]] (41777 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 CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 CANCEL From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 Max-Forwards: 70 Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 ] (41777 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (41777 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (41778 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (41778 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="1223304891230" isSender="true" transactionId="z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel" callId="bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145" firstLine="CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0" > <![CDATA[CANCEL sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 CSeq: 1 CANCEL From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 Max-Forwards: 70 Route: <sip:127.0.0.1:5060;lr;transport=udp> Servlet-Name: UasCancel Application-Name: com.bea.sipservlet.tck.apps.spectestapp.uas Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (41779 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (41780 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (41781 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (41781 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 279] (41781 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060> Content-Length: 0 CSeq: 1 CANCEL Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 ] (41782 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (41782 ms) [Thread-34] 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]] (41782 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (41782 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (41783 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (41783 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (41784 ms) [Thread-34] 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="1223304891236" isSender="false" transactionId="z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel" callId="bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060> CSeq: 1 CANCEL Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (41784 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (41784 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (41784 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel] (41784 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a for SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060> CSeq: 1 CANCEL Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 ] (41785 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a to gov.nist.javax.sip.DialogFilter@8faa02] (41785 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK current state = Trying Transaction] (41785 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41785 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@bdb859 lastResponse = SIP/2.0 200 OK ] (41786 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41786 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = CANCEL] (41786 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (41786 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (41783 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 306] (41787 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 487 Request Terminated To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t Content-Length: 0 CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 ] (41788 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (41788 ms) [Thread-35] 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]] (41788 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (41787 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (41788 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (41789 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : CANCEL returning false] (41789 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508sipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41789 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (41789 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (41790 ms) [Thread-35] 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="1223304891242" isSender="false" transactionId="z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3" callId="bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145" firstLine="SIP/2.0 487 Request Terminated" > <![CDATA[SIP/2.0 487 Request Terminated To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (41790 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (41790 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (41789 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060> CSeq: 1 CANCEL Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 ] (41795 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3] (41795 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (41795 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa for SIP/2.0 487 Request Terminated To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 ] (41796 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484athis.sipListener = org.cafesip.sipunit.SipStack@c57f88sipEvent.source = gov.nist.javax.sip.SipProviderImpl@91f61c] (41796 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa to gov.nist.javax.sip.DialogFilter@e26d2e] (41796 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41797 ms) [Thread-34] 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]] (41797 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@6e1ccd] (41797 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (41798 ms) [Thread-34] 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]] (41798 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a tickCount 10 currentTickCount = 64] (41798 ms) [Thread-34] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (41796 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 487 Request Terminated current state = Proceeding Transaction] (41801 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@6e1ccdnevents 1] (41808 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]source = gov.nist.javax.sip.SipProviderImpl@91f61c] (41808 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK ] (41808 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] SIPUNIT TRACE: 1223304891262 Asynchronous response received: SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060> CSeq: 1 CANCEL Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 (41803 ms) [Thread-34] 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]] (41808 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41809 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@bdb859 lastResponse = SIP/2.0 487 Request Terminated ] (41809 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41810 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (41810 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Early Dialog] (41810 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (41810 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 487] (41810 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (41810 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (41811 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@bdb859newState = 3] (41832 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41835 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@bdb859 old dialog state is Early Dialog] (41835 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@bdb859 New dialog state is Terminated Dialog] (41835 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9tsipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41836 ms) [Thread-35] 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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (41836 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState Proceeding Transaction] (41836 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (41837 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:440][SIPClientTransaction.java:866][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41837 ms) [Thread-35] 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:866][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41837 ms) [Thread-35] 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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (41837 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (41838 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (41839 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (41839 ms) [Thread-35] 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="1223304891291" isSender="true" transactionId="z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3" callId="bb713af1f5b3c3fe0ab24d866c097479@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: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=2078061508 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (41839 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (41839 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (41840 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (41840 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:873][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41841 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 487 Request Terminated To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 ] (41841 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (41841 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@bdb859 lastResponse = SIP/2.0 487 Request Terminated ] (41841 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (41841 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9tsipDialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41843 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@bac3faathis.sipListener = org.cafesip.sipunit.SipStack@c57f88sipEvent.source = gov.nist.javax.sip.SipProviderImpl@91f61c] (41843 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@bdb859] (41844 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:880][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (41844 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@6bc73b] (41844 ms) [Thread-35] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa tickCount 64 currentTickCount = -1] (41845 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9t=gov.nist.javax.sip.stack.SIPDialog@bdb859} default dialog gov.nist.javax.sip.stack.SIPDialog@bdb859 retval gov.nist.javax.sip.stack.SIPDialog@bdb859] (41845 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (41846 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]] (41846 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@6bc73bnevents 1] (41846 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]source = gov.nist.javax.sip.SipProviderImpl@91f61c] (41846 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 487 Request Terminated ] (41846 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (41847 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@bac3faa] (41847 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: 1223304891302 Outgoing call response received: SIP/2.0 487 Request Terminated To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=dfbz9t CSeq: 1 INVITE Call-ID: bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 From: <sip:alice@192.168.0.145>;tag=2078061508 Content-Length: 0 (41848 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508:dfbz9t=gov.nist.javax.sip.stack.SIPDialog@bdb859} default dialog gov.nist.javax.sip.stack.SIPDialog@bdb859 retval gov.nist.javax.sip.stack.SIPDialog@bdb859] (46786 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.fireTimeoutTimer(SIPClientTransaction.java:1037) [fireTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (46786 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {bb713af1f5b3c3fe0ab24d866c097479@192.168.0.145:2078061508=gov.nist.javax.sip.stack.SIPDialog@bdb859} default dialog gov.nist.javax.sip.stack.SIPDialog@bdb859 retval gov.nist.javax.sip.stack.SIPDialog@bdb859] (46787 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a branchID = z9hG4bK471e0355fac46b91fc24a51ccbdcc1c3 isClient = true] (46787 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:1088][SIPTransaction.java:632][SIPClientTransaction.java:268][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (47288 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction$TransactionTimer.runTask(SIPClientTransaction.java:201) [removing = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a isReliable false] (47288 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel transaction = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (47288 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1288) [REMOVED client tx gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a KEY = z9hg4bk471e0355fac46b91fc24a51ccbdcc1c3:cancel] (47288 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484athis.sipListener = org.cafesip.sipunit.SipStack@c57f88sipEvent.source = gov.nist.javax.sip.SipProviderImpl@91f61c] (47289 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:1300][SIPClientTransaction.java:206][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (47289 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@e99db4] (47289 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@e99db4nevents 1] (47289 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]source = gov.nist.javax.sip.SipProviderImpl@91f61c] (47289 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (47290 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = gov.nist.javax.sip.stack.SIPClientTransaction@cb0a484a] (47291 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = null] (49839 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]currentTransaction = nullthis.sipListener = org.cafesip.sipunit.SipStack@c57f88sipEvent.source = gov.nist.javax.sip.SipProviderImpl@91f61c] (49839 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:590][SIPDialog.java:178][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (49840 ms) [Timer-6] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@70cdd2] (49841 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@70cdd2nevents 1] (49842 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@91f61c]source = gov.nist.javax.sip.SipProviderImpl@91f61c] (63849 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@bdb859newState = 3] (63850 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]] (63850 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (63850 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (63851 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (64852 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (64852 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (64853 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (65853 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (65854 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (65854 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]