(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} ] (7 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>] (8 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (9 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (12 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (47 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (240 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:704) [Created Message Processor: 192.168.0.145 port = 5071 transport = udp] (252 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@7aa2a8 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@4ce427] (252 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@4ce427] (260 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@d38976] (263 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} ] (263 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (264 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (264 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (264 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (265 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (265 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (266 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] (267 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@479ef9 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@162a9c] (268 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@162a9c] (268 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@47a8f3] (270 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} ] (270 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (270 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (271 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent3" name="null" /> ] (272 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (272 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (273 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (274 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] (274 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@a4edc4 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@f5eb7f] (275 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@f5eb7f] (275 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@381a53] (443 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 ] (445 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] (446 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(013c1a8b0d034142ec3eb4790241b0df@192.168.0.145:79791326) : returning null] (449 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (458 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (458 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][B2buaTest.java:75][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]] (460 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3] (461 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk7dd98eb6e846ff0cdf1ff84c64415fc3] (462 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3] (464 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (476 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (479 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (479 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@f8acd079791326/null] (479 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk7dd98eb6e846ff0cdf1ff84c64415fc3/false] (480 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][B2buaTest.java:75][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]] (480 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@f8acd0] (481 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (484 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][B2buaTest.java:75][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]] (484 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145:79791326sipDialog = gov.nist.javax.sip.stack.SIPDialog@f8acd0] (487 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: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (488 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: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (488 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (489 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3] (490 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@96cdfbde branchID = z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 isClient = true] (490 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][B2buaTest.java:75][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]] (491 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde tickCount 64 currentTickCount = -1] (492 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][B2buaTest.java:75][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]] (493 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: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (493 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (498 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (499 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (499 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (499 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="1223304328290" isSender="true" transactionId="z9hg4bk7dd98eb6e846ff0cdf1ff84c64415fc3" callId="013c1a8b0d034142ec3eb4790241b0df@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: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (500 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (500 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304328300 INVITE after sending out through stack.......... (499 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 303] (503 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 ] SIPUNIT TRACE: 1223304328303 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 SIPUNIT TRACE: 1223304328303 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> SIPUNIT TRACE: 1223304328303 SS.waitRequest() - about to block, waiting (506 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (506 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (507 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304328302" isSender="false" transactionId="z9hg4bkerccfh" callId="uipthr" firstLine="INVITE sip:bob@192.168.0.145:5072 SIP/2.0" > <![CDATA[INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (507 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (507 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (509 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkerccfh] (513 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (514 ms) [Thread-9] DEBUG: testAgent2#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]] (514 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKerccfh] (514 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( INVITE:z9hG4bKerccfh):gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (519 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for INVITE sip:bob@192.168.0.145:5072 SIP/2.0 gov.nist.javax.sip.DialogFilter@6e056e messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (519 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (519 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (520 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (520 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process INVITE sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (521 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (521 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (521 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKerccfh] (521 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e branchID = z9hG4bKerccfh isClient = false] (522 ms) [Thread-9] DEBUG: testAgent2#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]] (522 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (523 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e listening point = 192.168.0.145:5072] (523 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Proceeding Transaction] (523 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(uipthr:o6eybu) : returning null] (525 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = uipthr:o6eybu] (525 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (525 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [INVITE transaction.isMapped = false] (525 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@489c06]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8ethis.sipListener = org.cafesip.sipunit.SipStack@47a8f3sipEvent.source = gov.nist.javax.sip.SipProviderImpl@489c06] (526 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (526 ms) [Thread-9] DEBUG: testAgent2#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]] (527 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@717ef5] (527 ms) [Thread-9] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing INVITE sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (527 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@717ef5nevents 1] (528 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@489c06]source = gov.nist.javax.sip.SipProviderImpl@489c06] (528 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : INVITE sip:bob@192.168.0.145:5072 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e sipEvent.serverTx = null] (529 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkerccfh existing={}] (529 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkerccfh] (529 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (530 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (530 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] SIPUNIT TRACE: 1223304328341 SipStack: request received ! SIPUNIT TRACE: 1223304328341 SipStack: calling listener SIPUNIT TRACE: 1223304328341 SipSession: request received ! SIPUNIT TRACE: 1223304328341 me ('To' check) = sip:bob@192.168.0.145 SIPUNIT TRACE: 1223304328341 my local contact info ('Request URI' check) = sip:bob@192.168.0.145:5072;lr;transport=udp SIPUNIT TRACE: 1223304328341 INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304328341 SipSession: notifying block object (542 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (543 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (543 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] SIPUNIT TRACE: 1223304328342 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304328342 SS.waitRequest() - either we got the request, or timed out (543 ms) [EventScannerThread] DEBUG: testAgent2#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]] (543 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkerccfh] SIPUNIT TRACE: 1223304328343 INVITE after received by stack.......... SIPUNIT TRACE: 1223304328343 INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 Content-Length: 0 (544 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (545 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkerccfh existing={}] (545 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (545 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$SendTrying.<init>(SIPServerTransaction.java:299) [scheduled timer for gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (546 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkerccfh] (546 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkerccfh] (547 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(uipthr:o6eybu) : returning null] (548 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:alice@192.168.0.145>] (548 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@65d588/1] (548 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@65d588null/o6eybu] (548 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkerccfh/true] (549 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:497][B2buaTest.java:80][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]] (549 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@65d588] (549 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5072] (550 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:497][B2buaTest.java:80][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]] (551 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e dialog = gov.nist.javax.sip.stack.SIPDialog@65d588] (551 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (552 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@65d588state = null] SIPUNIT TRACE: 1223304328354 Response before sending out through stack.......... SIPUNIT TRACE: 1223304328354 SIP/2.0 404 Not found To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1515598620 CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 (555 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@65d588 lastResponse = SIP/2.0 404 Not found ] (557 ms) [main] DEBUG: testAgent2#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:1253][SipCall.java:1212][B2buaTest.java:85][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]] (557 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (559 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (559 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (560 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 404] (560 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (561 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (561 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalTag(SIPDialog.java:1317) [set Local tag 1515598620 null] (561 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1319][SIPDialog.java:2280][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:85][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]] (562 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@65d588newState = 3] (564 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2295][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:85][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]] (564 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@65d588 old dialog state is null] (565 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@65d588 New dialog state is Terminated Dialog] (565 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@489c06]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8ethis.sipListener = org.cafesip.sipunit.SipStack@47a8f3sipEvent.source = gov.nist.javax.sip.SipProviderImpl@489c06] (566 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPServerTransaction.java:1415][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:85][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]] (566 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@4b2819] (567 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e branchID = z9hG4bKerccfh isClient = false] (568 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@4b2819nevents 1] (568 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@489c06]source = gov.nist.javax.sip.SipProviderImpl@489c06] (569 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:999][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:85][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]] (569 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e tickCount 64 currentTickCount = -1] (570 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e getState = Completed Transaction] (570 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (571 ms) [main] DEBUG: testAgent2#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:1253][SipCall.java:1212][B2buaTest.java:85][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]] (573 ms) [main] DEBUG: testAgent2#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 404 Not found To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1515598620 CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 ] (575 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (575 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 404 Not found To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1515598620 CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 ] (579 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (579 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 263] (580 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (580 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 305] (580 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [ACK sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1515598620 Content-Length: 0 CSeq: 1 ACK Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 ] (582 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (587 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (587 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304328380" isSender="false" transactionId="z9hg4bkerccfh" callId="uipthr" firstLine="ACK sip:bob@192.168.0.145:5072 SIP/2.0" > <![CDATA[ACK sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1515598620 CSeq: 1 ACK Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (587 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (587 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (591 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (592 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( ACK:z9hG4bKerccfh):gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (592 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for ACK sip:bob@192.168.0.145:5072 SIP/2.0 gov.nist.javax.sip.DialogFilter@364ef messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (591 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 404 Not found (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm Content-Length: 0 CSeq: 1 INVITE Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 From: <sip:alice@192.168.0.145>;tag=79791326 ] (592 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (593 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (593 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (594 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process ACK sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (594 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: ACK sip:bob@192.168.0.145:5072 SIP/2.0 ] (594 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = Completed Transaction] (594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde] (594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (594 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (594 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Confirmed Transaction gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e branchID = z9hG4bKerccfh isClient = false] (591 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (598 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5072" to="192.168.0.145:5060" time="1223304328372" isSender="true" transactionId="z9hg4bkerccfh" callId="uipthr" firstLine="SIP/2.0 404 Not found" > <![CDATA[SIP/2.0 404 Not found To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1515598620 CSeq: 1 INVITE Call-ID: uipthr Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKerccfh From: <sip:alice@192.168.0.145>;tag=o6eybu Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (598 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (598 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (599 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223304328394" isSender="false" transactionId="z9hg4bk7dd98eb6e846ff0cdf1ff84c64415fc3" callId="013c1a8b0d034142ec3eb4790241b0df@192.168.0.145" firstLine="SIP/2.0 404 Not found (relayed)" > <![CDATA[SIP/2.0 404 Not found (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm CSeq: 1 INVITE Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 From: <sip:alice@192.168.0.145>;tag=79791326 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (599 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (599 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (599 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk7dd98eb6e846ff0cdf1ff84c64415fc3] (597 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:747][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (600 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e tickCount 10 currentTickCount = 64] (600 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:768) [ACK received for server Tx z9hg4bkerccfh not delivering to application!] (604 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde for SIP/2.0 404 Not found (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm CSeq: 1 INVITE Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 From: <sip:alice@192.168.0.145>;tag=79791326 Content-Length: 0 ] (604 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (605 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (604 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde to gov.nist.javax.sip.DialogFilter@fa157c] (607 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkerccfh] (604 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (629 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPServerTransaction.java:775][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (630 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (630 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][SIPServerTransaction.java:1702][UDPMessageChannel.java:461][UDPMessageChannel.java:255][Thread.java:613]] (630 ms) [Thread-10] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing ACK sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@d896fa8e] (628 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (807 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@f8acd0 lastResponse = SIP/2.0 404 Not found (relayed) ] (809 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (809 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (809 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (810 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (810 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 404] (811 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde] (811 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (811 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@f8acd0newState = 3] (811 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2205][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (811 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@f8acd0 old dialog state is null] (812 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@f8acd0 New dialog state is Terminated Dialog] (814 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145:79791326:b2uemmsipDialog = gov.nist.javax.sip.stack.SIPDialog@f8acd0] (814 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 404 Not found (relayed) current state = Calling Transaction] (814 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@f8acd0] (815 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@f8acd0 lastResponse = SIP/2.0 404 Not found (relayed) ] (815 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (817 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145:79791326:b2uemmsipDialog = gov.nist.javax.sip.stack.SIPDialog@f8acd0] (818 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:423) [Sending Message ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (818 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState Calling Transaction] (818 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde branchID = z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 isClient = true] (819 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:440][SIPClientTransaction.java:813][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (819 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[UDPMessageChannel.java:604][MessageChannel.java:183][SIPTransaction.java:739][SIPClientTransaction.java:446][SIPClientTransaction.java:813][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (819 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:613) [gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 127.0.0.1/5060 ACK sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 ] (820 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (820 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (820 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (821 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5071" to="127.0.0.1:5060" time="1223304328618" isSender="true" transactionId="z9hg4bk7dd98eb6e846ff0cdf1ff84c64415fc3" callId="013c1a8b0d034142ec3eb4790241b0df@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: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Max-Forwards: 70 From: <sip:alice@192.168.0.145>;tag=79791326 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 CSeq: 1 ACK Route: <sip:127.0.0.1:5060;lr;transport=udp> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (822 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (822 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (822 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 404 Not found (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm CSeq: 1 INVITE Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 From: <sip:alice@192.168.0.145>;tag=79791326 Content-Length: 0 ] (823 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde] (823 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@f8acd0 lastResponse = SIP/2.0 404 Not found (relayed) ] (823 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (824 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145:79791326:b2uemmsipDialog = gov.nist.javax.sip.stack.SIPDialog@f8acd0] (824 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@199049]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbdethis.sipListener = org.cafesip.sipunit.SipStack@d38976sipEvent.source = gov.nist.javax.sip.SipProviderImpl@199049] (824 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@f8acd0] (824 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:832][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (825 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@988d36] (825 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde branchID = z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 isClient = true] (825 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@988d36nevents 1] (826 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@199049]source = gov.nist.javax.sip.SipProviderImpl@199049] (826 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 404 Not found (relayed) ] (826 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (827 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde] (827 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]] (826 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:839][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (828 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde tickCount 64 currentTickCount = 64] (828 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@96cdfbde] (828 ms) [Thread-11] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] SIPUNIT TRACE: 1223304328630 Outgoing call response received: SIP/2.0 404 Not found (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=b2uemm CSeq: 1 INVITE Call-ID: 013c1a8b0d034142ec3eb4790241b0df@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bK7dd98eb6e846ff0cdf1ff84c64415fc3 From: <sip:alice@192.168.0.145>;tag=79791326 Content-Length: 0 (832 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {013c1a8b0d034142ec3eb4790241b0df@192.168.0.145:79791326:b2uemm=gov.nist.javax.sip.stack.SIPDialog@f8acd0} default dialog gov.nist.javax.sip.stack.SIPDialog@f8acd0 retval gov.nist.javax.sip.stack.SIPDialog@f8acd0] (832 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@f8acd0newState = 3] (833 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]] (834 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@65d588newState = 3] (834 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:1334][SipCall.java:158][SipPhone.java:1231][TestBase.java:250][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]] (835 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (835 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (844 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (1845 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (1845 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (1846 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (2847 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (2851 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (2852 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (3854 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5071 transport = udp] (3855 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (3856 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] (3857 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@e5ed7b listeningPoint = gov.nist.javax.sip.ListeningPointImpl@4a4e31] (3857 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@4a4e31] (3858 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@538cc2] (3858 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5072 transport = udp] (3858 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (3859 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] (3864 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@3e2b4a listeningPoint = gov.nist.javax.sip.ListeningPointImpl@8c1852] (3864 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@8c1852] (3864 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@90ed52] (3865 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:667) [createListeningPoint : address = 192.168.0.145 port = 5073 transport = udp] (3865 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.reInit(SIPTransactionStack.java:406) [Re-initializing !] (3866 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] (3866 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.MessageProcessor.setListeningPoint(MessageProcessor.java:179) [setListeningPointgov.nist.javax.sip.stack.UDPMessageProcessor@ccbdf7 listeningPoint = gov.nist.javax.sip.ListeningPointImpl@cbc2d3] (3866 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipStackImpl.createSipProvider(SipStackImpl.java:735) [createSipProvider: gov.nist.javax.sip.ListeningPointImpl@cbc2d3] (3867 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.addSipListener(SipProviderImpl.java:203) [add SipListener org.cafesip.sipunit.SipStack@63d208] (3868 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 ] (3872 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] (3873 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382) : returning null] (3873 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 127.0.0.1/5060] (3874 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (3874 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][B2buaTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3875 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKe0217a12e0ab147a46595fd25ae3a059] (3875 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bke0217a12e0ab147a46595fd25ae3a059] (3876 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKe0217a12e0ab147a46595fd25ae3a059] (3877 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3877 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:JSR289_TCK@127.0.0.1:5060>] (3877 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalSequenceNumber(SIPDialog.java:1207) [setLocalSequenceNumber: original 0 new = 1] (3878 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@7237041802412382/null] (3879 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bke0217a12e0ab147a46595fd25ae3a059/false] (3879 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][B2buaTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3879 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@723704] (3880 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5071] (3880 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][B2buaTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3881 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382sipDialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3881 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: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1802412382 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (3882 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: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1802412382 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (3882 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (3883 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKe0217a12e0ab147a46595fd25ae3a059] (3883 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@a2c1e4df branchID = z9hG4bKe0217a12e0ab147a46595fd25ae3a059 isClient = true] (3884 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][B2buaTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3884 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df tickCount 64 currentTickCount = -1] (3885 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][B2buaTest.java:141][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3885 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: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1802412382 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 ] (3886 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (3887 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} ] (3887 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (3888 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (3888 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent" name="null" /> ] (3888 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (3889 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (3889 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (3890 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (3890 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="1223304331683" isSender="true" transactionId="z9hg4bke0217a12e0ab147a46595fd25ae3a059" callId="703f0c0e578d16800b1e13db2c07dbe5@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: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1802412382 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (3891 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (3891 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304331691 INVITE after sending out through stack.......... SIPUNIT TRACE: 1223304331691 INVITE sip:JSR289_TCK@127.0.0.1:5060 SIP/2.0 Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 CSeq: 1 INVITE From: <sip:alice@192.168.0.145>;tag=1802412382 To: <sip:JSR289_TCK@127.0.0.1:5060> Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 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: B2bua Application-Name: com.bea.sipservlet.tck.apps.spectestapp.b2bua private-uri: sip:bob@192.168.0.145:5072 Content-Length: 0 SIPUNIT TRACE: 1223304331691 RouteHeader address: <sip:127.0.0.1:5060;lr;transport=udp> SIPUNIT TRACE: 1223304331691 SS.waitRequest() - about to block, waiting (3892 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (3893 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 303] (3894 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 ] (3896 ms) [Thread-21] 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} ] (3897 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:276) [ &#x5d;&#x5d;&gt;] (3898 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:277) [</debug>] (3898 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:278) [<description logDescription="testAgent2" name="null" /> ] (3898 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:284) [<debug>] (3899 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.checkLogFile(ServerLog.java:285) [<![CDATA[ ] (3899 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (3899 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (3900 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304331693" isSender="false" transactionId="z9hg4bkrh6hhe" callId="afp8lm" firstLine="INVITE sip:bob@192.168.0.145:5072 SIP/2.0" > <![CDATA[INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (3900 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (3900 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (3900 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkrh6hhe] (3900 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (3901 ms) [Thread-21] DEBUG: testAgent2#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]] (3901 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKrh6hhe] (3901 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( INVITE:z9hG4bKrh6hhe):gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3902 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for INVITE sip:bob@192.168.0.145:5072 SIP/2.0 gov.nist.javax.sip.DialogFilter@ad7c0 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3902 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3902 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (3903 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (3903 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process INVITE sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3904 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (3904 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (3905 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKrh6hhe] (3905 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4 branchID = z9hG4bKrh6hhe isClient = false] (3905 ms) [Thread-21] DEBUG: testAgent2#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]] (3907 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (3907 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4 listening point = 192.168.0.145:5072] (3907 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Proceeding Transaction] (3908 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(afp8lm:xle663) : returning null] (3908 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = afp8lm:xle663] (3908 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = null] (3909 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [INVITE transaction.isMapped = false] (3910 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4this.sipListener = org.cafesip.sipunit.SipStack@90ed52sipEvent.source = gov.nist.javax.sip.SipProviderImpl@da9246] (3910 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = null] (3910 ms) [Thread-21] DEBUG: testAgent2#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]] (3911 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@b94ed3] (3911 ms) [Thread-21] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing INVITE sip:bob@192.168.0.145:5072 SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3912 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@b94ed3nevents 1] (3912 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]source = gov.nist.javax.sip.SipProviderImpl@da9246] (3912 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : INVITE sip:bob@192.168.0.145:5072 SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4 sipEvent.serverTx = null] (3913 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkrh6hhe existing={}] (3913 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bkrh6hhe] (3916 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3917 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (3917 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] SIPUNIT TRACE: 1223304331716 SipStack: request received ! SIPUNIT TRACE: 1223304331716 SipStack: calling listener SIPUNIT TRACE: 1223304331716 SipSession: request received ! SIPUNIT TRACE: 1223304331716 me ('To' check) = sip:bob@192.168.0.145 SIPUNIT TRACE: 1223304331716 my local contact info ('Request URI' check) = sip:bob@192.168.0.145:5072;lr;transport=udp SIPUNIT TRACE: 1223304331716 INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304331716 SipSession: notifying block object SIPUNIT TRACE: 1223304331716 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304331716 SS.waitRequest() - either we got the request, or timed out SIPUNIT TRACE: 1223304331716 INVITE after received by stack.......... SIPUNIT TRACE: 1223304331716 INVITE sip:bob@192.168.0.145:5072 SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060> Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 (3917 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (3917 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3919 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bkrh6hhe existing={}] (3919 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3919 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message INVITE sip:bob@192.168.0.145:5072 SIP/2.0 ] (3919 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$SendTrying.<init>(SIPServerTransaction.java:299) [scheduled timer for gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3919 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3920 ms) [EventScannerThread] DEBUG: testAgent2#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]] (3920 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkrh6hhe] (3920 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkrh6hhe] (3921 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bkrh6hhe] (3921 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(afp8lm:xle663) : returning null] (3921 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteParty(SIPDialog.java:428) [settingRemoteParty <sip:alice@192.168.0.145>] (3930 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@4adb34/1] (3930 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@4adb34null/xle663] (3930 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bkrh6hhe/true] (3930 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:312][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:497][B2buaTest.java:146][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]] (3931 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:314) [Creating a dialog : gov.nist.javax.sip.stack.SIPDialog@4adb34] (3931 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.<init>(SIPDialog.java:315) [provider port = 5072] (3931 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:317][SIPTransactionStack.java:537][SipProviderImpl.java:481][SipCall.java:497][B2buaTest.java:146][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]] (3932 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4 dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (3932 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3933 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@4adb34state = null] SIPUNIT TRACE: 1223304331732 Response before sending out through stack.......... SIPUNIT TRACE: 1223304331732 SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 (3933 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3934 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@4adb34 lastResponse = SIP/2.0 200 OK ] (3934 ms) [main] DEBUG: testAgent2#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:1253][SipCall.java:1212][B2buaTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3934 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (3935 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (3935 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (3936 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (3936 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (3936 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3937 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLocalTag(SIPDialog.java:1317) [set Local tag 1110338167 null] (3937 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1319][SIPDialog.java:2280][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3937 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@4adb34newState = 1] (3938 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2299][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3938 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@4adb34 old dialog state is null] (3939 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@4adb34 New dialog state is Confirmed Dialog] (3939 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=afp8lm:1110338167:xle663 dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (3940 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2301][SIPServerTransaction.java:1407][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3940 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.startTimer(SIPDialog.java:1902) [Starting dialog timer for afp8lm:1110338167:xle663] (3941 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4 branchID = z9hG4bKrh6hhe isClient = false] (3941 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:994][SIPServerTransaction.java:1437][SipSession.java:2041][SipSession.java:1864][SipCall.java:1095][SipCall.java:1253][SipCall.java:1212][B2buaTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3941 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4 getState = Terminated Transaction] (3943 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (3943 ms) [main] DEBUG: testAgent2#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:1253][SipCall.java:1212][B2buaTest.java:151][NativeMethodAccessorImpl.java:-2][NativeMethodAccessorImpl.java:39][DelegatingMethodAccessorImpl.java:25][Method.java:585][TestCase.java:154][TestCase.java:127][TestResult.java:106][TestResult.java:124][TestResult.java:109][TestCase.java:118][TestHandler.java:73][TestHandler.java:58][TestHandler.java:34][null:-1][TestProxy.java:24][TckJUnitTestRunner.java:272][TckJUnitTestRunner.java:647][TckJUnitTestRunner.java:542]] (3947 ms) [main] DEBUG: testAgent2#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:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 ] (3948 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (3948 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:698) [sendMessage 192.168.0.145/5060 SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 ] (3950 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (3950 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (3951 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (3952 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 349] (3952 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Content-Length: 0 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 From: <sip:alice@192.168.0.145>;tag=1802412382 ] (3953 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (3953 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (3953 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (3953 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (3954 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (3954 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="127.0.0.1:5060" to="192.168.0.145:5071" time="1223304331752" isSender="false" transactionId="z9hg4bke0217a12e0ab147a46595fd25ae3a059" callId="703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145" firstLine="SIP/2.0 200 OK (relayed)" > <![CDATA[SIP/2.0 200 OK (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 From: <sip:alice@192.168.0.145>;tag=1802412382 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (3954 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (3951 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5072" to="192.168.0.145:5060" time="1223304331746" isSender="true" transactionId="z9hg4bkrh6hhe" callId="afp8lm" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 INVITE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKrh6hhe From: <sip:alice@192.168.0.145>;tag=xle663 Contact: <sip:bob@192.168.0.145:5072;lr;transport=udp> Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (3954 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (3957 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bke0217a12e0ab147a46595fd25ae3a059] (3957 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df for SIP/2.0 200 OK (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 From: <sip:alice@192.168.0.145>;tag=1802412382 Content-Length: 0 ] (3958 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df to gov.nist.javax.sip.DialogFilter@ca5b68] (3958 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3958 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@723704 lastResponse = SIP/2.0 200 OK (relayed) ] (3958 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3958 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (3959 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = null] (3959 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (3959 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (3959 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (3959 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3959 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteTag(SIPDialog.java:1166) [setRemoteTag(): gov.nist.javax.sip.stack.SIPDialog@723704 remoteTag = null new tag = u4kt34] (3960 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putDialog(SIPTransactionStack.java:518) [putDialog dialogId=703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34 dialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3961 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:523][SIPDialog.java:2186][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3961 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:533) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@723704state = null] (3961 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:581][SIPDialog.java:2187][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3961 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@723704newState = 1] (3962 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (3962 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (3962 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bkrh6hhe] (3963 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:2189][SIPClientTransaction.java:1409][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3963 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@723704 old dialog state is null] (3963 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@723704 New dialog state is Confirmed Dialog] (3964 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34sipDialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3964 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK (relayed) current state = Calling Transaction] (3965 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3965 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@723704 lastResponse = SIP/2.0 200 OK (relayed) ] (3965 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][SIPClientTransaction.java:538][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3965 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (3965 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (3966 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (3966 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (3966 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (3966 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction$LingerTimer.<init>(SIPTransaction.java:261) [LingerTimer : z9hg4bkrh6hhe] (3966 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3966 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34sipDialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3967 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df branchID = z9hG4bKe0217a12e0ab147a46595fd25ae3a059 isClient = true] (3967 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPClientTransaction.java:1300][SIPClientTransaction.java:787][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3967 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 From: <sip:alice@192.168.0.145>;tag=1802412382 Content-Length: 0 ] (3968 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (3968 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@723704 lastResponse = SIP/2.0 200 OK (relayed) ] (3968 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:2146][DialogFilter.java:1065][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3969 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = INVITE] (3969 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (3969 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (3969 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (3969 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (3970 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (3970 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34sipDialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3970 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4dfthis.sipListener = org.cafesip.sipunit.SipStack@538cc2sipEvent.source = gov.nist.javax.sip.SipProviderImpl@79edfe] (3970 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@723704] (3970 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:1069][SIPClientTransaction.java:791][SIPClientTransaction.java:544][SIPClientTransaction.java:1444][UDPMessageChannel.java:496][UDPMessageChannel.java:255][Thread.java:613]] (3971 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@ff87dc] (3971 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (3972 ms) [Thread-22] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (3972 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@ff87dcnevents 1] (3972 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]source = gov.nist.javax.sip.SipProviderImpl@79edfe] (3973 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK (relayed) ] (3973 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (3974 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:331) [Garbage collecting unacknowledged dialog] (3974 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] SIPUNIT TRACE: 1223304331773 Outgoing call response received: SIP/2.0 200 OK (relayed) To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Contact: <sip:192.168.0.145:5060;transport=udp> CSeq: 1 INVITE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5071;branch=z9hG4bKe0217a12e0ab147a46595fd25ae3a059 From: <sip:alice@192.168.0.145>;tag=1802412382 Content-Length: 0 (3974 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]] (3974 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34=gov.nist.javax.sip.stack.SIPDialog@723704} default dialog gov.nist.javax.sip.stack.SIPDialog@723704 retval gov.nist.javax.sip.stack.SIPDialog@723704] (4079 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@723704] (4079 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (4080 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@723704] (4081 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (4081 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (4081 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (4082 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:633) [sendAckgov.nist.javax.sip.stack.SIPDialog@723704] (4082 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:658) [setting from tag For outgoing ACK= 1802412382] (4082 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:661) [setting To tag for outgoing ACK = u4kt34] (4082 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=z9hG4bKd0c0be0afd49d27ef6c8abb1633ea016 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1802412382 Max-Forwards: 70 Content-Length: 0 ] (4083 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] (4083 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendAck(SIPDialog.java:680) [hop = 192.168.0.145:5060/udp] (4083 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (4084 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][B2buaTest.java:162][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]] (4085 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=z9hG4bKd0c0be0afd49d27ef6c8abb1633ea016 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1802412382 Max-Forwards: 70 Content-Length: 0 ] (4085 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (4085 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=z9hG4bKd0c0be0afd49d27ef6c8abb1633ea016 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1802412382 Max-Forwards: 70 Content-Length: 0 ] (4086 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4086 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4087 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="1223304331884" isSender="true" transactionId="z9hg4bkd0c0be0afd49d27ef6c8abb1633ea016" callId="703f0c0e578d16800b1e13db2c07dbe5@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=z9hG4bKd0c0be0afd49d27ef6c8abb1633ea016 CSeq: 1 ACK To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 From: <sip:alice@192.168.0.145>;tag=1802412382 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4090 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4091 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304331890 SS.waitRequest() - about to block, waiting (4090 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (4091 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 364] (4091 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Content-Length: 0 CSeq: 1 ACK Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bK6sk95x;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.b2bua From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 ] (4092 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4092 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4093 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304331890" isSender="false" transactionId="z9hg4bk6sk95x" callId="afp8lm" firstLine="ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0" > <![CDATA[ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 ACK Call-ID: afp8lm 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.b2bua;branch=z9hG4bK6sk95x From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4093 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4093 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4093 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bk6sk95x] (4093 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (4095 ms) [Thread-23] DEBUG: testAgent2#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]] (4095 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK6sk95x] (4095 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( ACK:z9hG4bK6sk95x):gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4095 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest(NistSipMessageFactoryImpl.java:84) [Returning request interface for ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 gov.nist.javax.sip.DialogFilter@9719f4 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4095 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4096 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (4096 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (4096 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:452) [About to process ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4096 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:714) [processRequest: ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 ] (4097 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (4097 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK6sk95x] (4097 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d branchID = z9hG4bK6sk95x isClient = false] (4097 ms) [Thread-23] DEBUG: testAgent2#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]] (4098 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (4098 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:89) [PROCESSING INCOMING REQUEST ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 ACK Call-ID: afp8lm 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.b2bua;branch=z9hG4bK6sk95x From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d listening point = 192.168.0.145:5072] (4099 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (4099 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(afp8lm:1110338167:xle663) : returning gov.nist.javax.sip.stack.SIPDialog@4adb34] (4099 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = afp8lm:1110338167:xle663] (4099 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4099 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:262) [Processing ACK for dialog gov.nist.javax.sip.stack.SIPDialog@4adb34] (4101 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4101 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.ackReceived(SIPDialog.java:754) [ackReceived for INVITE] (4102 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:884) [isServer = true] (4102 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:885) [localTag = 1110338167] (4102 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:886) [remoteTag = xle663] (4102 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:887) [localSequenceNumer = 0] (4102 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:889) [remoteSequenceNumer = 1] (4102 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.printDebugInfo(SIPDialog.java:891) [ackLine:xle663 266] (4103 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@4adb34newState = 1] (4103 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:759][SIPDialog.java:2663][DialogFilter.java:286][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (4103 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.handleAck(SIPDialog.java:2664) [ACK for 2XX response --- sending to TU ] (4103 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@4adb34/1] (4103 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@4adb341110338167/xle663] (4104 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk6sk95x/true] (4104 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][DialogFilter.java:290][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (4105 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addRoute(SIPDialog.java:956) [setContact: dialogState: gov.nist.javax.sip.stack.SIPDialog@4adb34state = Confirmed Dialog] (4105 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4105 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : ACK returning false] (4106 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [ACK transaction.isMapped = true] (4106 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@88744c4dthis.sipListener = org.cafesip.sipunit.SipStack@90ed52sipEvent.source = gov.nist.javax.sip.SipProviderImpl@da9246] (4106 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4107 ms) [Thread-23] DEBUG: testAgent2#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]] (4107 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@8ab721] (4107 ms) [Thread-23] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:466) [Done processing ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 /gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4108 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@8ab721nevents 1] (4108 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]source = gov.nist.javax.sip.SipProviderImpl@da9246] (4108 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:148) [deliverEvent : ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 transaction gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d sipEvent.serverTx = gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4108 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bk6sk95x existing={z9hg4bkrh6hhe=gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4}] (4108 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bk6sk95x] (4109 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4109 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:215) [Calling listener ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 ] (4109 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] SIPUNIT TRACE: 1223304331909 SipStack: request received ! SIPUNIT TRACE: 1223304331909 SipStack: calling listener SIPUNIT TRACE: 1223304331909 SipSession: request received ! SIPUNIT TRACE: 1223304331909 me ('To' check) = sip:bob@192.168.0.145 SIPUNIT TRACE: 1223304331909 my local contact info ('Request URI' check) = sip:bob@192.168.0.145:5072;lr;transport=udp SIPUNIT TRACE: 1223304331909 ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 To: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 CSeq: 1 ACK Call-ID: afp8lm 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.b2bua;branch=z9hG4bK6sk95x From: <sip:alice@192.168.0.145>;tag=xle663 Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304331909 SipSession: notifying block object (4110 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:226) [Done processing Message ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 ] (4110 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:803) [Request Consumed -- next consumable Request Seqno = 2] (4110 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:246) [Done processing Message ACK sip:bob@192.168.0.145:5072;lr;transport=udp SIP/2.0 ] (4110 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d] (4111 ms) [EventScannerThread] DEBUG: testAgent2#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]] (4111 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bk6sk95x] (4111 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPServerTransaction@88744c4d branchID = z9hG4bK6sk95x isClient = false] (4111 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][EventScanner.java:267][EventScanner.java:492][Thread.java:613]] SIPUNIT TRACE: 1223304331910 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304331910 SS.waitRequest() - either we got the request, or timed out (4112 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:593) [getRouteList gov.nist.javax.sip.stack.SIPDialog@4adb34] (4112 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:608) [----- ] (4112 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:609) [getRouteList for gov.nist.javax.sip.stack.SIPDialog@4adb34] (4112 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:611) [RouteList = ] (4114 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:613) [myRouteList = ] (4115 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.getRouteList(SIPDialog.java:615) [----- ] (4115 ms) [main] DEBUG: testAgent2#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 ] (4115 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.DefaultRouter.getNextHop(DefaultRouter.java:234) [Used request-URI for nextHop = 192.168.0.145:5060/udp] (4116 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(afp8lm:1110338167:xle663) : returning gov.nist.javax.sip.stack.SIPDialog@4adb34] (4116 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (4116 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.<init>(SIPClientTransaction.java:301) [Creating clientTransaction gov.nist.javax.sip.stack.SIPClientTransaction@ffffffff] (4117 ms) [main] DEBUG: testAgent2#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][B2buaTest.java:172][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]] (4118 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK6cc1eeac02d15a7f184854b65f9a533f] (4119 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1353) [ putTransactionHash : key = z9hg4bk6cc1eeac02d15a7f184854b65f9a533f] (4120 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK6cc1eeac02d15a7f184854b65f9a533f] (4120 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (4122 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: afp8lm:1110338167:xle663sipDialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4122 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1604) [dialog.sendRequest dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34 dialogRequest = BYE sip:192.168.0.145:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.0.145:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f CSeq: 1 BYE To: <sip:alice@192.168.0.145>;tag=xle663 Call-ID: afp8lm From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Max-Forwards: 70 Content-Length: 0 ] (4123 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: afp8lm:1110338167:xle663sipDialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4123 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@4adb341110338167/xle663] (4123 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bk6cc1eeac02d15a7f184854b65f9a533f/false] (4123 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:1154][SIPDialog.java:1652][SipSession.java:1201][SipCall.java:3605][SipCall.java:3547][B2buaTest.java:172][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]] (4129 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (4130 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.sendRequest(SIPDialog.java:1785) [using message channel gov.nist.javax.sip.stack.UDPMessageChannel@4920f8] (4130 ms) [main] DEBUG: testAgent2#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:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f CSeq: 1 BYE To: <sip:alice@192.168.0.145>;tag=xle663 Call-ID: afp8lm From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Max-Forwards: 70 Content-Length: 0 ] (4135 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.sendMessage(SIPClientTransaction.java:425) [TransactionState null] (4135 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bK6cc1eeac02d15a7f184854b65f9a533f] (4135 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e branchID = z9hG4bK6cc1eeac02d15a7f184854b65f9a533f isClient = true] (4135 ms) [main] DEBUG: testAgent2#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][B2buaTest.java:172][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]] (4137 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e tickCount 64 currentTickCount = -1] (4137 ms) [main] DEBUG: testAgent2#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][B2buaTest.java:172][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]] (4138 ms) [main] DEBUG: testAgent2#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:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f CSeq: 1 BYE To: <sip:alice@192.168.0.145>;tag=xle663 Call-ID: afp8lm From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Max-Forwards: 70 Content-Length: 0 ] (4138 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:616) [******************* ] (4139 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4139 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4140 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5072" to="192.168.0.145:5060" time="1223304331936" isSender="true" transactionId="z9hg4bk6cc1eeac02d15a7f184854b65f9a533f" callId="afp8lm" 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:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f CSeq: 1 BYE To: <sip:alice@192.168.0.145>;tag=xle663 Call-ID: afp8lm From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4141 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4142 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] SIPUNIT TRACE: 1223304331941 SS.waitRequest() - about to block, waiting (4141 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (4142 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 406] (4142 ms) [Thread-24] 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 To: <sip:alice@192.168.0.145>;tag=1802412382 Content-Length: 0 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145 Via: SIP/2.0/UDP 192.168.0.145:5060;branch=z9hG4bKlbkerx;x-sm-sid=192.168.0.145-55128;x-sm-aid=com.bea.sipservlet.tck.apps.spectestapp.b2bua From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Max-Forwards: 70 ] (4146 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4146 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4146 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5071" time="1223304331941" isSender="false" transactionId="z9hg4bklbkerx" callId="703f0c0e578d16800b1e13db2c07dbe5@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 To: <sip:alice@192.168.0.145>;tag=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Max-Forwards: 70 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4146 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4147 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4147 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bklbkerx] (4148 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.<init>(SIPServerTransaction.java:497) [Creating Server Transactionnull] (4148 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPServerTransaction.java:499][SIPTransactionStack.java:1206][SIPTransactionStack.java:1004][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (4148 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKlbkerx] (4148 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest(SIPTransactionStack.java:1019) [newSIPServerRequest( BYE:z9hG4bKlbkerx):gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4148 ms) [Thread-24] 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@99257 messageChannel = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4149 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4149 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1029][UDPMessageChannel.java:426][UDPMessageChannel.java:255][Thread.java:613]] (4149 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (4149 ms) [Thread-24] 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@e3ab1ad5] (4149 ms) [Thread-24] 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 ] (4150 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.processRequest(SIPServerTransaction.java:716) [tx state = null] (4150 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest(SIPTransaction.java:413) [Setting Branch id : z9hG4bKlbkerx] (4150 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Trying Transaction gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5 branchID = z9hG4bKlbkerx isClient = false] (4150 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:550][SIPServerTransaction.java:1484][SIPServerTransaction.java:726][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (4151 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] (4152 ms) [Thread-24] 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 To: <sip:alice@192.168.0.145>;tag=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Max-Forwards: 70 Content-Length: 0 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5 listening point = 192.168.0.145:5071] (4152 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:119) [transaction state = Trying Transaction] (4152 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.getDialog(SIPTransactionStack.java:608) [getDialog(703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34) : returning gov.nist.javax.sip.stack.SIPDialog@723704] (4153 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:191) [dialogId = 703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145:1802412382:u4kt34] (4153 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:192) [dialog = gov.nist.javax.sip.stack.SIPDialog@723704] (4153 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction(SIPTransactionStack.java:1317) [added transaction gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4153 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bklbkerx] (4153 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash(SIPTransactionStack.java:1359) [ putTransactionHash : key = z9hg4bklbkerx] (4154 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setRemoteSequenceNumber(SIPDialog.java:1223) [setRemoteSeqno gov.nist.javax.sip.stack.SIPDialog@723704/1] (4154 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1149) [Transaction Added gov.nist.javax.sip.stack.SIPDialog@7237041802412382/u4kt34] (4154 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.addTransaction(SIPDialog.java:1151) [TID = z9hg4bklbkerx/true] (4154 ms) [Thread-24] 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]] (4155 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.setDialog(SIPServerTransaction.java:1528) [setDialog gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5 dialog = gov.nist.javax.sip.stack.SIPDialog@723704] (4155 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:449) [BYE Tx = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5 isMapped =true] (4155 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:720) [BYE transaction.isMapped = true] (4156 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5this.sipListener = org.cafesip.sipunit.SipStack@538cc2sipEvent.source = gov.nist.javax.sip.SipProviderImpl@79edfe] (4156 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:140) [Dialog = gov.nist.javax.sip.stack.SIPDialog@723704] (4156 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][DialogFilter.java:939][SIPServerTransaction.java:822][UDPMessageChannel.java:456][UDPMessageChannel.java:255][Thread.java:613]] (4157 ms) [Thread-24] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@66c3a0] (4157 ms) [Thread-24] 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@e3ab1ad5] (4157 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@66c3a0nevents 1] (4157 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.RequestEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]source = gov.nist.javax.sip.SipProviderImpl@79edfe] (4157 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@e3ab1ad5 sipEvent.serverTx = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4158 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:733) [serverTx: looking for key z9hg4bklbkerx existing={z9hg4bklbkerx=gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5}] (4158 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction(SIPTransactionStack.java:843) [looking for pending tx for :z9hg4bklbkerx] (4158 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction(SIPTransactionStack.java:1487) [putPendingTransaction: gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4158 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 ] (4158 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:219) [Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] SIPUNIT TRACE: 1223304331957 SipStack: request received ! SIPUNIT TRACE: 1223304331957 SipStack: calling listener SIPUNIT TRACE: 1223304331958 SipSession: request received ! SIPUNIT TRACE: 1223304331958 me ('To' check) = sip:alice@192.168.0.145 SIPUNIT TRACE: 1223304331958 my local contact info ('Request URI' check) = sip:alice@192.168.0.145:5071;lr;transport=udp SIPUNIT TRACE: 1223304331958 BYE sip:alice@192.168.0.145:5071;lr;transport=udp SIP/2.0 To: <sip:alice@192.168.0.145>;tag=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Max-Forwards: 70 Content-Length: 0 SIPUNIT TRACE: 1223304331958 SipSession: notifying block object (4159 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 ] SIPUNIT TRACE: 1223304331958 SS.waitRequest() - we've come out of the block SIPUNIT TRACE: 1223304331958 SS.waitRequest() - either we got the request, or timed out (4159 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.requestConsumed(SIPDialog.java:803) [Request Consumed -- next consumable Request Seqno = 2] SIPUNIT TRACE: 1223304331958 Response before sending out through stack.......... (4159 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 ] (4160 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4161 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]] (4161 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bklbkerx] SIPUNIT TRACE: 1223304331960 SIP/2.0 200 OK To: <sip:alice@192.168.0.145>;tag=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Content-Length: 0 (4161 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (4161 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@723704 lastResponse = SIP/2.0 200 OK ] (4162 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][B2buaTest.java:184][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]] (4162 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = BYE] (4162 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (4162 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (4163 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (4163 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5] (4164 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@723704newState = 3] (4164 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][B2buaTest.java:184][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]] (4164 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@723704 old dialog state is Confirmed Dialog] (4165 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@723704 New dialog state is Terminated Dialog] (4165 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@e3ab1ad5 branchID = z9hG4bKlbkerx isClient = false] (4166 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][B2buaTest.java:184][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]] (4167 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5 tickCount 64 currentTickCount = -1] (4167 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage(SIPServerTransaction.java:1094) [sendMessage : tx = gov.nist.javax.sip.stack.SIPServerTransaction@e3ab1ad5 getState = Completed Transaction] (4167 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.<init>(UDPMessageChannel.java:198) [Creating message channel 192.168.0.145/5060] (4168 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][B2buaTest.java:184][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]] (4168 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=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Content-Length: 0 ] (4169 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage(UDPMessageChannel.java:681) [******************* ] (4169 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=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Content-Length: 0 ] (4170 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4171 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4172 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="1223304331967" isSender="true" transactionId="z9hg4bklbkerx" callId="703f0c0e578d16800b1e13db2c07dbe5@192.168.0.145" firstLine="SIP/2.0 200 OK" > <![CDATA[SIP/2.0 200 OK To: <sip:alice@192.168.0.145>;tag=1802412382 CSeq: 1 BYE Call-ID: 703f0c0e578d16800b1e13db2c07dbe5@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.b2bua;branch=z9hG4bKlbkerx From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=u4kt34 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4172 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4172 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:284) [UDPMessageChannel: peerAddress = 192.168.0.145/62253] (4173 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4174 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:288) [Length = 257] (4178 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:290) [SIP/2.0 200 OK (relayed) To: <sip:alice@192.168.0.145>;tag=xle663 Content-Length: 0 CSeq: 1 BYE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 ] (4178 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1142) [acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (4179 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1143][SIPTransactionStack.java:1107][UDPMessageChannel.java:485][UDPMessageChannel.java:255][Thread.java:613]] (4179 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.acquireSem(SIPTransaction.java:1146) [acquireSem() returning : true] (4180 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:336) [ &#x5d;&#x5d;&gt;] (4180 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:337) [</debug>] (4180 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:338) [<message from="192.168.0.145:5060" to="192.168.0.145:5072" time="1223304331979" isSender="false" transactionId="z9hg4bk6cc1eeac02d15a7f184854b65f9a533f" callId="afp8lm" firstLine="SIP/2.0 200 OK (relayed)" > <![CDATA[SIP/2.0 200 OK (relayed) To: <sip:alice@192.168.0.145>;tag=xle663 CSeq: 1 BYE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Content-Length: 0 &#x5d;&#x5d;&gt; </message> ] (4180 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:339) [<debug>] (4181 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:340) [<![CDATA[ ] (4181 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction(SIPTransactionStack.java:755) [clientTx: looking for key z9hg4bk6cc1eeac02d15a7f184854b65f9a533f] (4181 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerResponse(NistSipMessageFactoryImpl.java:108) [Found Transaction gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e for SIP/2.0 200 OK (relayed) To: <sip:alice@192.168.0.145>;tag=xle663 CSeq: 1 BYE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Content-Length: 0 ] (4181 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setResponseInterface(SIPClientTransaction.java:315) [Setting response interface for gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e to gov.nist.javax.sip.DialogFilter@fe6707] (4182 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:525) [processing SIP/2.0 200 OK (relayed) current state = Trying Transaction] (4182 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.processResponse(SIPClientTransaction.java:528) [dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4182 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@4adb34 lastResponse = SIP/2.0 200 OK (relayed) ] (4182 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>(SIPServerTransaction.java:333) [TransactionTimer() : z9hg4bklbkerx] (4182 ms) [Thread-25] DEBUG: testAgent2#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]] (4183 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2147) [cseqMethod = BYE] (4184 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2148) [dialogState = Confirmed Dialog] (4184 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2150) [method = INVITE] (4184 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2151) [statusCode = 200] (4185 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2152) [transaction = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (4185 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : BYE returning false] (4185 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@4adb34newState = 3] (4185 ms) [Thread-25] DEBUG: testAgent2#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]] (4185 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:860) [gov.nist.javax.sip.stack.SIPDialog@4adb34 old dialog state is Confirmed Dialog] (4186 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:862) [gov.nist.javax.sip.stack.SIPDialog@4adb34 New dialog state is Terminated Dialog] (4186 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: afp8lm:1110338167:xle663sipDialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4186 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:954) [PROCESSING INCOMING RESPONSESIP/2.0 200 OK (relayed) To: <sip:alice@192.168.0.145>;tag=xle663 CSeq: 1 BYE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Content-Length: 0 ] (4189 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.DialogFilter.processResponse(DialogFilter.java:986) [Transaction = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (4190 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2131) [sipDialog: setLastResponse:gov.nist.javax.sip.stack.SIPDialog@4adb34 lastResponse = SIP/2.0 200 OK (relayed) ] (4190 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setLastResponse(SIPDialog.java:2137) [sipDialog: setLastResponse -- dialog is terminated - ignoring ] (4191 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.setDialog(SIPClientTransaction.java:1496) [setDialog: afp8lm:1110338167:xle663sipDialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4191 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2ethis.sipListener = org.cafesip.sipunit.SipStack@90ed52sipEvent.source = gov.nist.javax.sip.SipProviderImpl@da9246] (4191 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:143) [Dialog = gov.nist.javax.sip.stack.SIPDialog@4adb34] (4192 ms) [Thread-25] DEBUG: testAgent2#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]] (4192 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@13de03] (4192 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Completed Transaction gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e branchID = z9hG4bK6cc1eeac02d15a7f184854b65f9a533f isClient = true] (4192 ms) [Thread-25] DEBUG: testAgent2#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]] (4192 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer(SIPTransaction.java:607) [enableTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e tickCount 10 currentTickCount = 64] (4193 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (4193 ms) [Thread-25] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][UDPMessageChannel.java:500][UDPMessageChannel.java:255][Thread.java:613]] (4193 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@13de03nevents 1] (4194 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.ResponseEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]source = gov.nist.javax.sip.SipProviderImpl@da9246] (4194 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:281) [Calling listener for SIP/2.0 200 OK (relayed) ] (4194 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setPassToListener(SIPTransaction.java:1208) [setPassToListener()] SIPUNIT TRACE: 1223304331993 Asynchronous response received: SIP/2.0 200 OK (relayed) To: <sip:alice@192.168.0.145>;tag=xle663 CSeq: 1 BYE Call-ID: afp8lm Via: SIP/2.0/UDP 192.168.0.145:5072;branch=z9hG4bK6cc1eeac02d15a7f184854b65f9a533f From: <sip:JSR289_TCK@127.0.0.1:5060>;tag=1110338167 Content-Length: 0 (4194 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.semRelease(SIPTransaction.java:1181) [semRelease ]]]]gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (4194 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransaction.java:1182][SIPTransaction.java:1168][EventScanner.java:362][EventScanner.java:492][Thread.java:613]] (4392 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction$TransactionTimer.runTask(SIPClientTransaction.java:201) [removing = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df isReliable false] (4392 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bke0217a12e0ab147a46595fd25ae3a059 transaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (4393 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@a2c1e4df KEY = z9hg4bke0217a12e0ab147a46595fd25ae3a059] (4393 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@79edfe]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4dfthis.sipListener = org.cafesip.sipunit.SipStack@538cc2sipEvent.source = gov.nist.javax.sip.SipProviderImpl@79edfe] (4394 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]] (4394 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@2cdd20] (4394 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@2cdd20nevents 1] (4394 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]source = gov.nist.javax.sip.SipProviderImpl@79edfe] (4395 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (4395 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = gov.nist.javax.sip.stack.SIPClientTransaction@a2c1e4df] (4395 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = null] (9145 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.fireTimeoutTimer(SIPClientTransaction.java:1037) [fireTimeoutTimer gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (9148 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction.getDialog(SIPClientTransaction.java:1468) [ sipDialogs = {afp8lm:1110338167:xle663=gov.nist.javax.sip.stack.SIPDialog@4adb34} default dialog gov.nist.javax.sip.stack.SIPDialog@4adb34 retval gov.nist.javax.sip.stack.SIPDialog@4adb34] (9148 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction.setState(SIPTransaction.java:547) [Transaction:setState Terminated Transaction gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e branchID = z9hG4bK6cc1eeac02d15a7f184854b65f9a533f isClient = true] (9149 ms) [Timer-4] DEBUG: testAgent2#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]] (9646 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPClientTransaction$TransactionTimer.runTask(SIPClientTransaction.java:201) [removing = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e isReliable false] (9647 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bk6cc1eeac02d15a7f184854b65f9a533f transaction = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (9647 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1288) [REMOVED client tx gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e KEY = z9hg4bk6cc1eeac02d15a7f184854b65f9a533f] (9648 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]currentTransaction = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2ethis.sipListener = org.cafesip.sipunit.SipStack@90ed52sipEvent.source = gov.nist.javax.sip.SipProviderImpl@da9246] (9648 ms) [Timer-4] DEBUG: testAgent2#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]] (9648 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@6972f1] (9649 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@6972f1nevents 1] (9649 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]source = gov.nist.javax.sip.SipProviderImpl@da9246] (9649 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (9649 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = gov.nist.javax.sip.stack.SIPClientTransaction@fb9e0d2e] (9650 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = null] (11966 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction$LingerTimer.runTask(SIPTransaction.java:273) [LingerTimer: run() : z9hg4bkrh6hhe] (11968 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransaction$LingerTimer.runTask(SIPTransaction.java:284) [removinggov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (11969 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeTransaction(SIPTransactionStack.java:1255) [Removing Transaction = z9hg4bkrh6hhe transaction = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (11969 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPTransactionStack.java:1261][SIPTransaction.java:285][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (11969 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction(SIPTransactionStack.java:882) [removePendingTx: z9hg4bkrh6hhe] (11970 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated(SIPTransactionStack.java:478) [isDialogCreated : INVITE returning true] (11970 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPTransactionStack.removeFromMergeTable(SIPTransactionStack.java:898) [Removing tx from merge table ] (11970 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]currentTransaction = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4this.sipListener = org.cafesip.sipunit.SipStack@90ed52sipEvent.source = gov.nist.javax.sip.SipProviderImpl@da9246] (11971 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SipProviderImpl.java:145][SIPTransactionStack.java:1279][SIPTransaction.java:285][SIPStackTimerTask.java:29][Timer.java:512][Timer.java:462]] (11971 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@f93ee4] (11971 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@f93ee4nevents 1] (11972 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]source = gov.nist.javax.sip.SipProviderImpl@da9246] (11972 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:389) [About to deliver transactionTerminatedEvent] (11972 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:391) [tx = null] (11972 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:395) [tx = gov.nist.javax.sip.stack.SIPServerTransaction@ee24ade4] (12166 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]currentTransaction = nullthis.sipListener = org.cafesip.sipunit.SipStack@538cc2sipEvent.source = gov.nist.javax.sip.SipProviderImpl@79edfe] (12167 ms) [Timer-3] 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]] (12168 ms) [Timer-3] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@8fee4f] (12168 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@8fee4fnevents 1] (12168 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@79edfe]source = gov.nist.javax.sip.SipProviderImpl@79edfe] (12187 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:133) [handleEvent javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]currentTransaction = nullthis.sipListener = org.cafesip.sipunit.SipStack@90ed52sipEvent.source = gov.nist.javax.sip.SipProviderImpl@da9246] (12187 ms) [Timer-4] DEBUG: testAgent2#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]] (12188 ms) [Timer-4] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:81) [addEvent gov.nist.javax.sip.EventWrapper@66b06b] (12188 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:487) [Processing gov.nist.javax.sip.EventWrapper@66b06bnevents 1] (12189 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:129) [sipEvent = javax.sip.DialogTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@da9246]source = gov.nist.javax.sip.SipProviderImpl@da9246] (26184 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@723704newState = 3] (26185 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]] (26186 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.SIPDialog.setState(SIPDialog.java:855) [Setting dialog state for gov.nist.javax.sip.stack.SIPDialog@4adb34newState = 3] (26186 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.core.LogWriter.logStackTrace(LogWriter.java:121) [[SIPDialog.java:857][SIPDialog.java:1334][SipCall.java:158][SipPhone.java:1231][TestBase.java:250][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]] (26187 ms) [UDPMessageProcessorThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (26187 ms) [main] DEBUG: testAgent#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (26188 ms) [EventScannerThread] DEBUG: testAgent#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (27189 ms) [UDPMessageProcessorThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (27189 ms) [main] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (27190 ms) [EventScannerThread] DEBUG: testAgent2#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!] (28190 ms) [UDPMessageProcessorThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.stack.UDPMessageProcessor.run(UDPMessageProcessor.java:251) [UDPMessageProcessor: Stopping] (28191 ms) [main] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.SipProviderImpl.stop(SipProviderImpl.java:100) [Exiting provider] (28192 ms) [EventScannerThread] DEBUG: testAgent3#logDebug : gov.nist.javax.sip.EventScanner.run(EventScanner.java:455) [Stopped event scanner!!]