[OpenSIPS-Users] Wrong ACK

Vlad Paiu vladpaiu at opensips.org
Fri Apr 20 11:15:40 CEST 2012


Hi,

Please post the SIP trace as well, for the entire dialog.

Regards,

Vlad Paiu
OpenSIPS Developer
http://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 
> <http://sip:15488@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 <http://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 
> <mailto:sip%3A15488 at 11.22.33.44>}
>  : DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 at 11.22.33.44>]
>  : DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 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 
> <mailto:sip%3A77 at 11.22.33.44>}
>  : DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length'
>  : ASK from 11.22.33.44:5060 <http://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 
> <mailto:sip%3A77 at 11.22.33.44>>;tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj#015#012To: 
> <sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 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 <http://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 
> <mailto:sip%3A15488 at 11.22.33.44>}
>  : DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 at 11.22.33.44>]
>  : DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 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 
> <mailto:sip%3A77 at 11.22.33.44>}
>  : DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length'
>  : ASK from 77.88.100.100:5060 <http://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 
> <mailto:sip%3A77 at 11.22.33.44>>;tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj#015#012To: 
> <sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 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 <http://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 
> <mailto:sip%3A15488 at 11.22.33.44>}
>  : DBG:core:get_hdr_field: <To> [40]; uri=[sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 at 11.22.33.44>]
>  : DBG:core:get_hdr_field: to body [<sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 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 
> <mailto:sip%3A77 at 11.22.33.44>}
>  : DBG:sipmsgops:sip_validate_hdrs: duplicate header 'Content-Length'
>  : ASK from 77.88.100.100:5060 <http://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 
> <mailto:sip%3A77 at 11.22.33.44>>;tag=9XfR8ZmrUUho2HYFHzJ3tYmiMp2GbOXj#015#012To: 
> <sip:15488 at 11.22.33.44 
> <mailto:sip%3A15488 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 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/8085699d/attachment-0001.htm>


More information about the Users mailing list