< Previous by Date	Date Index	Next by Date >
< Previous in Thread	Thread Index	Next in Thread >
Re: [reSIProcate-users] Hanging up problem, BYE message processed differently on two machines

From: "Ali Ziad" <aziad@xxxxxxxxxxxxxx>
Date: Wed, 9 Jul 2008 22:47:50 -0400
I think the section on "Dum Threading" would be a suitable place for a note
on this.
http://www.resiprocate.org/DUM_Threading

I hope I am describing it accurately, here are my notes on this issue:
____________________________________________________________________________
______________

*Note* SipStack and DUM work independently using separate processing loops
that need to be serviced in the main application thread or in separate
threads as described in the above page on the DUM Threading.  In my
configuration, I used a Stack Thread for Stack processing and had an
application onIdle() event call on DUM->Process() to handle DUM messages.

In my program, the stack processing was handled in Stackthread, incoming
messages from the network were received 
and sent to the TU / DUM to be handled.

> TransactionState.cxx:1956 | Send to TU: TU: Dialog Usage Manager ...

At this point, the DUM should receive respond to the message. In my case it
was not, since my Dum->Process() was not getting called due to an
application error condition 

Instead of getting a response to my SIP request from DUM, I got the
following "100-Trying" response sent back from the stack: 
:
TransportSelector.cxx:932 | Transmitting to [ V4 10.30.21.100:5060 UDP
target domain=unspecified mFlowKey=508 ] 
                            Tls Domain= via [ V410.30.21.10:12111 UDP target
domain=unspecified mFlowKey=508 ]
> SIP/2.0 100 Trying
:
:
This indicates that the TU/DUM is not processing the message in its queue.
So, "100-Trying" in this context can be interpreted as the Stack waiting for
the TU/DUM to process the message and generate an appropriate reply.

In the working scenario, instead of the Trying message, Dum would receive
the request and handle it, starting with:
:
> INFO | 20080708-112916.234 | Sytech:ResipLib | RESIP:DUM | 5168 |
DialogUsageManager.cxx:1299 | 
:
  Got: SipReq: BYE 118@xxxxxxxxxxxxxx:12111 tid=-b0ed5168 cseq=BYE / 103
from(wire)
:

When troubleshooting SIP communications, I've often seen errors caused by
network (firewalls, etc) or unreachable IP addresses/ports being advertised
in the SIP messages, like the Contact: header or the SDP media ports.
(Example, 127.0.0.1 being sent in a Contact: header! Which makes
No sense to a remote host). 

The "100 Trying" message had me suspect such network issues when the real
communication break was happening between two software components in the
same process (Stack and DUM) and not actual network endpoints. When the
packet capture showed the messages reaching resiprocate, the next logical
step is to examine resiprocate.log and see how they're traversing the
software components.
____________________________________________________________________________
______________

-ali

-----Original Message-----
From: Robert Sparks [mailto:rjsparks@xxxxxxxxxxx] 
Sent: Wednesday, July 09, 2008 5:21 PM
To: Ali Ziad
Cc: resiprocate-users@xxxxxxxxxxxxxxx
Subject: Re: [reSIProcate-users] Hanging up problem, BYE message processed
differently on two machines

Thanks for the followup Ali.

While this is still fresh in your mind, would you poke around the wiki  
a little
and see if there's a natural place for a hint that would have helped  
you find
this faster? It sounds like a kind of thing other folks have tripped  
up on, and
any future pain we can save is pain we can spend elsewhere :)

RjS

On Jul 9, 2008, at 1:08 PM, Ali Ziad wrote:

