Thread: [OpenSIPStack] upper registration route problem - proxy problem
Brought to you by:
joegenbaclor
Menu
▾
▴
opensipstack-devel
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-13 12:17:46
|
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 never happens. The client is trying and trying to authenticate. Here is a small sippet from the log file: 337043:56:45.661 INF: [CID=0x0853] Routing REGISTER for URI sip:xxx...@si... 337043:56:45.663 PWL: [CID=0x0000] -->> From: sip:xxx...@si... Target: REGISTER sip:xxx...@sw...;domain=switch.def.de 337043:56:45.665 INF: [CID=0x0853] *** UPPER REGISTRATION ENABLE *** for sip:xxx...@si... 337043:56:45.680 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337043:56:45.689 INF: [CID=0x0853] >>> REGISTER sip:switch.def.de SIP/2.0 DST: 85.xxx.x.xx:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=712 337043:56:45.702 INF: [CID=0x0853] <<< SIP/2.0 401 Unauthorized SRC: 85.xxx.x.xx:5060:UDP enc=0 bytes=653 337043:56:45.717 INF: [CID=0x0853] *** DESTROYED *** PROXY Session bbtzpwogsaqeoge@10.70.4.9 337043:56:46.110 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 ........ 337044:10:06.997 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:07.005 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:11.013 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:11.020 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:15.009 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:15.017 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:19.005 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:19.013 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:23.003 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:23.011 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:26.999 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:27.007 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:30.996 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:31.003 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:10:34.992 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 337044:10:34.999 INF: [CID=0x0853] >>> SIP/2.0 100 Trying DST: 10.70.4.9:5060:UDP SRC: 192.168.10.238:5060 enc=0 bytes=335 337044:11:08.461 INF: [CID=0x0853] <<< REGISTER sip:sip.ccgmbh.de SIP/2.0 SRC: 10.70.4.9:5060:UDP enc=0 bytes=469 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. |
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-17 01:24:38
|
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:862...@si...>;tag=6613195e
> 337066:25:26.471 DBG: [CID=0x0e02] To: "SoftClient01" <sip:862...@si...>
> 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:862...@si...>;tag=6613195e
> 337066:25:26.500 DBG: [CID=0x0e02] To: "SoftClient01" <sip:862...@si...>
> 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:862...@si...
> 337066:25:26.505 PWL: [CID=0x0000] -->> From: sip:862...@si... Target: REGISTER sip:862...@so...;domain=softswitch.mydomain.net
> 337066:25:26.507 INF: [CID=0x0e02] *** UPPER REGISTRATION ENABLE *** for sip:862...@si...
> 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:862...@so...>;tag=6613195e
> 337066:25:26.529 DBG: [CID=0x0e02] To: "SoftClient01" <sip:862...@si...>
> 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:862...@85....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:862...@so...>;tag=6613195e
> 337066:25:26.545 DBG: [CID=0x0e02] To: "SoftClient01" <sip:862...@si...>;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
|
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-17 01:39:07
|
oops! sorryy it should be
if( GetTransportManager()->IsLocalAddressAndPort( via.GetURI() ) )
{
response.PopTopVia();
}else
{
PTRACE( 1, "FATAL!!!! Unable to POP Top-most Via" );
}
Joegen
|
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-17 13:33:55
|
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
|
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-17 15:29:14
|
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:862...@si... 337143:14:56.163 PWL: [CID=0x0000] -->> From: sip:862...@si... Target: REGISTER sip:862...@so...;domain=softswitch.mydomain.net 337143:14:56.166 INF: [CID=0x0d58] *** UPPER REGISTRATION ENABLE *** for sip:862...@si... 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. |
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-18 02:49:39
|
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:862...@si...
> 337143:14:56.163 PWL: [CID=0x0000] -->> From: sip:862...@si... Target: REGISTER sip:862...@so...;domain=softswitch.mydomain.net
> 337143:14:56.166 INF: [CID=0x0d58] *** UPPER REGISTRATION ENABLE *** for sip:862...@si...
> 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.
|
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-23 16:12:14
|
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 |
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-23 18:36:19
|
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
>
>
>
>
>
|
|
From: OpenSIPStack F. <ope...@op...> - 2008-06-23 19:38:34
|
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 |
×
Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.
Thanks for helping keep SourceForge clean.
X