Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Strange problem of changing SIP ACK CSeq #3206

Closed
denyspozniak opened this issue Sep 25, 2023 · 2 comments
Closed

[BUG] Strange problem of changing SIP ACK CSeq #3206

denyspozniak opened this issue Sep 25, 2023 · 2 comments

Comments

@denyspozniak
Copy link

OpenSIPS version you are running

# opensips -V
version: opensips 3.4.1 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, HP_MALLOC, DBG_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: c03bbc4f6
main.c compiled on 12:30:20 Sep 22 2023 with gcc 8

Describe the bug

When relaying a SIP ACK message, the Cseq suddenly changes (in the example below from 12 to 1).
1.1.1.49:5060 - Incoming public OpenSIPS interface
1.1.1.227:5060 - Outgoing public OpenSIPS interface

-- incoming --
2023/09/25 15:56:04.506202 1.1.1.140:5065 -> 1.1.1.49:5060
ACK sip:10.60.88.92:5080;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.25.101.67:5065;branch=z9hG4bK00ccf2f1185aee11868be2dc2b18db6f;rport
Route: <sip:1.1.1.49;r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01>
Route: <sip:1.1.1.227;r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01>
Route: <sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6>
Route: <sip:10.60.88.91;r2=on;lr=on;did=6bf1.9e6>
Route: <sip:10.60.88.59;lr=on;did=6bf1.3d53>
From: <sip:sipuser@10.60.88.92>;tag=80190ce3185aee118688e2dc2b18db6f
To: "DP" <sip:997@1.1.1.72>;tag=41295D55-6511915B0004839F-DB5F5700
Call-ID: 0d07d279-d64e-123c-c1ad-566ffb000052_sipuser
CSeq: 12 ACK
Contact: <sip:sipuser@1.1.1.140:5065;gr=00A6598E-FA59-EE11-8652-E2DC2B18DB6F>
Proxy-Authorization: <truncated>
Max-Forwards: 70
Content-Length: 0

-- outgoing --
2023/09/25 15:56:04.507531 1.1.1.227:5060 -> 1.1.1.72:5060
ACK sip:10.60.88.92:5080;transport=udp SIP/2.0
Via: SIP/2.0/UDP 1.1.1.227:5060;branch=z9hG4bK3d69.8dd4b19de728726f9b2f686fceac0d19.0
Via: SIP/2.0/UDP 10.25.101.67:5065;received=1.1.1.140;branch=z9hG4bK00ccf2f1185aee11868be2dc2b18db6f;rport=5065
Route: <sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6>
Route: <sip:10.60.88.91;r2=on;lr=on;did=6bf1.9e6>
Route: <sip:10.60.88.59;lr=on;did=6bf1.3d53>
From: <sip:sipuser@10.60.88.92>;tag=80190ce3185aee118688e2dc2b18db6f
To: "DP" <sip:997@1.1.1.72>;tag=41295D55-6511915B0004839F-DB5F5700
Call-ID: 0d07d279-d64e-123c-c1ad-566ffb000052_sipuser
CSeq: 1 ACK
Contact: <sip:sipuser@1.1.1.140:5065;gr=00A6598E-FA59-EE11-8652-E2DC2B18DB6F>
Proxy-Authorization: <truncated>
Max-Forwards: 69
X-PP-IP: 1.1.1.49:5060;transport=udp
X-PP-Received: 1.1.1.140:5065;transport=udp
X-PP-GWH: FROM_INTERNET
X-PP-FIX_NAT: yes
X-PP-iGWH: FROM_CORE_DC1
X-PP-SRC-DU: sip:1.1.1.72:5060;transport=udp
X-PP-DST-DU: sip:1.1.1.140:5065
X-PP-DU: sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6
Content-Length: 0

Relevant System Logs

OS/environment information

  • Operating System:
# cat /etc/redhat-release
Rocky Linux release 8.8 (Green Obsidian)
  • OpenSIPS installation:

