Up to Discussions in OpenSIPStack

This Question is Answered

1 "correct" answer available (4 pts) 2 "helpful" answers available (2 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@sip.fakedomain.net>;tag=6613195e
337066:25:26.471 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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@sip.fakedomain.net>;tag=6613195e
337066:25:26.500 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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@sip.fakedomain.net
337066:25:26.505 PWL: CID=0x0000 -->> From: sip:8621430679@sip.fakedomain.net Target: REGISTER sip:8621430679@softswitch.mydomain.net;domain=softswitch.mydomain.net
337066:25:26.507 INF: CID=0x0e02 *** UPPER REGISTRATION ENABLE *** for sip:8621430679@sip.fakedomain.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@softswitch.mydomain.net>;tag=6613195e
337066:25:26.529 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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@softswitch.mydomain.net>;tag=6613195e
337066:25:26.545 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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
136 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

cam100 wrote:
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@sip.fakedomain.net>;tag=6613195e
337066:25:26.471 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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@sip.fakedomain.net>;tag=6613195e
337066:25:26.500 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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@sip.fakedomain.net
337066:25:26.505 PWL: CID=0x0000 -->> From: sip:8621430679@sip.fakedomain.net Target: REGISTER sip:8621430679@softswitch.mydomain.net;domain=softswitch.mydomain.net
337066:25:26.507 INF: CID=0x0e02 *** UPPER REGISTRATION ENABLE *** for sip:8621430679@sip.fakedomain.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@softswitch.mydomain.net>;tag=6613195e
337066:25:26.529 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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@softswitch.mydomain.net>;tag=6613195e
337066:25:26.545 DBG: CID=0x0e02 To: "SoftClient01" <sip:8621430679@sip.fakedomain.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
136 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@sip.fakedomain.net
337143:14:56.163 PWL: CID=0x0000 -->> From: sip:8621430679@sip.fakedomain.net Target: REGISTER sip:8621430679@softswitch.mydomain.net;domain=softswitch.mydomain.net
337143:14:56.166 INF: CID=0x0d58 *** UPPER REGISTRATION ENABLE *** for sip:8621430679@sip.fakedomain.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
136 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

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

cam100 wrote:
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@sip.fakedomain.net
337143:14:56.163 PWL: CID=0x0000 -->> From: sip:8621430679@sip.fakedomain.net Target: REGISTER sip:8621430679@softswitch.mydomain.net;domain=softswitch.mydomain.net
337143:14:56.166 INF: CID=0x0d58 *** UPPER REGISTRATION ENABLE *** for sip:8621430679@sip.fakedomain.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
136 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

cam100 wrote:

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