<div dir="ltr">Bogdan, I've added extra debug, the output around stuckage looks like the below. As for getting PCAP capture that is not easy to arrange as TravisCI does not give us direct access to the network capture. However, bot A and B log whatever is being sent/received, so it should not be that difficult to correlate. You can find the full log here:<div><br></div><div><span style="color:rgb(163,170,174);font-family:proxima-nova,"Helvetica Neue",Helvetica,Arial,sans-serif;font-size:15.6px"><a href="http://bit.ly/2vgtcu2">http://bit.ly/2vgtcu2</a></span><br><div><br></div><div>Let me know if it helps to narrow it down or if you need more information. I might try to reproduce it locally here.</div><div><br></div><div>-Max</div><div><br></div><div><div>Jul 28 22:18:39 [21433] DBG:core:receive_msg: cleaning up</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_msg: SIP Request:</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_msg:  method:  <CANCEL></div><div>Jul 28 22:18:39 [21433] DBG:core:parse_msg:  uri:     <sip:bob_early_cancel@[::1]:5060></div><div>Jul 28 22:18:39 [21433] DBG:core:parse_msg:  version: <SIP/2.0></div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=2</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5aad8c9774f140be692c3025b6a86417>; state=16</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_via: end of header reached, state=5</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: via found, flags=2</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: this is the first via</div><div>Jul 28 22:18:39 [21433] DBG:core:receive_msg: After parse_msg...</div><div>Jul 28 22:18:39 [21433] DBG:core:receive_msg: preparing to run routing scripts...</div><div>Jul 28 22:18:39 [21433] OpenSIPS received a request CANCEL from 0:0:0:0:0:0:0:1</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=100</div><div>Jul 28 22:18:39 [21433] DBG:maxfwd:is_maxfwd_present: value = 70 </div><div>Jul 28 22:18:39 [21433] DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=ffffffffffffffff</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_to: end of header reached, state=10</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_to: display={}, ruri={sip:bob_early_cancel@[::1]}</div><div>Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: <To> [30]; uri=[sip:bob_early_cancel@[::1]] </div><div>Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: to body [<sip:bob_early_cancel@[::1]>]</div><div>Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: cseq <CSeq>: <200> <CANCEL></div><div>Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: content_length=0</div><div>Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: found end of header</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=78</div><div>Jul 28 22:18:39 [21433] DBG:tm:t_lookup_request: start searching: hash=18081, isACK=0</div><div>Jul 28 22:18:39 [21433] DBG:tm:matching_3261: RFC3261 transaction matching failed</div><div>Jul 28 22:18:39 [21433] DBG:tm:t_lookup_request: no transaction found</div><div>Jul 28 22:18:39 [21433] DBG:tm:run_reqin_callbacks: trans=0x7f63d409bc20, callback type 1, id 0 entered</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_to_param: tag=211ce361902b0d1ce3ec04a495688cf6</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_to: end of header reached, state=29</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_to: display={"Alice Smith"}, ruri={sip:alice_early_cancel_ipv6@[::1]}</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=200</div><div>Jul 28 22:18:39 [21433] DBG:rr:find_first_route: No Route headers found</div><div>Jul 28 22:18:39 [21433] DBG:rr:loose_route: There is no Route HF</div><div>Jul 28 22:18:39 [21433] DBG:tm:update_cloned_msg_from_msg: new_uri must be copied old=0, new=31</div><div>Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: searching on hash entry 18081</div><div>Jul 28 22:18:39 [21433] DBG:tm:matching_3261: RFC3261 transaction matched, tid=5aad8c9774f140be692c3025b6a86417</div><div>Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: canceled transaction found (0x7f63d4022f18)! </div><div>Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: REF_UNSAFE:[0x7f63d4022f18] after is 1</div><div>Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: t_lookupOriginalT completed</div><div>Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=ffffffffffffffff</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d401f050 next=0x7f63d4023138, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4023138 next=0x7f63d40272a8, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40272a8 next=0x7f63d402e838, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d402e838 next=0x7f63d402b398, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d402b398 next=0x7f63d40335e8, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40335e8 next=0x7f63d4037690, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4037690 next=0x7f63d403b788, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d403b788 next=0x7f63d403f870, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d403f870 next=0x7f63d40439d8, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40439d8 next=0x7f63d4047b40, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4047b40 next=0x7f63d404bca0, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d404bca0 next=0x7f63d404fe20, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d404fe20 next=0x7f63d4053f70, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4053f70 next=0x7f63d40573c0, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40573c0 next=0x7f63d405c180, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d405c180 next=0x7f63d4060278, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4060278 next=0x7f63d4064310, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4064310 next=0x7f63d4068408, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4068408 next=0x7f63d406c548, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d406c548 next=0x7f63d40705e0, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40705e0 next=0x7f63d40746d0, timeout=1700000</div><div>Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40746d0 next=0x7f63d4078770, timeout=1700000</div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d40744b0, INVITE si ... )</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d40746d0 (2700000)</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4078770 next=0x7f63d407c818, timeout=1700000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d4078550, INVITE si ... )</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4078770 (2700000)</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d407c818 next=0x7f63d4080908, timeout=1700000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d407c5f8, INVITE si ... )</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d407c818 (2700000)</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4080908 next=0x7f63d40849b8, timeout=1700000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d40806e8, INVITE si ... )</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4080908 (2700000)</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40849b8 next=0x7f63d4087be8, timeout=1700000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d4084798, INVITE si ... )</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d40849b8 (2700000)</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4087be8 next=(nil), timeout=1700000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d40879c8, INVITE si ... )</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4087be8 (2700000)</font></div><div><font color="#ff0000">Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div><font color="#ff0000">[...cycles of retransmits..]</font></div><div><font color="#ff0000">Jul 28 22:19:07 [21437] DBG:tm:set_timer: relative timeout is 4000000</font></div><div><font color="#ff0000">Jul 28 22:19:07 [21437] DBG:tm:insert_timer_unsafe: [7]: 0x7f63d4097d58 (32800000)</font></div><div><font color="#ff0000">Jul 28 22:19:07 [21437] DBG:tm:retransmission_handler: retransmission_handler : done</font></div><div>Jul 28 22:19:09 [21442] DBG:tm:timer_routine: timer routine:0,tl=0x7f63d4074700 next=0x7f63d40787a0, timeout=31</div><div>Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f63d40744b0)</div><div>Jul 28 22:19:09 [21442] DBG:tm:t_should_relay_response: T_code=100, new_code=408</div><div>Jul 28 22:19:09 [21442] DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800)</div><div>Jul 28 22:19:09 [21442] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=408, flags=1</div><div>Jul 28 22:19:09 [21442] DBG:tm:t_should_relay_response: trying DNS-based failover</div><div>Jul 28 22:19:09 [21442] DBG:core:parse_headers: flags=40</div><div>Jul 28 22:19:09 [21442] DBG:rtpproxy:unforce_rtpproxy: sent unforce command</div><div>Jul 28 22:19:09 [21442] DBG:tm:relay_reply: T_state=4, branch=0, save=0, relay=0, cancel_BM=0</div><div>Jul 28 22:19:09 [21442] DBG:core:parse_headers: flags=ffffffffffffffff</div><div>Jul 28 22:19:09 [21442] DBG:tm:set_timer: relative timeout is 500000</div><div>Jul 28 22:19:09 [21442] DBG:tm:insert_timer_unsafe: [4]: 0x7f63d40745f8 (32200000)</div><div>Jul 28 22:19:09 [21442] DBG:tm:insert_timer_unsafe: [0]: 0x7f63d4074628 (61)</div><div>Jul 28 22:19:09 [21442] DBG:tm:relay_reply: sent buf=0x7f63d5cfac98: SIP/2.0 4..., shmem=0x7f63d40776e0: SIP/2.0 4</div><div>Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: done</div><div>Jul 28 22:19:09 [21442] DBG:tm:timer_routine: timer routine:0,tl=0x7f63d40787a0 next=0x7f63d407c848, timeout=31</div><div>Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f63d4078550)</div></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Jul 28, 2017 at 2:54 AM, Bogdan-Andrei Iancu <span dir="ltr"><<a href="mailto:bogdan@opensips.org" target="_blank">bogdan@opensips.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi Maxim,,<br>
<br>
Is it possible to send me (off list) a pcap (in and out from OpenSIPS) and the log in log_level 4. I will try to investigate to see what is the actual problem.<br></blockquote></div>
</div></div>