This setup uses a clusterer module with a anycast interface 1.1.1.49:5060, in this example INVITE-OK transaction is processed on one node, 
and the corresponding ACK on another, from the point of view of routing everything is processed correctly,
the only problem is changing the Cseq value.  
In a private message I can send full traces and logs if this helps clarify the essence of the problem.
  • OpenSIPS debug log:
Sep 25 15:56:05 [1326835] DBG:core:parse_msg: SIP Request:
Sep 25 15:56:05 [1326835] DBG:core:parse_msg:  method:  <ACK>
Sep 25 15:56:05 [1326835] DBG:core:parse_msg:  uri:     <sip:10.60.88.92:5080;transport=udp>
Sep 25 15:56:05 [1326835] DBG:core:parse_msg:  version: <SIP/2.0>
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK00ccf2f1185aee11868be2dc2b18db6f>; state=6
Sep 25 15:56:05 [1326835] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Sep 25 15:56:05 [1326835] DBG:core:parse_via: end of header reached, state=5
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: via found, flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: this is the first via
Sep 25 15:56:05 [1326835] DBG:core:parse_to_param: tag=41295D55-6511915B0004839F-DB5F5700
Sep 25 15:56:05 [1326835] DBG:core:parse_to_param: end of header reached, state=13
Sep 25 15:56:05 [1326835] DBG:core:_parse_to: end of header reached, state=29
Sep 25 15:56:05 [1326835] DBG:core:_parse_to: display={"DP"}, ruri={sip:997@1.1.1.72}
Sep 25 15:56:05 [1326835] DBG:core:get_hdr_field: <To> [74]; uri=[sip:997@1.1.1.72]
Sep 25 15:56:05 [1326835] DBG:core:get_hdr_field: to body ["DP" <sip:997@1.1.1.72>]
Sep 25 15:56:05 [1326835] DBG:core:get_hdr_field: cseq <CSeq>: <12> <ACK>
Sep 25 15:56:05 [1326835] DBG:core:get_hdr_field: content_length=0
Sep 25 15:56:05 [1326835] DBG:core:get_hdr_field: found end of header
Sep 25 15:56:05 [1326835] DBG:core:receive_msg: After parse_msg...
Sep 25 15:56:05 [1326835] DBG:core:receive_msg: preparing to run routing scripts...
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:b2b_entities:b2b_prescript_f: start - method = ACK
Sep 25 15:56:05 [1326835] DBG:b2b_entities:b2b_prescript_f: Found route headers
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 13==9 &&  [1.1.1.49] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 13==13 &&  [1.1.1.49] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==9 &&  [1.1.1.227] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==13 &&  [1.1.1.227] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==14 &&  [1.1.1.227] == [1.1.1.227]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:b2b_entities:b2b_prescript_f: More than 2 route hdr -> not for me
Sep 25 15:56:05 [1326835] DBG:tracer:trace_w: tracing transaction!
Sep 25 15:56:05 [1326835] DBG:core:parse_to_param: tag=80190ce3185aee118688e2dc2b18db6f
Sep 25 15:56:05 [1326835] DBG:core:parse_to_param: end of header reached, state=11
Sep 25 15:56:05 [1326835] DBG:core:_parse_to: end of header reached, state=29
Sep 25 15:56:05 [1326835] DBG:core:_parse_to: display={}, ruri={sip:sipuser@10.60.88.92}
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=40
Sep 25 15:56:05 [1326835] DBG:tracer:sip_trace_instance: sip_trace called
Sep 25 15:56:05 [1326835] DBG:tracer:is_id_traced: trace=on dyn=off
Sep 25 15:56:05 [1326835] DBG:tracer:pipport2su: proto 17, host 1.1.1.140 , port 5065
Sep 25 15:56:05 [1326835] DBG:tracer:pipport2su: proto 17, host 1.1.1.49 , port 5060
Sep 25 15:56:05 [1326835] DBG:proto_hep:add_hep_chunk: Chunk with (id=17; vendor=0) not found! Creating!
Sep 25 15:56:05 [1326835] DBG:proto_hep:add_hep_chunk: Hep chunk with (id=17; vendor=0) successfully built!
Sep 25 15:56:05 [1326835] DBG:core:mk_proxy: doing DNS lookup...
Sep 25 15:56:05 [1326835] DBG:maxfwd:is_maxfwd_present: value = 70
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=8000000
Sep 25 15:56:05 [1326835] DBG:core:pv_get_useragent: no User-Agent header
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:core:comp_scriptvar: str 29: FROM_INTERNET
Sep 25 15:56:05 [1326835] DBG:regex:w_pcre_match: 'sipuser' matches '^([0-9]{8})$'
Sep 25 15:56:05 [1326835] DBG:core:comp_scriptvar: str 20: FROM_INTERNET
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 6==9 &&  [public] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 6==13 &&  [public] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 6==14 &&  [public] == [1.1.1.227]
Sep 25 15:56:05 [1326835] DBG:core:comp_scriptvar: str 29: FROM_INTERNET
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:sipmsgops:is_present_hf: header ''(10) not found
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:sipmsgops:has_totag: totag found
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=200
Sep 25 15:56:05 [1326835] DBG:rr:is_preloaded: No
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 11==9 &&  [10.60.88.92] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5080
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 11==13 &&  [10.60.88.92] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5080
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 11==14 &&  [10.60.88.92] == [1.1.1.227]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5080
Sep 25 15:56:05 [1326835] DBG:core:check_self: host != me
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 13==9 &&  [1.1.1.49] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 13==13 &&  [1.1.1.49] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:rr:after_loose: Topmost route URI: 'sip:1.1.1.49;r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01' is me
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==9 &&  [1.1.1.227] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==13 &&  [1.1.1.227] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==14 &&  [1.1.1.227] == [1.1.1.227]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:rr:after_loose: URI to be processed: 'sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6'
Sep 25 15:56:05 [1326835] DBG:rr:after_loose: Next URI is a loose router
Sep 25 15:56:05 [1326835] DBG:rr:run_rr_callbacks: callback id 0 entered with <r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01>
Sep 25 15:56:05 [1326835] DBG:core:parse_params: Parsing params for:[r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01]
Sep 25 15:56:05 [1326835] DBG:path:path_rr_callback: extracted received=, transport=
Sep 25 15:56:05 [1326835] DBG:rr:run_rr_callbacks: callback id 1 entered with <r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01>
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_onroute: route param is '6bf.b4d61b01' (len=12)
Sep 25 15:56:05 [1326835] DBG:dialog:lookup_dlg: dialog id=280063307 found on entry 4022
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=58
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_onroute: match_dialog => dst_leg=[0]
Sep 25 15:56:05 [1326835] DBG:dialog:next_state_dlg: dialog 0x7f6ce7593240 changed from state 4 to state 4, due event 6
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=0)
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_onroute: dialog_timeout: 43177
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_onroute: dlg_leg_get_cseq(dlg, [0], req)
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_leg_get_cseq: no cseq found in map for leg [0]
Sep 25 15:56:05 [1326835] DBG:dialog:dlg_onroute: dlg->legs[0].last_gen_cseq=[1]
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=20
Sep 25 15:56:05 [1326835] DBG:dialog:update_msg_cseq: null str provided. Using only int value for cseq
Sep 25 15:56:05 [1326835] DBG:dialog:update_msg_cseq: Message CSEQ translated from [12] to [1]
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=78
Sep 25 15:56:05 [1326835] DBG:tm:t_lookup_request: start searching: hash=38611, isACK=1
Sep 25 15:56:05 [1326835] DBG:tm:matching_3261: RFC3261 transaction matching failed
Sep 25 15:56:05 [1326835] DBG:tm:t_lookup_request: no transaction found
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=200
Sep 25 15:56:05 [1326835] DBG:rr:is_preloaded: No
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 11==9 &&  [10.60.88.92] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5080
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 11==13 &&  [10.60.88.92] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5080
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 11==14 &&  [10.60.88.92] == [1.1.1.227]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5080
Sep 25 15:56:05 [1326835] DBG:core:check_self: host != me
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 13==9 &&  [1.1.1.49] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 13==13 &&  [1.1.1.49] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:rr:after_loose: Topmost route URI: 'sip:1.1.1.49;r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01' is me
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==9 &&  [1.1.1.227] == [127.0.0.1]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==13 &&  [1.1.1.227] == [1.1.1.49]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if host==us: 14==14 &&  [1.1.1.227] == [1.1.1.227]
Sep 25 15:56:05 [1326835] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Sep 25 15:56:05 [1326835] DBG:rr:after_loose: URI to be processed: 'sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6'
Sep 25 15:56:05 [1326835] DBG:rr:after_loose: Next URI is a loose router
Sep 25 15:56:05 [1326835] DBG:rr:run_rr_callbacks: callback id 0 entered with <r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01>
Sep 25 15:56:05 [1326835] DBG:core:parse_params: Parsing params for:[r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01]
Sep 25 15:56:05 [1326835] DBG:path:path_rr_callback: extracted received=, transport=
Sep 25 15:56:05 [1326835] DBG:rr:run_rr_callbacks: callback id 1 entered with <r2=on;lr;ftag=41295D55-6511915B0004839F-DB5F5700;did=6bf.b4d61b01>
Sep 25 15:56:05 [1326835] DBG:dialog:fetch_dlg_value: looking for <guess_who>
Sep 25 15:56:05 [1326835] DBG:dialog:fetch_dlg_value: var found-> <FROM_CORE_DC1>!
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:dialog:fetch_dlg_value: looking for <request_src_du>
Sep 25 15:56:05 [1326835] DBG:dialog:fetch_dlg_value: var found-> <sip:1.1.1.72:5060;transport=udp>!
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:dialog:fetch_dlg_value: looking for <request_dst_du>
Sep 25 15:56:05 [1326835] DBG:dialog:fetch_dlg_value: var found-> <sip:1.1.1.140:5065>!
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:core:dup_ref_script_route_in_shm: dupping 0x7f6d07077550 [REPLY_FROM_EDGE], idx 2, ver/cnt 2, to new 0x7f6ce758b7f0 [REPLY_FROM_EDGE], idx 2, ver/cnt 1
Sep 25 15:56:05 [1326835] DBG:tm:t_newtran: transaction on entrance=(nil)
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:tm:t_relay_to: forwarding ACK
Sep 25 15:56:05 [1326835] DBG:core:mk_proxy: doing DNS lookup...
Sep 25 15:56:05 [1326835] DBG:core:MD5StringArray: MD5 calculated: 8dd4b19de728726f9b2f686fceac0d19
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=60
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 25 15:56:05 [1326835] DBG:core:forward_request: sending:
 ACK sip:10.60.88.92:5080;transport=udp SIP/2.0
 Via: SIP/2.0/UDP 1.1.1.227:5060;branch=z9hG4bK3d69.8dd4b19de728726f9b2f686fceac0d19.0
 Via: SIP/2.0/UDP 10.25.101.67:5065;received=1.1.1.140;branch=z9hG4bK00ccf2f1185aee11868be2dc2b18db6f;rport=5065
 Route: <sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6>
 Route: <sip:10.60.88.91;r2=on;lr=on;did=6bf1.9e6>
 Route: <sip:10.60.88.59;lr=on;did=6bf1.3d53>
 From: <sip:sipuser@10.60.88.92>;tag=80190ce3185aee118688e2dc2b18db6f
 To: "DP" <sip:997@1.1.1.72>;tag=41295D55-6511915B0004839F-DB5F5700
 Call-ID: 0d07d279-d64e-123c-c1ad-566ffb000052_sipuser
 CSeq: 1 ACK
 Contact: <sip:sipuser@1.1.1.140:5065;gr=00A6598E-FA59-EE11-8652-E2DC2B18DB6F>
 Proxy-Authorization: Digest <truncated>
 Max-Forwards: 69
 X-PP-IP: 1.1.1.49:5060;transport=udp
 X-PP-Received: 1.1.1.140:5065;transport=udp
 X-PP-GWH: FROM_INTERNET
 X-PP-FIX_NAT: yes
 X-PP-iGWH: FROM_CORE_DC1
 X-PP-SRC-DU: sip:1.1.1.72:5060;transport=udp
 X-PP-DST-DU: sip:1.1.1.140:5065
 X-PP-DU: sip:1.1.1.72;r2=on;lr=on;did=6bf1.9e6
 Content-Length: 0
 [1B blob data]
 .
