[OpenSIPS-Users] Wrong ACK
goup2010
goup2010 at gmail.com
Fri Apr 20 13:32:19 CEST 2012
I send SIP trace
======== Opensips send 200 OK ==============
SIP/2.0 200 OK
Via: SIP/2.0/UDP
11.22.33.44;rport=5060;received=11.22.33.44;branch=z9hG4bK3bd4.e77f7ba1.0
Via: SIP/2.0/UDP 66.55.44.33:59050
;received=66.55.44.33;rport=59050;branch=z9hG4bKPjbf00VZezyzupEI5-i2gZmPGnwFiQay9a
Record-Route:
<sip:77.88.100.100;lr;ftag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU;did=c39.cf631a61>
Record-Route:
<sip:11.22.33.44;lr;ftag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU;did=c39.c01d4622>
From: <sip:77 at 11.22.33.44>;tag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU
To: <sip:15488 at 11.22.33.44>;tag=as776fa5cd
Call-ID: tcwJKO8ofRAPk3ndJbSfW4k5envUn9Bf
CSeq: 22589 INVITE
Server: ITG SBC
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:15488 at 87.11.11.11:2000>
Content-Type: application/sdp
Content-Length: 325
v=0
o=root 1580617885 1580617886 IN IP4 87.11.11.11
s=ITG SBC
c=IN IP4 87.11.11.11
t=0 0
m=audio 10466 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
======== Opensips receive ACK ==============
ACK sip:15488 at 77.88.100.100:5060 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44;branch=z9hG4bK3bd4.e77f7ba1.2
Via: SIP/2.0/UDP 66.55.44.33:59050
;received=66.55.44.33;rport=59050;branch=z9hG4bKPjhAnLMELM0.GE.jF7GfflQnGmFz8oMoGv
Max-Forwards: 69
From: <sip:77 at 11.22.33.44>;tag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU
To: <sip:15488 at 11.22.33.44>;tag=as776fa5cd
Call-ID: tcwJKO8ofRAPk3ndJbSfW4k5envUn9Bf
CSeq: 22589 ACK
Route:
<sip:77.88.100.100;lr;ftag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU;did=c39.cf631a61>
Content-Length: 0
======= trace log 6 ========================
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_msg: SIP Request:
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_msg: method: <ACK>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_msg: uri: <sip:15488 at 77.88.100.100:5060>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_msg: version: <SIP/2.0>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=2
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK3bd4.e77f7ba1.2>; state=16
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_via: end of header reached, state=5
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: via found, flags=2
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: this is the first via
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:receive_msg: After parse_msg...
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:receive_msg: preparing to run routing scripts...
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:sl:sl_filter_ACK: to late to be a local ACK!
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
++++++++++++++++++++++++++++++++++++++++++++++++++++ from 11.22.33.44:5060
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=100
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_via_param: found param type 234, <received> = <66.55.44.33>;
state=6
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_via_param: found param type 235, <rport> = <59050>; state=6
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKPjhAnLMELM0.GE.jF7GfflQnGmFz8oMoGv>; state=16
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_via: end of header reached, state=5
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: via found, flags=100
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: parse_headers: this is the second via
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:maxfwd:is_maxfwd_present: value = 69
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]: ASK from
11.22.33.44:5060
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=ffffffffffffffff
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_to_param: tag=as776fa5cd
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_to: end of header reached, state=29
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_to: display={}, ruri={sip:15488 at 11.22.33.44}
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44]
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44>]
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:get_hdr_field: cseq <CSeq>: <22589> <ACK>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:get_hdr_field: content_length=0
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:get_hdr_field: found end of header
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=ffffffffffffffff
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=ffffffffffffffff
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:uri:has_totag: totag found
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]: Have to_tag
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=200
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:rr:is_preloaded: is_preloaded: No
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:grep_sock_info: checking if host==us: 14==9 && [77.88.100.100] ==
[127.0.0.1]
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:grep_sock_info: checking if host==us: 14==14 && [77.88.100.100]
== [77.88.100.100]
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:rr:after_strict: Next hop:
'sip:77.88.100.100;lr;ftag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU;did=c39.cf631a61'
is loose router
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=ffffffffffffffff
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:rr:after_strict: The last route URI:
'sip:77.88.100.100;lr;ftag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU;did=c39.cf631a61'
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:rr:run_rr_callbacks: callback id 1 entered with <>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:dialog:dlg_onroute: Route param 'did' not found
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:rr:run_rr_callbacks: callback id 2 entered with <>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:uac:restore_uri: getting 'vsf' Route param
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:uac:restore_uri: route param 'vsf' not found
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:uac:restore_uri: getting 'vst' Route param
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:uac:restore_uri: route param 'vst' not found
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]: Sip Trace =
<null>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:siptrace:sip_trace: nothing to trace...
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]: Has totag -
loose route. Trace id <null>
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=ffffffffffffffff
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=78
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_lookup_request: start searching: hash=19891, isACK=1
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_headers: flags=38
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_to_param: tag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_to: end of header reached, state=29
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:parse_to: display={}, ruri={sip:77 at 11.22.33.44}
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f90daccda40] after is 1
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_lookup_request: e2e proxy ACK found
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_newtran: building branch for end2end ACK - flags=1
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_relay_to: forwarding ACK
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:mk_proxy: doing DNS lookup...
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:forward_request: sending:#012ACK
sip:77.88.100.100;lr;ftag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU;did=c39.cf631a61
SIP/2.0#015#012Via: SIP/2.0/UDP
77.88.100.100;branch=z9hG4bK3bd4.ad913244.2#015#012Via: SIP/2.0/UDP
11.22.33.44;rport=5060;received=11.22.33.44;branch=z9hG4bK3bd4.e77f7ba1.2#015#012Via:
SIP/2.0/UDP 66.55.44.33:59050;received=66.55.44.33;rport=59050;branch=z9hG4bKPjhAnLMELM0.GE.jF7GfflQnGmFz8oMoGv#015#012Max-Forwards:
68#015#012From:
<sip:77 at 11.22.33.44>;tag=gTVXPlnKDDix.LcLHTy4Ck9s5gLwC4PU#015#012To:
<sip:15488 at 11.22.33.44>;tag=as776fa5cd#015#012Call-ID:
tcwJKO8ofRAPk3ndJbSfW4k5envUn9Bf#015#012CSeq: 22589
ACK#015#012Content-Length: 0#015#012#015#012.
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:forward_request: orig. len=517, new_len=572, proto=1
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:run_fwd_callbacks: FWD callback entered
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:siptrace:trace_msg_out: trace off...
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]: Send relay.
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f90daccda40] after is 0
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:destroy_avp_list: destroying list 0x7f90dacd12c0
Apr 20 14:16:41 routecall /usr/local/sbin/opensips[31138]:
DBG:core:receive_msg: cleaning up
2012/4/20 Vlad Paiu <vladpaiu at opensips.org>
> **
> Hi,
>
> Please post the SIP trace as well, for the entire dialog.
>
> Regards,
>
> Vlad Paiu
> OpenSIPS Developerhttp://www.opensips-solutions.com
>
>
> On 04/20/2012 02:26 AM, goup2010 wrote:
>
> Hello,
>
> I use latest openisps 1.8 by follow sheme:
>
> opensips 1 (11.22.33.44)-----> opensips 2 (77.88.100.100)
>
> When opensips 2 receive ACK I see follow problems:
>
> 1. In trace debug 6 I see message:
> " DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length' "
>
> There is not duplicate header.
>
> 2. The ACK messages not find dialog parameters.
>
> Here is debug 6 :
>
> : DBG:core:parse_msg: SIP Request:
> : DBG:core:parse_msg: method: <ACK>
> : DBG:core:parse_msg: uri: <sip:15488 at 77.88.100.100:5060>
> : DBG:core:parse_msg: version: <SIP/2.0>
> : DBG:core:parse_headers: flags=2
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bK1af6.8dfa1be2.2>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=2
> : DBG:core:parse_headers: this is the first via
> : DBG:core:receive_msg: After parse_msg...
> : DBG:core:receive_msg: preparing to run routing scripts...
> : DBG:sl:sl_filter_ACK: to late to be a local ACK!
> : ++++++++++++++++++++++++++++++++++++++++++++++++++++ from
> 11.22.33.44:5060
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_via_param: found param type 234, <received> =
> <66.55.44.33>; state=6
> : DBG:core:parse_via_param: found param type 235, <rport> = <52625>;
> state=6
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bKPj-BqsfN5zeuwvMDMyA9q93C5tBdFaeMZg>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=ffffffffffffffff
> : DBG:core:parse_headers: parse_headers: this is the second via
> : DBG:core:parse_to_param: tag=as25148399
> : DBG:core:parse_to: end of header reached, state=29
> : DBG:core:parse_to: display={}, ruri={sip:15488 at 11.22.33.44}
> : DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44]
> : DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44>]
> : DBG:core:get_hdr_field: cseq <CSeq>: <31391> <ACK>
> : DBG:core:get_hdr_field: content_length=0
> : DBG:core:get_hdr_field: found end of header
> : DBG:core:parse_to_param: tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj
> : DBG:core:parse_to: end of header reached, state=29
> : DBG:core:parse_to: display={}, ruri={sip:77 at 11.22.33.44}
> : DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length'
> : ASK from 11.22.33.44:5060
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:uri:has_totag: totag found
> : Have to_tag
> : DBG:core:parse_headers: flags=200
> : DBG:rr:is_preloaded: is_preloaded: No
> : DBG:core:grep_sock_info: checking if host==us: 14==9 && [77.88.100.100]
> == [127.0.0.1]
> : DBG:core:grep_sock_info: checking if port 5060 matches port 5060
> : DBG:core:grep_sock_info: checking if host==us: 14==14 &&
> [77.88.100.100] == [77.88.100.100]
> : DBG:core:grep_sock_info: checking if port 5060 matches port 5060
> : DBG:rr:after_strict: Next hop: 'sip:77.88.100.100;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645'
> is loose router
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:rr:after_strict: The last route URI: 'sip:77.88.100.100
> ;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645'
> : DBG:rr:run_rr_callbacks: callback id 1 entered with <>
> : DBG:dialog:dlg_onroute: Route param 'did' not found
> : DBG:rr:run_rr_callbacks: callback id 2 entered with <>
> : DBG:uac:restore_uri: getting 'vsf' Route param
> : DBG:uac:restore_uri: route param 'vsf' not found
> : DBG:uac:restore_uri: getting 'vst' Route param
> : DBG:uac:restore_uri: route param 'vst' not found
> : Sip Trace = <null>
> : DBG:siptrace:sip_trace: nothing to trace...
> : Has totag - loose route. Trace id <null>
> : DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=78
> : DBG:tm:t_lookup_request: start searching: hash=28577, isACK=1
> : DBG:core:parse_headers: flags=38
> : DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f619a9e92f8] after is 1
> : DBG:tm:t_lookup_request: e2e proxy ACK found
> : DBG:tm:t_newtran: building branch for end2end ACK - flags=1
> : DBG:tm:t_relay_to: forwarding ACK
> : DBG:core:mk_proxy: doing DNS lookup...
> : DBG:core:forward_request: sending:#012ACK sip:77.88.100.100;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645
> SIP/2.0#015#012Via: SIP/2.0/UDP 77.88.100.100;branch=z9hG4bK1af6.7d6364b3.2#015#012Via:
> SIP/2.0/UDP
> 11.22.33.44;rport=5060;received=11.22.33.44;branch=z9hG4bK1af6.8dfa1be2.2#015#012Via:
> SIP/2.0/UDP 66.55.44.33:52625;received=66.55.44.33;rport=52625;branch=z9hG4bKPj-BqsfN5zeuwvMDMyA9q93C5tBdFaeMZg#015#012Max-Forwards:
> 67#015#012From: <sip:77 at 11.22.33.44>;tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj#015#012To:
> <sip:15488 at 11.22.33.44>;tag=as25148399#015#012Call-ID:
> BFq2DLQKfpwA1bgpaaKLDeZJsLgtbDBA#015#012CSeq: 31391
> ACK#015#012Content-Length: 0#015#012#015#012.
> : DBG:core:forward_request: orig. len=517, new_len=572, proto=1
> : DBG:core:run_fwd_callbacks: FWD callback entered
> : DBG:siptrace:trace_msg_out: trace off...
> : Send relay.
> : DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f619a9e92f8] after is 0
> : DBG:core:destroy_avp_list: destroying list 0x7f619a9f3258
> : DBG:core:receive_msg: cleaning up
> : DBG:core:parse_msg: SIP Request:
> : DBG:core:parse_msg: method: <ACK>
> : DBG:core:parse_msg: uri: <sip:77.88.100.100
> ;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645>
> : DBG:core:parse_msg: version: <SIP/2.0>
> : DBG:core:parse_headers: flags=2
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bK1af6.7d6364b3.2>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=2
> : DBG:core:parse_headers: this is the first via
> : DBG:core:receive_msg: After parse_msg...
> : DBG:core:receive_msg: preparing to run routing scripts...
> : DBG:sl:sl_filter_ACK: to late to be a local ACK!
> : ++++++++++++++++++++++++++++++++++++++++++++++++++++ from
> 77.88.100.100:5060
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_via_param: found param type 235, <rport> = <5060>;
> state=6
> : DBG:core:parse_via_param: found param type 234, <received> =
> <11.22.33.44>; state=6
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bK1af6.8dfa1be2.2>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=ffffffffffffffff
> : DBG:core:parse_headers: parse_headers: this is the second via
> : DBG:core:parse_via_param: found param type 234, <received> =
> <66.55.44.33>; state=6
> : DBG:core:parse_via_param: found param type 235, <rport> = <52625>;
> state=6
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bKPj-BqsfN5zeuwvMDMyA9q93C5tBdFaeMZg>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=ffffffffffffffff
> : DBG:core:parse_to_param: tag=as25148399
> : DBG:core:parse_to: end of header reached, state=29
> : DBG:core:parse_to: display={}, ruri={sip:15488 at 11.22.33.44}
> : DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44]
> : DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44>]
> : DBG:core:get_hdr_field: cseq <CSeq>: <31391> <ACK>
> : DBG:core:get_hdr_field: content_length=0
> : DBG:core:get_hdr_field: found end of header
> : DBG:core:parse_to_param: tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj
> : DBG:core:parse_to: end of header reached, state=29
> : DBG:core:parse_to: display={}, ruri={sip:77 at 11.22.33.44}
> : DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length'
> : ASK from 77.88.100.100:5060
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:uri:has_totag: totag found
> : Have to_tag
> : DBG:core:parse_headers: flags=200
> : DBG:rr:find_first_route: No Route headers found
> : DBG:rr:loose_route: There is no Route HF
> : ASK when not loose_route.
> : DBG:core:parse_headers: flags=78
> : DBG:tm:t_lookup_request: start searching: hash=28577, isACK=1
> : DBG:core:parse_headers: flags=38
> : DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f619a9e92f8] after is 1
> : DBG:tm:t_lookup_request: e2e proxy ACK found
> : t_check_trans (YES).
> : DBG:tm:t_newtran: transaction on entrance=(nil)
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:tm:t_newtran: building branch for end2end ACK - flags=1
> : DBG:tm:t_relay_to: forwarding ACK
> : DBG:core:mk_proxy: doing DNS lookup...
> : DBG:core:forward_request: sending:#012ACK sip:77.88.100.100;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645
> SIP/2.0#015#012Via: SIP/2.0/UDP 77.88.100.100;branch=z9hG4bK1af6.7d6364b3.2#015#012Via:
> SIP/2.0/UDP 77.88.100.100;rport=5060;received=77.88.100.100;branch=z9hG4bK1af6.7d6364b3.2#015#012Via:
> SIP/2.0/UDP
> 11.22.33.44;rport=5060;received=11.22.33.44;branch=z9hG4bK1af6.8dfa1be2.2#015#012Via:
> SIP/2.0/UDP 66.55.44.33:52625;received=66.55.44.33;rport=52625;branch=z9hG4bKPj-BqsfN5zeuwvMDMyA9q93C5tBdFaeMZg#015#012Max-Forwards:
> 65#015#012From: <sip:77 at 11.22.33.44>;tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj#015#012To:
> <sip:15488 at 11.22.33.44>;tag=as25148399#015#012Call-ID:
> BFq2DLQKfpwA1bgpaaKLDeZJsLgtbDBA#015#012CSeq: 31391
> ACK#015#012Content-Length: 0#015#012#015#012.
> : DBG:core:forward_request: orig. len=572, new_len=670, proto=1
> : DBG:core:run_fwd_callbacks: FWD callback entered
> : DBG:siptrace:trace_msg_out: trace off...
> : Send relay.
> : DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f619a9e92f8] after is 0
> : DBG:core:destroy_avp_list: destroying list 0x7f619a9f3258
> : DBG:core:receive_msg: cleaning up
> : DBG:core:parse_msg: SIP Request:
> : DBG:core:parse_msg: method: <ACK>
> : DBG:core:parse_msg: uri: <sip:77.88.100.100
> ;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645>
> : DBG:core:parse_msg: version: <SIP/2.0>
> : DBG:core:parse_headers: flags=2
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bK1af6.7d6364b3.2>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=2
> : DBG:core:parse_headers: this is the first via
> : DBG:core:receive_msg: After parse_msg...
> : DBG:core:receive_msg: preparing to run routing scripts...
> : DBG:sl:sl_filter_ACK: to late to be a local ACK!
> : ++++++++++++++++++++++++++++++++++++++++++++++++++++ from
> 77.88.100.100:5060
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_via_param: found param type 235, <rport> = <5060>;
> state=6
> : DBG:core:parse_via_param: found param type 234, <received> = <
> 77.88.100.100>; state=6
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bK1af6.7d6364b3.2>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=ffffffffffffffff
> : DBG:core:parse_headers: parse_headers: this is the second via
> : DBG:core:parse_via_param: found param type 235, <rport> = <5060>;
> state=6
> : DBG:core:parse_via_param: found param type 234, <received> =
> <11.22.33.44>; state=6
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bK1af6.8dfa1be2.2>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=ffffffffffffffff
> : DBG:core:parse_via_param: found param type 234, <received> =
> <66.55.44.33>; state=6
> : DBG:core:parse_via_param: found param type 235, <rport> = <52625>;
> state=6
> : DBG:core:parse_via_param: found param type 232, <branch> =
> <z9hG4bKPj-BqsfN5zeuwvMDMyA9q93C5tBdFaeMZg>; state=16
> : DBG:core:parse_via: end of header reached, state=5
> : DBG:core:parse_headers: via found, flags=ffffffffffffffff
> : DBG:core:parse_to_param: tag=as25148399
> : DBG:core:parse_to: end of header reached, state=29
> : DBG:core:parse_to: display={}, ruri={sip:15488 at 11.22.33.44}
> : DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44]
> : DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44>]
> : DBG:core:get_hdr_field: cseq <CSeq>: <31391> <ACK>
> : DBG:core:get_hdr_field: content_length=0
> : DBG:core:get_hdr_field: found end of header
> : DBG:core:parse_to_param: tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj
> : DBG:core:parse_to: end of header reached, state=29
> : DBG:core:parse_to: display={}, ruri={sip:77 at 11.22.33.44}
> : DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length'
> : ASK from 77.88.100.100:5060
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:uri:has_totag: totag found
> : Have to_tag
> : DBG:core:parse_headers: flags=200
> : DBG:rr:find_first_route: No Route headers found
> : DBG:rr:loose_route: There is no Route HF
> : ASK when not loose_route.
> : DBG:core:parse_headers: flags=78
> : DBG:tm:t_lookup_request: start searching: hash=28577, isACK=1
> : DBG:core:parse_headers: flags=38
> : DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f619a9e92f8] after is 1
> : DBG:tm:t_lookup_request: e2e proxy ACK found
> : t_check_trans (YES).
> : DBG:tm:t_newtran: transaction on entrance=(nil)
> : DBG:core:parse_headers: flags=ffffffffffffffff
> : DBG:tm:t_newtran: building branch for end2end ACK - flags=1
> : DBG:tm:t_relay_to: forwarding ACK
> : DBG:core:mk_proxy: doing DNS lookup...
> : DBG:core:forward_request: sending:#012ACK sip:77.88.100.100;lr;ftag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj;did=706.c142d645
> SIP/2.0#015#012Via: SIP/2.0/UDP 77.88.100.100;branch=z9hG4bK1af6.7d6364b3.2#015#012Via:
> SIP/2.0/UDP 77.88.100.100;rport=5060;received=77.88.100.100;branch=z9hG4bK1af6.7d6364b3.2#015#012Via:
> SIP/2.0/UDP 77.88.100.100;rport=5060;received=77.88.100.100;branch=z9hG4bK1af6.7d6364b3.2#015#012Via:
> SIP/2.0/UDP
> 11.22.33.44;rport=5060;received=11.22.33.44;branch=z9hG4bK1af6.8dfa1be2.2#015#012Via:
> SIP/2.0/UDP 66.55.44.33:52625;received=66.55.44.33;rport=52625;branch=z9hG4bKPj-BqsfN5zeuwvMDMyA9q93C5tBdFaeMZg#015#012Max-Forwards:
> 63#015#012From: <sip:77 at 11.22.33.44>;tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj#015#012To:
> <sip:15488 at 11.22.33.44>;tag=as25148399#015#012Call-ID:
> BFq2DLQKfpwA1bgpaaKLDeZJsLgtbDBA#015#012CSeq: 31391
> ACK#015#012Content-Length: 0#015#012#015#012.
> : DBG:core:forward_request: orig. len=670, new_len=768, proto=1
> : DBG:core:run_fwd_callbacks: FWD callback entered
> : DBG:siptrace:trace_msg_out: trace off...
> : Send relay.
> : DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f619a9e92f8] after is 0
> : DBG:core:destroy_avp_list: destroying list 0x7f619a9f3258
> Best regards;
> PlayMen
>
>
> _______________________________________________
> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20120420/640d4f10/attachment-0001.htm>
More information about the Users
mailing list