> Hello, Please disregard my previous posting, I have resolved the  
> problem.
>
> Due to an application condition, my code was not calling dum- 
> >process().
>
> In both systems the BYE message was received and queued but on one  
> it was
> not getting processed by DUM.
>
> Thanks,
> -ali
>
>
> -----Original Message-----
> From: resiprocate-users-bounces@xxxxxxxxxxxxxxx
> [mailto:resiprocate-users-bounces@xxxxxxxxxxxxxxx] On Behalf Of Ali  
> Ziad
> Sent: Tuesday, July 08, 2008 3:25 PM
> To: resiprocate-users@xxxxxxxxxxxxxxx
> Subject: [reSIProcate-users] Hanging up problem, BYE message processed
> differently on two machines
>
> Hello,
>
> I have an application which acts as a SIP client behaving  
> differently on two
> machines. Using repro as a SIP proxy. I am getting this in a similar
> configuration (softphone,)  and identical executables.
>
> A packet trace on the SIP messages shows both systems have a similar  
> flow of
> messages but the difference is in how they're handled in my  
> application and
> resiprocate.
>
> The problem occurs while accepting a call as a UAS. On the one  
> system it
> works on, a BYE message is received and processed successfully.  
> Sending back
> a 200-OK message.
>
> On the system where it doesn't work, the BYE message is received and a
> 100-Trying message is sent back and the SIP client locks up.
>
>> From the resiprocate logs, it appears as the message flows from  
>> TRANSACTION
> to TRANSPORT when it doesn't work and TRANSACTION to DUM when it  
> does. Is it
> having a problem locating the associated dialog!?
>
> Any ideas what may be causing this?
>
> Thanks,
> -ali
>
> Here is an excerpt from reciprocate.log for both cases (failed one  
> first):
>
----------------------------------------------------------------------------
> -
>
> DEBUG | 20080707-164431.578 | Sytech:ResipLib | RESIP:TRANSACTION |  
> 3948 |
> TransactionUser.cxx:74 | Match!
> DEBUG | 20080707-164431.578 | Sytech:ResipLib | RESIP | 3948 |
> Helper.cxx:372 | Helper::makeResponse(SipReq:  BYE  
> 110@xxxxxxxxxxx:12111
> tid=-44c6cf24 cseq=BYE / 103 from(wire) code=100 reason=
> DEBUG | 20080707-164431.578 | Sytech:ResipLib | RESIP:TRANSACTION |  
> 3948 |
> TimerQueue.cxx:85 | Adding timer: Timer Trying tid=-44c6cf24 ms=3500
> DEBUG | 20080707-164431.578 | Sytech:ResipLib | RESIP:TRANSACTION |  
> 3948 |
> TransactionState.cxx:1956 | Send to TU: TU: DialogUsageManager size=2
>
> BYE sip:110@xxxxxxxxxxx:12111;rinstance=6009f8625e50a10b SIP/2.0
> Via: SIP/2.0/UDP 10.30.21.100:5060;branch=z9hG4bK-44c6cf24
> Max-Forwards: 70
> To: <sip:110@xxxxxxxxxxx>;tag=59070e4e
> From: "Linksys 2" <sip:104@xxxxxxxxxxx>;tag=69e1022c43c72f7fo0
> Call-ID: ef2af570-b1e2350b@xxxxxxxxxxxx
> CSeq: 103 BYE
>
> Proxy-Authorization: Digest
> username 
> ="104",realm="10.30.21.20",nonce="12859936959:39deb688c5744e8e12e523
> e128449427",uri="sip: 
> 110@xxxxxxxxxxx:12111",algorithm=MD5,response="cdc73212
> c9cfe0d98bd536a324212137",qop=auth,nc=00000002,cnonce="bc69c0a5"
> User-Agent: Linksys/SPA922-5.1.15(a)
> Content-Length: 0
>
> DEBUG | 20080707-164432.078 | Sytech:ResipLib | RESIP:TRANSPORT |  
> 3948 |
> Transport.cxx:287 | incoming from: [ V4 10.30.21.100:5060 UDP target
> domain=unspecified mFlowKey=508 ]
> DEBUG | 20080707-164433.078 | Sytech:ResipLib | RESIP:TRANSPORT |  
> 3948 |
> Transport.cxx:287 | incoming from: [ V4 10.30.21.100:5060 UDP target
> domain=unspecified mFlowKey=508 ]
> DEBUG | 20080707-164435.078 | Sytech:ResipLib | RESIP:TRANSPORT |  
> 3948 |
> TransportSelector.cxx:932 | Transmitting to [ V4 10.30.21.100:5060 UDP
> target domain=unspecified mFlowKey=508 ] tlsDomain= via [ V4
> 10.30.21.10:12111 UDP target domain=unspecified mFlowKey=508 ]
>
> SIP/2.0 100 Trying
> Via: SIP/2.0/UDP 10.30.21.100:5060;branch=z9hG4bK-44c6cf24
> To: <sip:110@xxxxxxxxxxx>;tag=59070e4e
> From: "Linksys 2" <sip:104@xxxxxxxxxxx>;tag=69e1022c43c72f7fo0
> Call-ID: ef2af570-b1e2350b@xxxxxxxxxxxx
> CSeq: 103 BYE
> Content-Length: 0
>
> = 
> = 
> = 
> = 
> = 
> = 
> ======================================================================
> =================
> The following is the working scenario ...
> = 
> = 
> = 
> = 
> = 
> = 
> ======================================================================
> =================
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP:TRANSACTION |  
> 3372 |
> TransactionUser.cxx:74 | Match!
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP | 3372 |
> Helper.cxx:372 | Helper::makeResponse(SipReq:  BYE  
> 118@xxxxxxxxxxxxxx:12111
> tid=-b0ed5168 cseq=BYE / 103 from(wire) code=100 reason=
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP:TRANSACTION |  
> 3372 |
> TimerQueue.cxx:85 | Adding timer: Timer Trying tid=-b0ed5168 ms=3500
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP:TRANSACTION |  
> 3372 |
> TransactionState.cxx:1956 | Send to TU: TU: DialogUsageManager size=0
>
> BYE sip:118@xxxxxxxxxxxxxx:12111;rinstance=b42bbc240d7a6105 SIP/2.0
> Via: SIP/2.0/UDP 192.168.10.202:5060;branch=z9hG4bK-b0ed5168
> Max-Forwards: 70
> To: <sip:118@xxxxxxxxxxxxxx>;tag=d506286d
> From: Ali Ziad Home <sip:100@xxxxxxxxxxxxxx>;tag=6335d0b68949cc59o0
> Call-ID: 755f29ba-abb6a725@xxxxxxxxxxxxxx
> CSeq: 103 BYE
> Proxy-Authorization: Digest
> username 
> ="100",realm="192.168.10.206",nonce="12860004504:fcdf307358e7174abf9
> 5b8aa8c461c8e",uri="sip: 
> 118@xxxxxxxxxxxxxx:12111",algorithm=MD5,response="a7
> 21cdb6520739b3dbab4e6c95d8a7b4",qop=auth,nc=00000002,cnonce="dd0a79ee"
> User-Agent: Sipura/SPA1001-2.0.13(SEg)
> Content-Length: 0
>
> INFO | 20080708-112916.234 | Sytech:ResipLib | RESIP:DUM | 5168 |
> DialogUsageManager.cxx:1299 | Got: SipReq:  BYE  
> 118@xxxxxxxxxxxxxx:12111
> tid=-b0ed5168 cseq=BYE / 103 from(wire)
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP:DUM | 5168 |
> DialogUsageManager.cxx:1617 | DialogUsageManager::processRequest:  
> SipReq:
> BYE 118@xxxxxxxxxxxxxx:12111 tid=-b0ed5168 cseq=BYE / 103 from(wire)
> INFO | 20080708-112916.234 | Sytech:ResipLib | RESIP:DUM | 5168 |
> DialogUsageManager.cxx:1677 | Handling in-dialog request: SipReq:  BYE
> 118@xxxxxxxxxxxxxx:12111 tid=-b0ed5168 cseq=BYE / 103 from(wire)
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP:DUM | 5168 |
> DialogId.cxx:50 | DialogId::DialogId:
> 755f29ba-abb6a725@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> DEBUG | 20080708-112916.234 | Sytech:ResipLib | RESIP:DUM | 5168 |
> DialogSet.cxx:467 | Found matching dialog mClientSubscriptions(0),
> mServerSubscriptions(0) for
>
>
> _______________________________________________
> resiprocate-users mailing list
> resiprocate-users@xxxxxxxxxxxxxxx
> List Archive: http://list.resiprocate.org/archive/resiprocate-users/
>
> _______________________________________________
> resiprocate-users mailing list
> resiprocate-users@xxxxxxxxxxxxxxx
> List Archive: http://list.resiprocate.org/archive/resiprocate-users/
References:
- [reSIProcate-users] resip stack, and remote UAs behind NAT
  - From: Max Bowsher
- [reSIProcate-users] Hanging up problem, BYE message processed differently on two machines
  - From: Ali Ziad
- Re: [reSIProcate-users] Hanging up problem, BYE message processed differently on two machines
  - From: Ali Ziad
- Re: [reSIProcate-users] Hanging up problem, BYE message processed differently on two machines
  - From: Robert Sparks
Prev by Date: [reSIProcate-users] SIP / TCP and DTMF<>INFO
Next by Date: [reSIProcate-users] How to get all the registered users from a sip proxy??
Previous by thread: Re: [reSIProcate-users] Hanging up problem, BYE message processed differently on two machines
Next by thread: Re: [reSIProcate-users] resip stack, and remote UAs behind NAT
Index(es):
- Date
- Thread