Sep 25 15:56:05 [1326835] DBG:core:forward_request: orig. len=1051, new_len=1291, proto=1
Sep 25 15:56:05 [1326835] DBG:core:parse_headers: flags=40
Sep 25 15:56:05 [1326835] DBG:tracer:trace_msg_out: trace msg out
Sep 25 15:56:05 [1326835] DBG:tracer:is_id_traced: trace=on dyn=off
Sep 25 15:56:05 [1326835] DBG:tracer:pipport2su: proto 17, host 1.1.1.227 , port 5060
Sep 25 15:56:05 [1326835] DBG:tracer:pipport2su: proto 17, host 1.1.1.72 , port 5060
Sep 25 15:56:05 [1326835] DBG:proto_hep:add_hep_chunk: Chunk with (id=17; vendor=0) not found! Creating!
Sep 25 15:56:05 [1326835] DBG:proto_hep:add_hep_chunk: Hep chunk with (id=17; vendor=0) successfully built!
@denyspozniak
Copy link
Author

denyspozniak commented Sep 25, 2023 •
edited
Loading

I disabled the dialog module and the issue was resolved, maybe it connected to this commit?
a76af3f

In my case, it is reproduced when the person answering the call puts it on hold

@razvancrainea
Copy link
Member

@denyspozniak can you please share a full pcap? If you cannot share it publicly, perhaps you can send it to my email.

