Up to Discussions in OpenSIPStack

This Question is Answered

1 "correct" answer available (5 pts) 2 "helpful" answers available (1 pts)
8 Replies Last post: Jun 23, 2008 3:38 PM by cam100  
Click to view cam100's profile  
cam100
8 posts since
Jun 10, 2008

Jun 14, 2008 7:12 AM

upper registration route problem - authentication fails

Hi all,


I have been searching the forum for hours now but can not find any hint what I' m doing wrong. I' m running OpenSBC in B2B upper registration mode and would like to have my clients registering whith our existing softswitch. I have set up everything according to the tutorials and howto's which can be found in this forum.

The client sends a register message to the SBC, the SBC acknowledges that there is an upper registration route and forwards the request to the softswitch. The softswitch reguires digest authentication and sends a 401 unauthorized back. I would expect now that this message is relayed back to the original client in order to continue with the authentication.


For some reason, that message never arrives at the client - therefore the client is trying and trying to authenticate.


Here is what I' m seeing in the log file:


337066:25:26.471 INF: [CID=0x0e02] <<< REGISTER sip:sip.fakedomain.net SIP/2.0 SRC: 192.168.10.3:37934:UDP enc=0 bytes=576
337066:25:26.471 DBG: [CID=0x0e02]
337066:25:26.471 DBG: [CID=0x0e02] REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.471 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>;tag=6613195e
337066:25:26.471 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>
337066:25:26.471 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-
337066:25:26.471 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.471 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.471 DBG: [CID=0x0e02] Contact: <sip:8621430679@192.168.10.3:37934;rinstance=6e999ef109459e0f>
337066:25:26.471 DBG: [CID=0x0e02] User-Agent: X-Lite release 1011s stamp 41150
337066:25:26.471 DBG: [CID=0x0e02] Expires: 3600
337066:25:26.471 DBG: [CID=0x0e02] Max-Forwards: 70
337066:25:26.471 DBG: [CID=0x0e02] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
337066:25:26.471 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.471 DBG: [CID=0x0e02]
337066:25:26.471 DBG: [CID=0x0e02]
337066:25:26.473 DBG: [CID=0x0e02] Finding transaction for REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.473 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK-d87543-30153228e21d0017-1--d87543-|REGISTER
337066:25:26.474 DBG: [CID=0x0e02]
337066:25:26.474 DBG: [CID=0x0e02] *** CREATING TRANSACTION (NIST) ***
337066:25:26.474 DBG: [CID=0x0e02] Message: REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.474 DBG: [CID=0x0e02] Call-Id: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.474 DBG: [CID=0x0e02]
337066:25:26.475 DTL: [CID=0x0e02] NIST(2258349004) *** CREATED *** - NIST|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK-d87543-30153228e21d0017-1--d87543-|REGISTER
337066:25:26.477 DTL: [CID=0x0e02] NIST(2258349004) Event(SIPMessage) - REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.477 DBG: [CID=0x0e02] TRANSACTION: (NIST) REGISTER sip:sip.fakedomain.net SIP/2.0 State: 0
337066:25:26.478 DTL: [CID=0x0e02] NIST(2258349004) StateIdle->StateTrying
337066:25:26.478 DBG: [CID=0x0e02] Event: SIPStack::Enqueue(REGISTER sip:sip.fakedomain.net SIP/2.0)
337066:25:26.480 DBG: [CID=0x0e02] Event: B2BUserAgent::ProcessEvent( REGISTER sip:sip.fakedomain.net SIP/2.0 )
337066:25:26.484 DBG: [CID=0x0e02] Event: Setting UA Core [Proxy] to handle event REGISTER
337066:25:26.484 DTL: [CID=0x0e02] Event: ---> Inbound - REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.485 DBG: [CID=0x0e02] Session CREATED
337066:25:26.486 INF: [CID=0x0e02] *** CREATED *** PROXY Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.487 DBG: [CID=0x0e02] *** MESSAGE ARRIVAL *** for SIP Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.493 DTL: [CID=0x0e02] Found NIST|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK-d87543-30153228e21d0017-1--d87543-|REGISTER for SIP/2.0 100 Trying
337066:25:26.494 DTL: [CID=0x0e02] NIST(2258349004) Event(SIPMessage) - SIP/2.0 100 Trying
337066:25:26.494 DBG: [CID=0x0e02] TRANSACTION: (NIST) SIP/2.0 100 Trying State: 1
337066:25:26.495 DTL: [CID=0x0e02] NIST(2258349004) StateTrying->StateProceeding
337066:25:26.499 INF: [CID=0x0e02] >>> SIP/2.0 100 Trying DST: 192.168.10.3:37934:UDP SRC: 85.xxx.x.200:5060 enc=0 bytes=388
337066:25:26.500 DBG: [CID=0x0e02]
337066:25:26.500 DBG: [CID=0x0e02] SIP/2.0 100 Trying
337066:25:26.500 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>;tag=6613195e
337066:25:26.500 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>
337066:25:26.500 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;iid=16143;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-;rport=37934;received=192.168.10.3
337066:25:26.500 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.500 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.500 DBG: [CID=0x0e02] Server: OpenSBC v1.1.5-6
337066:25:26.500 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.500 DBG: [CID=0x0e02]
337066:25:26.500 DBG: [CID=0x0e02]
337066:25:26.504 INF: [CID=0x0e02] Routing REGISTER for URI sip:8621430679 at sip dot fakedomain dot net
337066:25:26.505 PWL: [CID=0x0000] -->> From: sip:8621430679 at sip dot fakedomain dot net Target: REGISTER sip:8621430679 at softswitch dot mydomain dot net;domain=softswitch.mydomain.net
337066:25:26.507 INF: [CID=0x0e02] *** UPPER REGISTRATION ENABLE *** for sip:8621430679 at sip dot fakedomain dot net
337066:25:26.511 DBG: [CID=0x06cb] CREATED via=85.xxx.x.200:5060 for target=85.xxx.x.85 protocol=UDP
337066:25:26.513 DBG: [CID=0x0e02] Proxying request REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.516 DBG: [CID=0x0e02] Finding transaction for REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.516 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:26.517 DBG: [CID=0x0e02]
337066:25:26.517 DBG: [CID=0x0e02] *** CREATING TRANSACTION (NICT) ***
337066:25:26.517 DBG: [CID=0x0e02] Message: REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.517 DBG: [CID=0x0e02] Call-Id: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.517 DBG: [CID=0x0e02]
337066:25:26.518 DTL: [CID=0x0e02] NICT(2258349005) *** CREATED *** - NICT|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:26.520 DTL: [CID=0x0e02] NICT(2258349005) Event(SIPMessage) - REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.521 DBG: [CID=0x0e02] TRANSACTION: (NICT) REGISTER sip:softswitch.mydomain.net SIP/2.0 State: 0
337066:25:26.521 DTL: [CID=0x0e02] NICT(2258349005) StateIdle->StateTrying(REGISTER sip:softswitch.mydomain.net SIP/2.0)
337066:25:26.521 DBG: [CID=0x0e02] NICT(2258349005) Timer E( 500 ms ) STARTED
337066:25:26.521 DBG: [CID=0x0e02] NICT(2258349005) Timer F( 10000 ms ) STARTED
337066:25:26.528 INF: [CID=0x0e02] >>> REGISTER sip:softswitch.mydomain.net SIP/2.0 DST: 85.xxx.x.85:5060:UDP SRC: 85.xxx.x.200:5060 enc=0 bytes=770
337066:25:26.529 DBG: [CID=0x0e02]
337066:25:26.529 DBG: [CID=0x0e02] REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.529 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at softswitch dot mydomain dot net>;tag=6613195e
337066:25:26.529 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>
337066:25:26.529 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 85.xxx.x.200:5060;iid=16143;branch=z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220;uas-addr=85.xxx.x.85;rport
337066:25:26.529 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-;rport=37934;received=192.168.10.3
337066:25:26.529 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.529 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.529 DBG: [CID=0x0e02] Contact: <sip:8621430679@85.xxx.x.200:5062;rinstance=6e999ef109459e0f>
337066:25:26.529 DBG: [CID=0x0e02] User-Agent: OpenSBC v1.1.5-6
337066:25:26.529 DBG: [CID=0x0e02] Expires: 3600
337066:25:26.529 DBG: [CID=0x0e02] Max-Forwards: 69
337066:25:26.529 DBG: [CID=0x0e02] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
337066:25:26.529 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.529 DBG: [CID=0x0e02]
337066:25:26.529 DBG: [CID=0x0e02]
337066:25:26.544 INF: [CID=0x0e02] <<< SIP/2.0 401 Unauthorized SRC: 85.xxx.x.85:5060:UDP enc=0 bytes=681
337066:25:26.545 DBG: [CID=0x0e02]
337066:25:26.545 DBG: [CID=0x0e02] SIP/2.0 401 Unauthorized
337066:25:26.545 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at softswitch dot mydomain dot net>;tag=6613195e
337066:25:26.545 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>;tag=1_1146_t930_7352
337066:25:26.545 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 85.xxx.x.200:5060;iid=16143;branch=z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220;uas-addr=85.xxx.x.85;rport=5060;received=85.xxx.x.200
337066:25:26.545 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-;rport=37934;received=192.168.10.3
337066:25:26.545 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.545 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.545 DBG: [CID=0x0e02] WWW-Authenticate: Digest realm="ccsip", nonce="455432f8519b24380e57d40f5f2cca7f", algorithm=MD5, qop="auth"
337066:25:26.545 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.545 DBG: [CID=0x0e02]
337066:25:26.545 DBG: [CID=0x0e02]
337066:25:26.546 DBG: [CID=0x0e02] Finding transaction for SIP/2.0 401 Unauthorized
337066:25:26.546 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:26.547 DTL: [CID=0x0e02] Found NICT|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER for SIP/2.0 401 Unauthorized
337066:25:26.548 DTL: [CID=0x0e02] NICT(2258349005) Event(SIPMessage) - SIP/2.0 401 Unauthorized
337066:25:26.548 DBG: [CID=0x0e02] TRANSACTION: (NICT) SIP/2.0 401 Unauthorized State: 1
337066:25:26.548 DTL: [CID=0x0e02] NICT(2258349005) StateTrying->StateCompleted
337066:25:26.548 DBG: [CID=0x0e02] NICT(2258349005) Timer E STOPPED
337066:25:26.549 DBG: [CID=0x0e02] NICT(2258349005) Timer F STOPPED
337066:25:26.549 DBG: [CID=0x0e02] Event: SIPStack::Enqueue(SIP/2.0 401 Unauthorized)
337066:25:26.550 DBG: [CID=0x0e02] NICT(2258349005) Timer K( 5000 ms ) STARTED
337066:25:26.551 DBG: [CID=0x0e02] Event: B2BUserAgent::ProcessEvent( SIP/2.0 401 Unauthorized )
337066:25:26.553 DBG: [CID=0x0e02] Event: Setting UA Core [Proxy] to handle event REGISTER
337066:25:26.553 DTL: [CID=0x0e02] Event: ---> Inbound - SIP/2.0 401 Unauthorized
337066:25:26.554 DBG: [CID=0x0e02] *** MESSAGE ARRIVAL *** for SIP Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.700 DBG: [CID=0x0e02] NICT(2258349005) Timer K( 5000 ms ) EXPIRED
337066:25:32.706 DBG: [CID=0x0e02] Finding transaction for SIP/2.0 401 Unauthorized
337066:25:32.707 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:32.708 DBG: [CID=0x0e02]
337066:25:32.708 DBG: [CID=0x0e02] *** TRANSACTION DOES NOT EXIST ***
337066:25:32.708 DBG: [CID=0x0e02] Message: SIP/2.0 401 Unauthorized
337066:25:32.708 DBG: [CID=0x0e02] Call-Id: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.708 DBG: [CID=0x0e02]
337066:25:32.709 DTL: [CID=0x06cb] *** QUEUED FOR DELETION *** SIPSession: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.709 DBG: [CID=0x0000] GC: First Stale Object ProxySession
337066:25:32.722 INF: [CID=0x0e02] *** DESTROYED *** PROXY Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.722 DBG: [CID=0x0e02] PROXY: Session DESTROYED


