RE: [reSIProcate] Exception encountered when using reSIProcate in a multi-threaded program
If I run a simple program that generates calls one after the other
INVITE, ACK, BYE, INVITE,... Then this problem does not happen. I tried
this with thousands of calls.
But if I run my multithreaded program that's generating these INVITEs
*once every 20 ms*, then I get this assertion error for different pairs
of calls. Last time it was between call 1 and call 40. This time it is
between call 33 and call 86 (see tid=eb01e926a62eb30b in the log excerpt
below)
But if I slow down the rate of INVITE generation to *once every 80 ms*,
then I don't get this assertion error anymore. I am running this program
on a Windows Server 2003, 3GHz Pentium 4 box.
I guess the tid generation takes the timestamp into account which is
what could be causing this problem at 'high speeds'.
Is SipMessage::compute2543TransactionHash() the one that is being used
to generate the tid ? Can you give me an idea of where I should place
more debug statements.
****************
* LOG EXCERPT *
****************
DEBUG | 20050718-154445.888 | UAC | RESIP | 1552 | SipStack.cxx:269 |
SEND: SipReq: BYE 14152484081@xxxxxxxxx:5060 tid=eb01e926a62eb30b
cseq=BYE contact=33@xxxxxxxxx:6050 / 2 from(tu)
STACK | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:190 | No matching transaction for SipReq: BYE
14152484081@xxxxxxxxx:5060 tid=eb01e926a62eb30b cseq=BYE
contact=33@xxxxxxxxx:6050 / 2 from(tu)
STACK | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:45 | Creating new TransactionState:
tid=eb01e926a62eb30b [ ClientNonInvite/Trying reliable target=[ V4
0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]]
STACK | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:431 | TransactionState::processClientNonInvite:
SipReq: BYE 14152484081@xxxxxxxxx:5060 tid=eb01e926a62eb30b cseq=BYE
contact=33@xxxxxxxxx:6050 / 2 from(tu)
DEBUG | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TimerQueue.cxx:85 | Adding timer: Timer F tid=eb01e926a62eb30b ms=32000
STACK | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:1490 | sendToWire with no dns result:
tid=eb01e926a62eb30b [ ClientNonInvite/Trying reliable target=[ V4
0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]]
STACK | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:1329 | tid=eb01e926a62eb30b [
ClientNonInvite/Trying reliable target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT
connectionId=0 ]] got DNS result: 127.0.0.1 --> [[ V4 127.0.0.1:5060 UDP
connectionId=0 ]]
STACK | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:1372 | Unreliable transport: tid=eb01e926a62eb30b [
ClientNonInvite/Trying unreliable target=[ V4 0.0.0.0:0
UNKNOWN_TRANSPORT connectionId=0 ]]
DEBUG | 20050718-154445.904 | UAC | RESIP:TRANSACTION | 3520 |
TimerQueue.cxx:85 | Adding timer: Timer E1 tid=eb01e926a62eb30b ms=500
STACK | 20050718-154445.935 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:155 | Found matching transaction for SipResp: 200
tid=eb01e926a62eb30b cseq=BYE contact=14152484081@xxxxxxxxx:5060 / 2
from(wire) -> tid=eb01e926a62eb30b [ ClientNonInvite/Trying unreliable
target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]]
STACK | 20050718-154445.935 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:431 | TransactionState::processClientNonInvite:
SipResp: 200 tid=eb01e926a62eb30b cseq=BYE
contact=14152484081@xxxxxxxxx:5060 / 2 from(wire)
DEBUG | 20050718-154445.935 | UAC | RESIP:TRANSACTION | 3520 |
TimerQueue.cxx:85 | Adding timer: Timer K tid=eb01e926a62eb30b ms=5000
DEBUG | 20050718-154445.935 | UAC | RESIP | 3520 | SipStack.cxx:375 |
RECV: SipResp: 200 tid=eb01e926a62eb30b cseq=BYE
contact=14152484081@xxxxxxxxx:5060 / 2 from(wire)
STACK | 20050718-154446.404 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:155 | Found matching transaction for Timer: Timer
E1 500 -> tid=eb01e926a62eb30b [ ClientNonInvite/Completed unreliable
target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]]
DEBUG | 20050718-154447.513 | UAC | RESIP | 1892 | SipStack.cxx:269 |
SEND: SipReq: INVITE 14152484081@xxxxxxxxx:5060 tid=eb01e926a62eb30b
cseq=INVITE contact=86 / 1 from(tu)
STACK | 20050718-154447.529 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:155 | Found matching transaction for SipReq:
INVITE 14152484081@xxxxxxxxx:5060 tid=eb01e926a62eb30b cseq=INVITE
contact=86 / 1 from(tu) -> tid=eb01e926a62eb30b [
ClientNonInvite/Completed unreliable target=[ V4 0.0.0.0:0
UNKNOWN_TRANSPORT connectionId=0 ]]
STACK | 20050718-154447.529 | UAC | RESIP:TRANSACTION | 3520 |
TransactionState.cxx:431 | TransactionState::processClientNonInvite:
SipReq: INVITE 14152484081@xxxxxxxxx:5060 tid=eb01e926a62eb30b
cseq=INVITE contact=86 / 1 from(tu)
andy
-----Original Message-----
From: Fischl jason [mailto:jason.fischl@xxxxxxxxx]
Sent: Monday, July 18, 2005 3:00 PM
To: Andy Agarwal
Cc: resiprocate-devel@xxxxxxxxxxxxxxxxxxx
Subject: Re: [reSIProcate] Exception encountered when using reSIProcate
in a multi-threaded program
That is pretty strange behavior. I haven't seen it before. Can you try
writing a test program that just makes an INVITE request, then a BYE,
then another INVITE. See if the behavior still occurs in a simple test
program.
I wonder if you are running into some random number generation problem
on your platform. I think you'll have to add some more debug statements
in the stack. Possibly in makeInvite, the Via constructor and/or
Random::getRandom.
Thanks,
Jason
On 7/18/05, Andy Agarwal <Andy@xxxxxxxxxxx> wrote:
>
> Thanks for the tip Jason. I ran my program with logging set to
> Level::Stack and it seems that the stack is generating the same tid
> for two different calls. The assertion error is encountered in the
> second call.
> In this particular example tid tid=5e3024011c490d44 was used to send
> the BYE message for a certain call and then attempted to be used for
> an INVITE message for another call.
> I use the makeInvite function to generate the Invite msg -
> auto_ptr<SipMessage> message(Helper::makeInvite( dest, from,
> contact));
>
>
>
> Here is an excerpt from the logs -
>
> *******************
> *** Send INVITE ***
> *******************
> INFO | 20050718-121512.123 | UAC | RESIP:TRANSPORT | 1572 |
> UdpTransport.cxx:30 | Creating UDP transport host= port=6050 ipv4=1
> DEBUG | 20050718-121512.123 | UAC | RESIP:TRANSPORT | 1572 |
> InternalTransport.cxx:87 | Creating fd=1816 V4/UDP DEBUG |
> 20050718-121512.123 | UAC | RESIP:TRANSPORT | 1572 |
> InternalTransport.cxx:95 | Binding to 0.0.0.0 DEBUG |
> 20050718-121515.123 | UAC | RESIP | 3592 | SipStack.cxx:269 |
> SEND: SipReq: INVITE 14152484081@xxxxxxxxx:5060 tid=ae72d62c905f5269
> cseq=INVITE contact=1 / 1 from(tu) Sent INVITE for port 1 STACK |
> 20050718-121515.138 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:190 | No matching transaction for SipReq: INVITE
> 14152484081@xxxxxxxxx:5060 tid=ae72d62c905f5269 cseq=INVITE contact=1
> /
> 1 from(tu)
> STACK | 20050718-121515.138 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:45 | Creating new TransactionState:
> tid=ae72d62c905f5269 [ ClientInvite/Calling reliable target=[ V4
> 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] STACK |
> 20050718-121515.138 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:570 | TransactionState::processClientInvite:
> SipReq: INVITE 14152484081@xxxxxxxxx:5060 tid=ae72d62c905f5269
> cseq=INVITE contact=1 / 1 from(tu) tid=ae72d62c905f5269 [
> ClientInvite/Calling reliable target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT
> connectionId=0 ]] DEBUG | 20050718-121515.138 | UAC |
> RESIP:TRANSACTION | 1572 |
> TimerQueue.cxx:85 | Adding timer: Timer B tid=ae72d62c905f5269
> ms=32000 STACK | 20050718-121515.138 | UAC | RESIP:TRANSACTION | 1572
> | TransactionState.cxx:1490 | sendToWire with no dns result:
> tid=ae72d62c905f5269 [ ClientInvite/Calling reliable target=[ V4
> 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG |
> 20050718-121515.138 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:243 | Looking up dns entries for
> sip:14152484081@xxxxxxxxx:5060 DEBUG | 20050718-121515.138 | UAC |
> RESIP:DNS | 1572 | DnsResult.cxx:136
> | DnsResult::lookup sip:14152484081@xxxxxxxxx:5060
> DEBUG | 20050718-121515.138 | UAC | RESIP:DNS | 1572 |
> DnsResult.cxx:255
> | Numeric result so return immediately: [ V4 127.0.0.1:5060 UDP
> connectionId=0 ]
> STACK | 20050718-121515.138 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1329 | tid=ae72d62c905f5269 [
> ClientInvite/Calling reliable target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT
> connectionId=0 ]] got DNS result: 127.0.0.1 --> [[ V4 127.0.0.1:5060
> UDP connectionId=0 ]] STACK | 20050718-121515.138 | UAC | RESIP:DNS |
> 1572 | DnsResult.cxx:128
> | Returning next dns entry: [ V4 127.0.0.1:5060 UDP connectionId=0 ]
> STACK | 20050718-121515.138 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1372 | Unreliable transport: tid=ae72d62c905f5269
> [ ClientInvite/Calling unreliable target=[ V4 0.0.0.0:0
> UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG | 20050718-121515.138 | UAC
> | RESIP:TRANSACTION | 1572 |
> TimerQueue.cxx:85 | Adding timer: Timer A tid=ae72d62c905f5269 ms=500
> DEBUG | 20050718-121515.138 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:514 | Looked up source for destination: [ V4
> 127.0.0.1:5060 UDP connectionId=0 ] -> [ V4 127.0.0.1:6050 UDP
> connectionId=0 ] sent-by= sent-port=6050 DEBUG | 20050718-121515.138 |
> UAC | RESIP:TRANSPORT | 1572 | TransportSelector.cxx:740 |
> findTransport([ V4 127.0.0.1:6050 UDP connectionId=0 ]) DEBUG |
> 20050718-121515.138 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:759 | findTransport (any interface) =>
Transport:
> [ V4 0.0.0.0:6050 UDP connectionId=0 ] DEBUG | 20050718-121515.138 |
> UAC | RESIP:TRANSPORT | 1572 | TransportSelector.cxx:620 | !sipit!
> Populated Contact:
> <sip:1@xxxxxxxxx:6050>
> DEBUG | 20050718-121515.138 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:658 | Transmitting to [ V4 127.0.0.1:5060 UDP
> received on: Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ]
> connectionId=0 ] via [ V4 127.0.0.1:6050 UDP connectionId=0 ]INVITE
> sip:14152484081@xxxxxxxxx:5060 SIP/2.0 To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp From:
> <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900 Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-ae72d62c905f5269-1--d87543-;rport
> Call-ID: 8467be186c3de14a@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx CSeq: 1
> INVITE Contact: <sip:1@xxxxxxxxx:6050> Max-Forwards: 70
Content-Length:
> 0
>
> *******************
> *** Recv 200 OK ***
> *******************
> DEBUG | 20050718-121515.170 | UAC | RESIP:TRANSPORT | 1572 |
> Transport.cxx:209 | incoming from: [ V4 127.0.0.1:5060 UDP received
on:
> Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ] connectionId=0 ]
> STACK | 20050718-121515.170 | UAC | RESIP:TRANSPORT | 1572 |
> Transport.cxx:210 | SIP/2.0 200 OK To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=23482900 From:
> <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900 Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-ae72d62c905f5269-1--d87543-;rport
> =6 050 Call-ID: 8467be186c3de14a@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> CSeq:
> 1 INVITE Contact: <sip:14152484081@xxxxxxxxx:5060>;transport=udp
> Content-Length: 0
> STACK | 20050718-121515.170 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:155 | Found matching transaction for SipResp: 200
> tid=ae72d62c905f5269 cseq=INVITE contact=14152484081@xxxxxxxxx:5060 /
> 1
> from(wire) -> tid=ae72d62c905f5269 [ ClientInvite/Calling unreliable
> target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] STACK |
> 20050718-121515.170 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:570 | TransactionState::processClientInvite:
> SipResp: 200 tid=ae72d62c905f5269 cseq=INVITE
> contact=14152484081@xxxxxxxxx:5060 / 1 from(wire) tid=ae72d62c905f5269
> [ ClientInvite/Calling unreliable target=[ V4 0.0.0.0:0
> UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG | 20050718-121515.170 | UAC
> | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1531 | Send to default TU: SIP/2.0 200 OK To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=23482900 From:
> <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900 Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-ae72d62c905f5269-1--d87543-;rport
> =6 050 Call-ID: 8467be186c3de14a@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> CSeq:
> 1 INVITE Contact: <sip:14152484081@xxxxxxxxx:5060>;transport=udp
> Content-Length: 0
> *******************
> *** Send ACK ***
> *******************
> STACK | 20050718-121515.170 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:632 | Received 2xx on client invite transaction
> STACK | 20050718-121515.170 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:633 | tid=ae72d62c905f5269 [
> ClientStale/Terminated unreliable target=[ V4 0.0.0.0:0
> UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG | 20050718-121515.170 | UAC
> | RESIP:TRANSACTION | 1572 |
> TimerQueue.cxx:85 | Adding timer: Timer StaleClient
> tid=ae72d62c905f5269 ms=32000 DEBUG | 20050718-121515.170 | UAC |
> RESIP | 1572 | SipStack.cxx:375 |
> RECV: SipResp: 200 tid=ae72d62c905f5269 cseq=INVITE
> contact=14152484081@xxxxxxxxx:5060 / 1 from(wire) Received response
> 200 for port 1 DEBUG | 20050718-121515.170 | UAC | RESIP | 3592 |
> SipStack.cxx:269 |
> SEND: SipReq: ACK 14152484081@xxxxxxxxx:5060 tid=0c39877e99003e0f
> cseq=ACK contact=1@xxxxxxxxx:6050 / 1 from(tu) Sent ACK for port 1
> DEBUG | 20050718-121515.170 | UAC | RESIP | 3592 | SipStack.cxx:269 |
> SEND: SipReq: BYE 14152484081@xxxxxxxxx:5060 tid=5e3024011c490d44
> cseq=BYE contact=1@xxxxxxxxx:6050 / 2 from(tu) Sent BYE for port 1
> STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:190 | No matching transaction for SipReq: ACK
> 14152484081@xxxxxxxxx:5060 tid=0c39877e99003e0f cseq=ACK
> contact=1@xxxxxxxxx:6050 / 1 from(tu) STACK | 20050718-121515.201 |
> UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:45 | Creating new TransactionState:
> tid=0c39877e99003e0f [ Stateless/Calling reliable target=[ V4
> 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TimerQueue.cxx:85 | Adding timer: Timer Stateless tid=0c39877e99003e0f
> ms=32000 STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572
> | TransactionState.cxx:390 | TransactionState::processStateless:
> SipReq:
> ACK 14152484081@xxxxxxxxx:5060 tid=0c39877e99003e0f cseq=ACK
> contact=1@xxxxxxxxx:6050 / 1 from(tu) STACK | 20050718-121515.201 |
> UAC | RESIP:TRANSACTION | 1572 | TransactionState.cxx:1490 |
> sendToWire with no dns result:
> tid=0c39877e99003e0f [ Stateless/Calling reliable target=[ V4
> 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:243 | Looking up dns entries for
> sip:14152484081@xxxxxxxxx:5060 DEBUG | 20050718-121515.201 | UAC |
> RESIP:DNS | 1572 | DnsResult.cxx:136
> | DnsResult::lookup sip:14152484081@xxxxxxxxx:5060
> DEBUG | 20050718-121515.201 | UAC | RESIP:DNS | 1572 |
> DnsResult.cxx:255
> | Numeric result so return immediately: [ V4 127.0.0.1:5060 UDP
> connectionId=0 ]
> STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1329 | tid=0c39877e99003e0f [ Stateless/Calling
> reliable target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] got
> DNS result: 127.0.0.1 --> [[ V4 127.0.0.1:5060 UDP connectionId=0 ]]
> STACK | 20050718-121515.201 | UAC | RESIP:DNS | 1572 |
> DnsResult.cxx:128
> | Returning next dns entry: [ V4 127.0.0.1:5060 UDP connectionId=0 ]
> STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1372 | Unreliable transport: tid=0c39877e99003e0f
> [ Stateless/Calling unreliable target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT
> connectionId=0 ]] DEBUG | 20050718-121515.201 | UAC | RESIP:TRANSPORT
> | 1572 |
> TransportSelector.cxx:514 | Looked up source for destination: [ V4
> 127.0.0.1:5060 UDP connectionId=0 ] -> [ V4 127.0.0.1:0 UDP
> connectionId=0 ] sent-by= sent-port=0 DEBUG | 20050718-121515.201 |
> UAC | RESIP:TRANSPORT | 1572 | TransportSelector.cxx:740 |
> findTransport([ V4 127.0.0.1:0 UDP connectionId=0 ]) DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:782 | findTransport (any port, any interface) =>
> Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ] DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:658 | Transmitting to [ V4 127.0.0.1:5060 UDP
> received on: Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ]
> connectionId=0 ] via [ V4 127.0.0.1:0 UDP connectionId=0 ]ACK
> sip:14152484081@xxxxxxxxx:5060 SIP/2.0 To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=23482900 From:
> <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900 Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-0c39877e99003e0f-1--d87543-;rport
> Call-ID: 8467be186c3de14a@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx CSeq: 1
> ACK Contact: <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900
> Max-Forwards: 70 Content-Length: 0
> *******************
> *** Send BYE ***
> *******************
> DEBUG | 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> Transport.cxx:160 | Adding message to tx buffer to: [ V4
> 127.0.0.1:5060 UDP received on: Transport: [ V4 0.0.0.0:6050 UDP
> connectionId=0 ] connectionId=0 ] STACK | 20050718-121515.201 | UAC |
> RESIP:DNS | 1572 | DnsResult.cxx:819
> | Priming []
> STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:190 | No matching transaction for SipReq: BYE
> 14152484081@xxxxxxxxx:5060 tid=5e3024011c490d44 cseq=BYE
> contact=1@xxxxxxxxx:6050 / 2 from(tu) STACK | 20050718-121515.201 |
> UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:45 | Creating new TransactionState:
> tid=5e3024011c490d44 [ ClientNonInvite/Trying reliable target=[ V4
> 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] STACK |
> 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:431 | TransactionState::processClientNonInvite:
> SipReq: BYE 14152484081@xxxxxxxxx:5060 tid=5e3024011c490d44 cseq=BYE
> contact=1@xxxxxxxxx:6050 / 2 from(tu) DEBUG | 20050718-121515.201 |
> UAC | RESIP:TRANSACTION | 1572 |
> TimerQueue.cxx:85 | Adding timer: Timer F tid=5e3024011c490d44
> ms=32000 STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572
> | TransactionState.cxx:1490 | sendToWire with no dns result:
> tid=5e3024011c490d44 [ ClientNonInvite/Trying reliable target=[ V4
> 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:243 | Looking up dns entries for
> sip:14152484081@xxxxxxxxx:5060 DEBUG | 20050718-121515.201 | UAC |
> RESIP:DNS | 1572 | DnsResult.cxx:136
> | DnsResult::lookup sip:14152484081@xxxxxxxxx:5060
> DEBUG | 20050718-121515.201 | UAC | RESIP:DNS | 1572 |
> DnsResult.cxx:255
> | Numeric result so return immediately: [ V4 127.0.0.1:5060 UDP
> connectionId=0 ]
> STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1329 | tid=5e3024011c490d44 [
> ClientNonInvite/Trying reliable target=[ V4 0.0.0.0:0
> UNKNOWN_TRANSPORT connectionId=0 ]] got DNS result: 127.0.0.1 --> [[
> V4 127.0.0.1:5060 UDP connectionId=0 ]] STACK | 20050718-121515.201 |
> UAC | RESIP:DNS | 1572 | DnsResult.cxx:128
> | Returning next dns entry: [ V4 127.0.0.1:5060 UDP connectionId=0 ]
> STACK | 20050718-121515.201 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1372 | Unreliable transport: tid=5e3024011c490d44
> [ ClientNonInvite/Trying unreliable target=[ V4 0.0.0.0:0
> UNKNOWN_TRANSPORT connectionId=0 ]] DEBUG | 20050718-121515.201 | UAC
> | RESIP:TRANSACTION | 1572 |
> TimerQueue.cxx:85 | Adding timer: Timer E1 tid=5e3024011c490d44 ms=500
> DEBUG | 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:514 | Looked up source for destination: [ V4
> 127.0.0.1:5060 UDP connectionId=0 ] -> [ V4 127.0.0.1:0 UDP
> connectionId=0 ] sent-by= sent-port=0 DEBUG | 20050718-121515.201 |
> UAC | RESIP:TRANSPORT | 1572 | TransportSelector.cxx:740 |
> findTransport([ V4 127.0.0.1:0 UDP connectionId=0 ]) DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:782 | findTransport (any port, any interface) =>
> Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ] DEBUG |
> 20050718-121515.201 | UAC | RESIP:TRANSPORT | 1572 |
> TransportSelector.cxx:658 | Transmitting to [ V4 127.0.0.1:5060 UDP
> received on: Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ]
> connectionId=0 ] via [ V4 127.0.0.1:0 UDP connectionId=0 ]BYE
> sip:14152484081@xxxxxxxxx:5060 SIP/2.0 To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=23482900 From:
> <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900 Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-5e3024011c490d44-1--d87543-;rport
> Call-ID: 8467be186c3de14a@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx CSeq: 2
> BYE Contact: <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900
> Max-Forwards: 70 Content-Length: 0
>
> *******************
> *** Recv 200 OK ***
> *******************
> DEBUG | 20050718-121515.232 | UAC | RESIP:TRANSPORT | 1572 |
> Transport.cxx:160 | Adding message to tx buffer to: [ V4
> 127.0.0.1:5060 UDP received on: Transport: [ V4 0.0.0.0:6050 UDP
> connectionId=0 ] connectionId=0 ] STACK | 20050718-121515.232 | UAC |
> RESIP:DNS | 1572 | DnsResult.cxx:819
> | Priming []
> STACK | 20050718-121515.232 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:155 | Found matching transaction for SipResp: 200
> tid=5e3024011c490d44 cseq=BYE contact=14152484081@xxxxxxxxx:5060 / 2
> from(wire) -> tid=5e3024011c490d44 [ ClientNonInvite/Trying unreliable
> target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]] STACK |
> 20050718-121515.232 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:431 | TransactionState::processClientNonInvite:
> SipResp: 200 tid=5e3024011c490d44 cseq=BYE
> contact=14152484081@xxxxxxxxx:5060 / 2 from(wire) DEBUG |
> 20050718-121515.232 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1531 | Send to default TU: SIP/2.0 200 OK To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=23482900 From:
> <sip:1@xxxxxxxxx:6050>;transport=udp;tag=23482900 Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-5e3024011c490d44-1--d87543-;rport
> =6 050 Call-ID: 8467be186c3de14a@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> CSeq:
> 2 BYE Contact:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=23482900
> Content-Length: 0 DEBUG | 20050718-121515.232 | UAC |
> RESIP:TRANSACTION
> | 1572 | TimerQueue.cxx:85 | Adding timer: Timer K
> | tid=5e3024011c490d44
> ms=5000
> DEBUG | 20050718-121515.232 | UAC | RESIP | 1572 | SipStack.cxx:375 |
> RECV: SipResp: 200 tid=5e3024011c490d44 cseq=BYE
> contact=14152484081@xxxxxxxxx:5060 / 2 from(wire) Received response
> 200 for port 1 DEBUG | 20050718-121515.232 | UAC | RESIP:TRANSPORT |
> 1572 |
> Transport.cxx:209 | incoming from: [ V4 127.0.0.1:5060 UDP received
on:
> Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ] connectionId=0 ]
> STACK | 20050718-121515.232 | UAC | RESIP:TRANSPORT | 1572 |
> Transport.cxx:210 | SIP/2.0 200 OK To:
> <sip:14152484081@xxxxxxxxx:5060>;transport=udp;tag=6c3de14a From:
> <sip:3@xxxxxxxxx:6050>;transport=udp;tag=b74d064d Via: SIP/2.0/UDP
> 127.0.0.1:6050;branch=z9hG4bK-d87543-c84d4d07bb664364-1--d87543-;rport
> =6 050 Call-ID: de544715122db339@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> CSeq:
> 1 INVITE Contact: <sip:14152484081@xxxxxxxxx:5060>;transport=udp
> Content-Length: 0
>
>
> ****************************
> *** Some timer expired ? ***
> ****************************
> STACK | 20050718-121515.701 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:1151 | TransactionState::processClientStale:
Timer:
> Timer A 500
> STACK | 20050718-121515.701 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:155 | Found matching transaction for Timer: Timer
> E1 500 -> tid=5e3024011c490d44 [ ClientNonInvite/Completed unreliable
> target=[ V4 0.0.0.0:0 UNKNOWN_TRANSPORT connectionId=0 ]]
>
>
>
> *********************************
> *** New INVITE using same tid ***
> *********************************
> DEBUG | 20050718-121516.341 | UAC | RESIP | 3836 | SipStack.cxx:269 |
> SEND: SipReq: INVITE 14152484081@xxxxxxxxx:5060 tid=5e3024011c490d44
> cseq=INVITE contact=40 / 1 from(tu) Sent INVITE for port 40 DEBUG |
> 20050718-121516.357 | UAC | RESIP:TRANSPORT | 1572 | Transport.cxx:160
> | Adding message to tx buffer to: [ V4 127.0.0.1:5060 UDP received on:
> Transport: [ V4 0.0.0.0:6050 UDP connectionId=0 ] connectionId=0 ]
> STACK | 20050718-121516.357 | UAC | RESIP:DNS | 1572 |
> DnsResult.cxx:819
> | Priming []
> STACK | 20050718-121516.357 | UAC | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:155 | Found matching transaction for SipReq:
> INVITE 14152484081@xxxxxxxxx:5060 tid=5e3024011c490d44 cseq=INVITE
> contact=40 / 1 from(tu) -> tid=5e3024011c490d44 [
> ClientNonInvite/Completed unreliable target=[ V4 0.0.0.0:0
> UNKNOWN_TRANSPORT connectionId=0 ]] STACK | 20050718-121516.357 | UAC
> | RESIP:TRANSACTION | 1572 |
> TransactionState.cxx:431 | TransactionState::processClientNonInvite:
> SipReq: INVITE 14152484081@xxxxxxxxx:5060 tid=5e3024011c490d44
> cseq=INVITE contact=40 / 1 from(tu)
>
>
> -----Original Message-----
> From: Fischl jason [mailto:jason.fischl@xxxxxxxxx]
> Sent: Monday, July 18, 2005 11:50 AM
> To: Andy Agarwal
> Cc: resiprocate-devel@xxxxxxxxxxxxxxxxxxx
> Subject: Re: [reSIProcate] Exception encountered when using
> reSIProcate in a multi-threaded program
>
> Hi Andy,
>
> Can you provide us with some more information. It would be helpful to
> see the stack logs running at Log::Stack. Your stack usage looks fine
> to me.
>
> Is it possible that you are reusing the same transaction id (branch
> parameter in Via) for each transaction in your call threads? This
> might cause this sort of problem.
>
> Jason
>
>
> On 7/18/05, Andy Agarwal <Andy@xxxxxxxxxxx> wrote:
> >
> > Hi,
> >
> > Let me first describe how i'm using reSIProcate (ver. 0.90.5019).
> >
> > 1. There is a global SipStack object available to all threads in the
> > program.
> > 2. There is one dedicated 'receiver' thread which is the one doing
> > the
>
> > following in a loop - while (true)
> > {
> > FdSet fdset;
> > g_sipStack.buildFdSet(fdset);
> > int err = fdset.selectMilliSeconds(20);
> > assert (err != -1);
> > g_sipStack.process(fdset);
> > SharedPtr<SipMessage> receivedMsg(g_sipStack.receive());
> > if (receivedMsg == NULL) continue;
> >
> > ... Figure out what message this is ...
> > ... Post a message to the thread that is handling this call...
> > }
> > 3. There are many 'call' threads that are using the the global
> > SipStack object and calling the send method on it (e.g.
> > g_sipStack.send(*msgInvite),...). For now all they do is send an
> > INVITE, wait for an OK, send an ACK and then send a BYE shortly
> > after that and wait for the OK for the bye. Thats it.
> > 4. When you run the program, it wil spawn a bunch of the above
'call'
> > threads and will wait for them to run and exit.
> >
> > So now, if i run my program in Debug mode, i encounter this
> > exception after a few calls have already been made successfully -
> > "Assertion failed in TransactionState::processClientNonInvite -
> > TransactionState.cxx, line 433".
> > The call stack is as follows - 'Receiver thread' is calling
> > sipStack.process which is in turn calling
> > TransactionController::process which then calls
> > TransactionState::process which believes that the current state is -
> > ClientNonInvite so it calls TransactionState::processClientNonInvite
> > which then fails this assertion.
> >
> > If i run this program in Release mode, then it works fine.
> >
> > I'm guessing i'm not using the stack in the right way (for a
> > multithreaded program). Can anyone help me here ?
> >
> > thanks,
> > andy
> >
> > _______________________________________________
> > resiprocate-devel mailing list
> > resiprocate-devel@xxxxxxxxxxxxxxxxxxx
> > https://list.sipfoundry.org/mailman/listinfo/resiprocate-devel
> >
> >
>