razvancrainea added a commit that referenced this issue Sep 26, 2023
@razvancrainea
dialog: increment last_gen_cseq only if initialized
d4aead2 
Many thanks to Denys Pozniak (@denyspozniak on GitHub) for reporting and
providing troubleshooting information.

Close #3206

(cherry picked from commit 7bafee1)
razvancrainea added a commit that referenced this issue Sep 26, 2023
@razvancrainea
dialog: increment last_gen_cseq only if initialized
79bbdb7 
Many thanks to Denys Pozniak (@denyspozniak on GitHub) for reporting and
providing troubleshooting information.

Close #3206

(cherry picked from commit 7bafee1)
razvancrainea added a commit that referenced this issue Sep 26, 2023
@razvancrainea
dialog: increment last_gen_cseq only if initialized
588af72 
Many thanks to Denys Pozniak (@denyspozniak on GitHub) for reporting and
providing troubleshooting information.

Close #3206

(cherry picked from commit 7bafee1)
sobomax pushed a commit to sippy/opensips that referenced this issue Dec 3, 2023
@razvancrainea @sobomax
dialog: increment last_gen_cseq only if initialized
8ae6ed7 
Many thanks to Denys Pozniak (@denyspozniak on GitHub) for reporting and
providing troubleshooting information.

Close OpenSIPS#3206
@denyspozniak denyspozniak mentioned this issue Feb 21, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@razvancrainea @denyspozniak