Has somebody seen such a behavior ? Is my expectation right that the SBC should forward the request and not close the proxy session immediately ?

Many thanks in advance.


Andre

Click to view joegen's profile  
joegen
519 posts since
Apr 28, 2007
1. Jun 16, 2008 9:24 PM in response to: cam100
Re: upper registration route problem - authentication fails
Hi,

I am unable to replicate this in my box. However, I have a hunch what is causing this for you. You need to help me out understand why it is happening. Can you trace though ProxySession.cxx for me and find the following code block:

void ProxySession::OnFinalResponse( SIPMessage & message )
{
GCVERIFYREF_VOID( "ProxySession::OnFinalResponse" );

SIPMessage response = message;

Via via;
response.GetViaAt( 0, via );

if( GetTransportManager()->IsLocalAddressAndPort( via.GetURI() ) )
response.PopTopVia();

If my hunch is correct, OpenSBC is unable to POP the top-most via of the response because it did not resolve as a local address:port. Can you confirm this? Please add a PTRACE within the if block like so:

if( GetTransportManager()->IsLocalAddressAndPort( via.GetURI() ) )
{
PTRACE( 1, "FATAL!!!! Unable to POP Top-most Via" );
response.PopTopVia();
}

Let me know if it appears in your tests. If you are a developer, it would be nice if you could trace into IsLocalAddressAndPort function and tell me where it fails.

Joegen

{quote:title=cam100 wrote:}{quote}
Hi all,


I have been searching the forum for hours now but can not find any hint what I' m doing wrong. I' m running OpenSBC in B2B upper registration mode and would like to have my clients registering whith our existing softswitch. I have set up everything according to the tutorials and howto's which can be found in this forum.

The client sends a register message to the SBC, the SBC acknowledges that there is an upper registration route and forwards the request to the softswitch. The softswitch reguires digest authentication and sends a 401 unauthorized back. I would expect now that this message is relayed back to the original client in order to continue with the authentication.


For some reason, that message never arrives at the client - therefore the client is trying and trying to authenticate.


Here is what I' m seeing in the log file:


337066:25:26.471 INF: [CID=0x0e02] <<< REGISTER sip:sip.fakedomain.net SIP/2.0 SRC: 192.168.10.3:37934:UDP enc=0 bytes=576
337066:25:26.471 DBG: [CID=0x0e02]
337066:25:26.471 DBG: [CID=0x0e02] REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.471 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>;tag=6613195e
337066:25:26.471 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>
337066:25:26.471 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-
337066:25:26.471 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.471 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.471 DBG: [CID=0x0e02] Contact: <sip:8621430679@192.168.10.3:37934;rinstance=6e999ef109459e0f>
337066:25:26.471 DBG: [CID=0x0e02] User-Agent: X-Lite release 1011s stamp 41150
337066:25:26.471 DBG: [CID=0x0e02] Expires: 3600
337066:25:26.471 DBG: [CID=0x0e02] Max-Forwards: 70
337066:25:26.471 DBG: [CID=0x0e02] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
337066:25:26.471 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.471 DBG: [CID=0x0e02]
337066:25:26.471 DBG: [CID=0x0e02]
337066:25:26.473 DBG: [CID=0x0e02] Finding transaction for REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.473 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK-d87543-30153228e21d0017-1--d87543-|REGISTER
337066:25:26.474 DBG: [CID=0x0e02]
337066:25:26.474 DBG: [CID=0x0e02] *** CREATING TRANSACTION (NIST) ***
337066:25:26.474 DBG: [CID=0x0e02] Message: REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.474 DBG: [CID=0x0e02] Call-Id: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.474 DBG: [CID=0x0e02]
337066:25:26.475 DTL: [CID=0x0e02] NIST(2258349004) *** CREATED *** - NIST|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK-d87543-30153228e21d0017-1--d87543-|REGISTER
337066:25:26.477 DTL: [CID=0x0e02] NIST(2258349004) Event(SIPMessage) - REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.477 DBG: [CID=0x0e02] TRANSACTION: (NIST) REGISTER sip:sip.fakedomain.net SIP/2.0 State: 0
337066:25:26.478 DTL: [CID=0x0e02] NIST(2258349004) StateIdle->StateTrying
337066:25:26.478 DBG: [CID=0x0e02] Event: SIPStack::Enqueue(REGISTER sip:sip.fakedomain.net SIP/2.0)
337066:25:26.480 DBG: [CID=0x0e02] Event: B2BUserAgent::ProcessEvent( REGISTER sip:sip.fakedomain.net SIP/2.0 )
337066:25:26.484 DBG: [CID=0x0e02] Event: Setting UA Core [Proxy] to handle event REGISTER
337066:25:26.484 DTL: [CID=0x0e02] Event: ---> Inbound - REGISTER sip:sip.fakedomain.net SIP/2.0
337066:25:26.485 DBG: [CID=0x0e02] Session CREATED
337066:25:26.486 INF: [CID=0x0e02] *** CREATED *** PROXY Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.487 DBG: [CID=0x0e02] *** MESSAGE ARRIVAL *** for SIP Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.493 DTL: [CID=0x0e02] Found NIST|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK-d87543-30153228e21d0017-1--d87543-|REGISTER for SIP/2.0 100 Trying
337066:25:26.494 DTL: [CID=0x0e02] NIST(2258349004) Event(SIPMessage) - SIP/2.0 100 Trying
337066:25:26.494 DBG: [CID=0x0e02] TRANSACTION: (NIST) SIP/2.0 100 Trying State: 1
337066:25:26.495 DTL: [CID=0x0e02] NIST(2258349004) StateTrying->StateProceeding
337066:25:26.499 INF: [CID=0x0e02] >>> SIP/2.0 100 Trying DST: 192.168.10.3:37934:UDP SRC: 85.xxx.x.200:5060 enc=0 bytes=388
337066:25:26.500 DBG: [CID=0x0e02]
337066:25:26.500 DBG: [CID=0x0e02] SIP/2.0 100 Trying
337066:25:26.500 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>;tag=6613195e
337066:25:26.500 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>
337066:25:26.500 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;iid=16143;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-;rport=37934;received=192.168.10.3
337066:25:26.500 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.500 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.500 DBG: [CID=0x0e02] Server: OpenSBC v1.1.5-6
337066:25:26.500 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.500 DBG: [CID=0x0e02]
337066:25:26.500 DBG: [CID=0x0e02]
337066:25:26.504 INF: [CID=0x0e02] Routing REGISTER for URI sip:8621430679 at sip dot fakedomain dot net
337066:25:26.505 PWL: [CID=0x0000] -->> From: sip:8621430679 at sip dot fakedomain dot net Target: REGISTER sip:8621430679 at softswitch dot mydomain dot net;domain=softswitch.mydomain.net
337066:25:26.507 INF: [CID=0x0e02] *** UPPER REGISTRATION ENABLE *** for sip:8621430679 at sip dot fakedomain dot net
337066:25:26.511 DBG: [CID=0x06cb] CREATED via=85.xxx.x.200:5060 for target=85.xxx.x.85 protocol=UDP
337066:25:26.513 DBG: [CID=0x0e02] Proxying request REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.516 DBG: [CID=0x0e02] Finding transaction for REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.516 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:26.517 DBG: [CID=0x0e02]
337066:25:26.517 DBG: [CID=0x0e02] *** CREATING TRANSACTION (NICT) ***
337066:25:26.517 DBG: [CID=0x0e02] Message: REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.517 DBG: [CID=0x0e02] Call-Id: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.517 DBG: [CID=0x0e02]
337066:25:26.518 DTL: [CID=0x0e02] NICT(2258349005) *** CREATED *** - NICT|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:26.520 DTL: [CID=0x0e02] NICT(2258349005) Event(SIPMessage) - REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.521 DBG: [CID=0x0e02] TRANSACTION: (NICT) REGISTER sip:softswitch.mydomain.net SIP/2.0 State: 0
337066:25:26.521 DTL: [CID=0x0e02] NICT(2258349005) StateIdle->StateTrying(REGISTER sip:softswitch.mydomain.net SIP/2.0)
337066:25:26.521 DBG: [CID=0x0e02] NICT(2258349005) Timer E( 500 ms ) STARTED
337066:25:26.521 DBG: [CID=0x0e02] NICT(2258349005) Timer F( 10000 ms ) STARTED
337066:25:26.528 INF: [CID=0x0e02] >>> REGISTER sip:softswitch.mydomain.net SIP/2.0 DST: 85.xxx.x.85:5060:UDP SRC: 85.xxx.x.200:5060 enc=0 bytes=770
337066:25:26.529 DBG: [CID=0x0e02]
337066:25:26.529 DBG: [CID=0x0e02] REGISTER sip:softswitch.mydomain.net SIP/2.0
337066:25:26.529 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at softswitch dot mydomain dot net>;tag=6613195e
337066:25:26.529 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>
337066:25:26.529 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 85.xxx.x.200:5060;iid=16143;branch=z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220;uas-addr=85.xxx.x.85;rport
337066:25:26.529 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-;rport=37934;received=192.168.10.3
337066:25:26.529 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.529 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.529 DBG: [CID=0x0e02] Contact: <sip:8621430679@85.xxx.x.200:5062;rinstance=6e999ef109459e0f>
337066:25:26.529 DBG: [CID=0x0e02] User-Agent: OpenSBC v1.1.5-6
337066:25:26.529 DBG: [CID=0x0e02] Expires: 3600
337066:25:26.529 DBG: [CID=0x0e02] Max-Forwards: 69
337066:25:26.529 DBG: [CID=0x0e02] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
337066:25:26.529 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.529 DBG: [CID=0x0e02]
337066:25:26.529 DBG: [CID=0x0e02]
337066:25:26.544 INF: [CID=0x0e02] <<< SIP/2.0 401 Unauthorized SRC: 85.xxx.x.85:5060:UDP enc=0 bytes=681
337066:25:26.545 DBG: [CID=0x0e02]
337066:25:26.545 DBG: [CID=0x0e02] SIP/2.0 401 Unauthorized
337066:25:26.545 DBG: [CID=0x0e02] From: "SoftClient01" <sip:8621430679 at softswitch dot mydomain dot net>;tag=6613195e
337066:25:26.545 DBG: [CID=0x0e02] To: "SoftClient01" <sip:8621430679 at sip dot fakedomain dot net>;tag=1_1146_t930_7352
337066:25:26.545 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 85.xxx.x.200:5060;iid=16143;branch=z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220;uas-addr=85.xxx.x.85;rport=5060;received=85.xxx.x.200
337066:25:26.545 DBG: [CID=0x0e02] Via: SIP/2.0/UDP 192.168.10.3:37934;branch=z9hG4bK-d87543-30153228e21d0017-1--d87543-;rport=37934;received=192.168.10.3
337066:25:26.545 DBG: [CID=0x0e02] CSeq: 1 REGISTER
337066:25:26.545 DBG: [CID=0x0e02] Call-ID: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:26.545 DBG: [CID=0x0e02] WWW-Authenticate: Digest realm="ccsip", nonce="455432f8519b24380e57d40f5f2cca7f", algorithm=MD5, qop="auth"
337066:25:26.545 DBG: [CID=0x0e02] Content-Length: 0
337066:25:26.545 DBG: [CID=0x0e02]
337066:25:26.545 DBG: [CID=0x0e02]
337066:25:26.546 DBG: [CID=0x0e02] Finding transaction for SIP/2.0 401 Unauthorized
337066:25:26.546 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:26.547 DTL: [CID=0x0e02] Found NICT|OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER for SIP/2.0 401 Unauthorized
337066:25:26.548 DTL: [CID=0x0e02] NICT(2258349005) Event(SIPMessage) - SIP/2.0 401 Unauthorized
337066:25:26.548 DBG: [CID=0x0e02] TRANSACTION: (NICT) SIP/2.0 401 Unauthorized State: 1
337066:25:26.548 DTL: [CID=0x0e02] NICT(2258349005) StateTrying->StateCompleted
337066:25:26.548 DBG: [CID=0x0e02] NICT(2258349005) Timer E STOPPED
337066:25:26.549 DBG: [CID=0x0e02] NICT(2258349005) Timer F STOPPED
337066:25:26.549 DBG: [CID=0x0e02] Event: SIPStack::Enqueue(SIP/2.0 401 Unauthorized)
337066:25:26.550 DBG: [CID=0x0e02] NICT(2258349005) Timer K( 5000 ms ) STARTED
337066:25:26.551 DBG: [CID=0x0e02] Event: B2BUserAgent::ProcessEvent( SIP/2.0 401 Unauthorized )
337066:25:26.553 DBG: [CID=0x0e02] Event: Setting UA Core [Proxy] to handle event REGISTER
337066:25:26.553 DTL: [CID=0x0e02] Event: ---> Inbound - SIP/2.0 401 Unauthorized
337066:25:26.554 DBG: [CID=0x0e02] *** MESSAGE ARRIVAL *** for SIP Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.700 DBG: [CID=0x0e02] NICT(2258349005) Timer K( 5000 ms ) EXPIRED
337066:25:32.706 DBG: [CID=0x0e02] Finding transaction for SIP/2.0 401 Unauthorized
337066:25:32.707 DBG: [CID=0x0e02] Setting Transaction ID to OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.|z9hG4bK4cba98df6938dd118b1d98e0e14f783f-69bc052885e284aa4b0d2044600ff220|REGISTER
337066:25:32.708 DBG: [CID=0x0e02]
337066:25:32.708 DBG: [CID=0x0e02] *** TRANSACTION DOES NOT EXIST ***
337066:25:32.708 DBG: [CID=0x0e02] Message: SIP/2.0 401 Unauthorized
337066:25:32.708 DBG: [CID=0x0e02] Call-Id: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.708 DBG: [CID=0x0e02]
337066:25:32.709 DTL: [CID=0x06cb] *** QUEUED FOR DELETION *** SIPSession: OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.709 DBG: [CID=0x0000] GC: First Stale Object ProxySession
337066:25:32.722 INF: [CID=0x0e02] *** DESTROYED *** PROXY Session OWFkMTI4ODljOGQ3NjA1MDM1NzY0ZGViZDUzMjZmMmM.
337066:25:32.722 DBG: [CID=0x0e02] PROXY: Session DESTROYED


Has somebody seen such a behavior ? Is my expectation right that the SBC should forward the request and not close the proxy session immediately ?

Many thanks in advance.


Andre
Click to view joegen's profile  
joegen
519 posts since
Apr 28, 2007
2. Jun 16, 2008 9:38 PM in response to: joegen
Re: upper registration route problem - authentication fails
oops! sorryy it should be

if( GetTransportManager()->IsLocalAddressAndPort( via.GetURI() ) )
{
response.PopTopVia();
}else
{
PTRACE( 1, "FATAL!!!! Unable to POP Top-most Via" );
}

Joegen

Click to view cam100's profile  
cam100
8 posts since
Jun 10, 2008
3. Jun 17, 2008 9:33 AM in response to: cam100
Re: upper registration route problem - authentication fails
Hello Joegen,

many thanks for your reply and pointing me into the right direction. You have been perfectly right with your hunch - the problem is that the OpenSBC cannot pop the first via header. I have digged a bit deeper into the source code and added some traces to the functions where I suspect the error.

From my point of view it goes the following way :

1. ProxySession.cxx --> GetTransportManager()->IsLocalAddressAndPort( via.GetURI() ) is called
since this call fails, response.PopTopVia() is not executed and the message is not routed back to the client

2. Within SIPTransportManager::IsLocalAddressAndPort the function SIPTransport::Resolve( uri, addr, port ) is called
- the call for this function fails and FALSE is returned

3. SIPTransport::Resolve is called. I' m still trying to find out at which point it fails in this function. I will provide an update as soon as I know.

Regards,

Andre

Click to view cam100's profile  
cam100
8 posts since
Jun 10, 2008
4. Jun 17, 2008 11:28 AM in response to: cam100
Re: upper registration route problem - authentication fails
Hello Joegen,

here is what I get from the logs now.

337143:14:56.132 INF: [CID=0x0d58] <<< REGISTER sip:sip.fakedomain.net SIP/2.0 SRC: 192.168.10.3:10164:UDP enc=0 bytes=576
337143:14:56.143 INF: [CID=0x0d58] *** CREATED *** PROXY Session ZDY1MWMxYjg4NWM5Nzc1M2ZmMGY2MjM1NDI5ZmQ1N2E.
337143:14:56.156 INF: [CID=0x0d58] >>> SIP/2.0 100 Trying DST: 192.168.10.3:10164:UDP SRC: 85.xxx.x.:5060 enc=0 bytes=388
337143:14:56.161 INF: [CID=0x0d58] Routing REGISTER for URI sip:8621430679 at sip dot fakedomain dot net
337143:14:56.163 PWL: [CID=0x0000] -->> From: sip:8621430679 at sip dot fakedomain dot net Target: REGISTER sip:8621430679 at softswitch dot mydomain dot net;domain=softswitch.mydomain.net
337143:14:56.166 INF: [CID=0x0d58] *** UPPER REGISTRATION ENABLE *** for sip:8621430679 at sip dot fakedomain dot net
337143:14:56.184 INF: [CID=0x0d58] >>> REGISTER sip:softswitch.mydomain.net SIP/2.0 DST: 85.xxx.x.85:5060:UDP SRC: 85.xxx.x.:5060 enc=0 bytes=785
337143:14:56.198 INF: [CID=0x0d58] <<< SIP/2.0 401 Unauthorized SRC: 85.xxx.x.85:5060:UDP enc=0 bytes=697
--> those are the new debugging messages:
337143:14:56.267 PWL: [CID=0x0000] return false from SIPTransport::Resolve
337143:14:56.267 PWL: [CID=0x0000] return FALSE from SIPTransportManager::IsLocalAddressAndPort when calling SIPTransport::Resolve whith uri: sip: 85.xxx.x.:5060;iid=13477;branch=z9hG4bK7649f5cfed3add11880c857f5cf1f22e-619874e34902600b7e5781e691407b49;uas-addr=85.xxx.x.85;rport=5060;received=85.xxx.x. addr: 127.0.0.1 port: 0
337143:14:56.267 PWL: [CID=0x0000] FATAL ! Unable to POP Top-most Via sip: 85.xxx.x.:5060;iid=13477;branch=z9hG4bK7649f5cfed3add11880c857f5cf1f22e-619874e34902600b7e5781e691407b49;uas-addr=85.xxx.x.85;rport=5060;received=85.xxx.x.

Click to view joegen's profile  
joegen
519 posts since
Apr 28, 2007
5. Jun 17, 2008 10:49 PM in response to: cam100
Re: upper registration route problem - authentication fails
Hi,

Thanks for confirming. Since I can't replicate this locally, it seems this problem is specific to your box. It will be of great value if we can pinpoint where exactly it fails in SIPTransport::Resolve() so we can give the library a defense mechanism to prevent this behavior. To give you a clue where to look next. A lot of the stuffs in resolving uris happen in

[http://SIPSrvRecord.cxx|http://SIPSrvRecord.cxx]

BOOL SIPSrvRecord::Resolve(
const OString & _domain,
const OString & _proto,
WORD port
);

So if it SIPTransport::Resolve fails somewhere, this is likely the place where it will happen.

Joegen

Joegen

{quote:title=cam100 wrote:}{quote}
Hello Joegen,

here is what I get from the logs now.

337143:14:56.132 INF: [CID=0x0d58] <<< REGISTER sip:sip.fakedomain.net SIP/2.0 SRC: 192.168.10.3:10164:UDP enc=0 bytes=576
337143:14:56.143 INF: [CID=0x0d58] *** CREATED *** PROXY Session ZDY1MWMxYjg4NWM5Nzc1M2ZmMGY2MjM1NDI5ZmQ1N2E.
337143:14:56.156 INF: [CID=0x0d58] >>> SIP/2.0 100 Trying DST: 192.168.10.3:10164:UDP SRC: 85.xxx.x.:5060 enc=0 bytes=388
337143:14:56.161 INF: [CID=0x0d58] Routing REGISTER for URI sip:8621430679 at sip dot fakedomain dot net
337143:14:56.163 PWL: [CID=0x0000] -->> From: sip:8621430679 at sip dot fakedomain dot net Target: REGISTER sip:8621430679 at softswitch dot mydomain dot net;domain=softswitch.mydomain.net
337143:14:56.166 INF: [CID=0x0d58] *** UPPER REGISTRATION ENABLE *** for sip:8621430679 at sip dot fakedomain dot net
337143:14:56.184 INF: [CID=0x0d58] >>> REGISTER sip:softswitch.mydomain.net SIP/2.0 DST: 85.xxx.x.85:5060:UDP SRC: 85.xxx.x.:5060 enc=0 bytes=785
337143:14:56.198 INF: [CID=0x0d58] <<< SIP/2.0 401 Unauthorized SRC: 85.xxx.x.85:5060:UDP enc=0 bytes=697
--> those are the new debugging messages:
337143:14:56.267 PWL: [CID=0x0000] return false from SIPTransport::Resolve
337143:14:56.267 PWL: [CID=0x0000] return FALSE from SIPTransportManager::IsLocalAddressAndPort when calling SIPTransport::Resolve whith uri: sip: 85.xxx.x.:5060;iid=13477;branch=z9hG4bK7649f5cfed3add11880c857f5cf1f22e-619874e34902600b7e5781e691407b49;uas-addr=85.xxx.x.85;rport=5060;received=85.xxx.x. addr: 127.0.0.1 port: 0
337143:14:56.267 PWL: [CID=0x0000] FATAL ! Unable to POP Top-most Via sip: 85.xxx.x.:5060;iid=13477;branch=z9hG4bK7649f5cfed3add11880c857f5cf1f22e-619874e34902600b7e5781e691407b49;uas-addr=85.xxx.x.85;rport=5060;received=85.xxx.x.
Click to view cam100's profile  
cam100
8 posts since
Jun 10, 2008
6. Jun 23, 2008 12:11 PM in response to: joegen
Re: upper registration route problem - authentication fails

Hello Joegen,

I'm close to give up on that... I have been debugging a lot of things so far - but there is no true result. The only thing I have found is the following:


The via.GetUri() is called I see a strange behavior when we are parsing the via: headers. I added some debugs in order to find out what it causes:

337287:45:59.687 PWL: [CID=0x0000] show uri in via.GetURI Part 1:
337287:45:59.687 PWL: [CID=0x0000] show uri in via.GetURI Part 2, after GetAddress() sip: 85.xx.x.200
337287:45:59.687 PWL: [CID=0x0000] show uri in via.GetURI: sip: 85.xx.x.200:5060


As you can see, we have a space between sip: and the IP Address. What is your opinion ? Can that be the root cause ? I tried to find out where the sip: is added but were unable to. Can you please give me a hint ? Does it make sense to send you a complete SIP trace off list ? Many thanks for your help in advance.

Regards,

Andre

Click to view joegen's profile  
joegen
519 posts since
Apr 28, 2007
7. Jun 23, 2008 2:35 PM in response to: cam100
Re: upper registration route problem - authentication fails
Don't give up just yet. I think your server is re-encoding the Via in the response and adding an extra space after SIP/2.0/UDP. I have applied a patch that would handle this behavior. Try the latet from CVS and let me know how it goes.

Joegen

{quote:title=cam100 wrote:}{quote}

Hello Joegen,

I'm close to give up on that... I have been debugging a lot of things so far - but there is no true result. The only thing I have found is the following:


The via.GetUri() is called I see a strange behavior when we are parsing the via: headers. I added some debugs in order to find out what it causes:

337287:45:59.687 PWL: [CID=0x0000] show uri in via.GetURI Part 1:
337287:45:59.687 PWL: [CID=0x0000] show uri in via.GetURI Part 2, after GetAddress() sip: 85.xx.x.200
337287:45:59.687 PWL: [CID=0x0000] show uri in via.GetURI: sip: 85.xx.x.200:5060

As you can see, we have a space between sip: and the IP Address. What is your opinion ? Can that be the root cause ? I tried to find out where the sip: is added but were unable to. Can you please give me a hint ? Does it make sense to send you a complete SIP trace off list ? Many thanks for your help in advance.

Regards,

Andre

Click to view cam100's profile  
cam100
8 posts since
Jun 10, 2008
8. Jun 23, 2008 3:38 PM in response to: joegen
Re: upper registration route problem - authentication fails

Hello Joegen,

it works now, many thanks. A little Trim() makes sometimes a big difference... I need to spend a little bit more time reading the source code to get a better understanding.

Many thanks again for the great help.

Regards,

Andre

Actions

More Like This