[OpenSIPS-Devel] Can't get 2.3 running with voiptests properly

Maxim Sobolev sobomax at sippysoft.com
Mon Jul 31 17:15:06 EDT 2017


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:

http://bit.ly/2vgtcu2

Let me know if it helps to narrow it down or if you need more information.
I might try to reproduce it locally here.

-Max

Jul 28 22:18:39 [21433] DBG:core:receive_msg: cleaning up
Jul 28 22:18:39 [21433] DBG:core:parse_msg: SIP Request:
Jul 28 22:18:39 [21433] DBG:core:parse_msg:  method:  <CANCEL>
Jul 28 22:18:39 [21433] DBG:core:parse_msg:  uri:     <sip:bob_early_cancel@
[::1]:5060>
Jul 28 22:18:39 [21433] DBG:core:parse_msg:  version: <SIP/2.0>
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=2
Jul 28 22:18:39 [21433] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=6
Jul 28 22:18:39 [21433] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK5aad8c9774f140be692c3025b6a86417>; state=16
Jul 28 22:18:39 [21433] DBG:core:parse_via: end of header reached, state=5
Jul 28 22:18:39 [21433] DBG:core:parse_headers: via found, flags=2
Jul 28 22:18:39 [21433] DBG:core:parse_headers: this is the first via
Jul 28 22:18:39 [21433] DBG:core:receive_msg: After parse_msg...
Jul 28 22:18:39 [21433] DBG:core:receive_msg: preparing to run routing
scripts...
Jul 28 22:18:39 [21433] OpenSIPS received a request CANCEL from
0:0:0:0:0:0:0:1
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=100
Jul 28 22:18:39 [21433] DBG:maxfwd:is_maxfwd_present: value = 70
Jul 28 22:18:39 [21433] DBG:tm:t_newtran: transaction on
entrance=0xffffffffffffffff
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 28 22:18:39 [21433] DBG:core:parse_to: end of header reached, state=10
Jul 28 22:18:39 [21433] DBG:core:parse_to: display={},
ruri={sip:bob_early_cancel@[::1]}
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: <To> [30];
uri=[sip:bob_early_cancel@[::1]]
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: to body
[<sip:bob_early_cancel@[::1]>]
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: cseq <CSeq>: <200> <CANCEL>
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: content_length=0
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: found end of header
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=78
Jul 28 22:18:39 [21433] DBG:tm:t_lookup_request: start searching:
hash=18081, isACK=0
Jul 28 22:18:39 [21433] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Jul 28 22:18:39 [21433] DBG:tm:t_lookup_request: no transaction found
Jul 28 22:18:39 [21433] DBG:tm:run_reqin_callbacks: trans=0x7f63d409bc20,
callback type 1, id 0 entered
Jul 28 22:18:39 [21433] DBG:core:parse_to_param:
tag=211ce361902b0d1ce3ec04a495688cf6
Jul 28 22:18:39 [21433] DBG:core:parse_to: end of header reached, state=29
Jul 28 22:18:39 [21433] DBG:core:parse_to: display={"Alice Smith"},
ruri={sip:alice_early_cancel_ipv6@[::1]}
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=200
Jul 28 22:18:39 [21433] DBG:rr:find_first_route: No Route headers found
Jul 28 22:18:39 [21433] DBG:rr:loose_route: There is no Route HF
Jul 28 22:18:39 [21433] DBG:tm:update_cloned_msg_from_msg: new_uri must be
copied old=0, new=31
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: searching on hash entry
18081
Jul 28 22:18:39 [21433] DBG:tm:matching_3261: RFC3261 transaction matched,
tid=5aad8c9774f140be692c3025b6a86417
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: canceled transaction
found (0x7f63d4022f18)!
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT:
REF_UNSAFE:[0x7f63d4022f18] after is 1
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: t_lookupOriginalT
completed
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d401f050 next=0x7f63d4023138, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4023138 next=0x7f63d40272a8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40272a8 next=0x7f63d402e838, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d402e838 next=0x7f63d402b398, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d402b398 next=0x7f63d40335e8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40335e8 next=0x7f63d4037690, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4037690 next=0x7f63d403b788, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d403b788 next=0x7f63d403f870, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d403f870 next=0x7f63d40439d8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40439d8 next=0x7f63d4047b40, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4047b40 next=0x7f63d404bca0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d404bca0 next=0x7f63d404fe20, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d404fe20 next=0x7f63d4053f70, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4053f70 next=0x7f63d40573c0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40573c0 next=0x7f63d405c180, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d405c180 next=0x7f63d4060278, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4060278 next=0x7f63d4064310, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4064310 next=0x7f63d4068408, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4068408 next=0x7f63d406c548, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d406c548 next=0x7f63d40705e0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40705e0 next=0x7f63d40746d0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40746d0 next=0x7f63d4078770, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : request resending (t=0x7f63d40744b0, INVITE si ...
)
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d40746d0
(2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4078770 next=0x7f63d407c818, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : request resending (t=0x7f63d4078550, INVITE si ...
)
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4078770
(2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d407c818 next=0x7f63d4080908, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : request resending (t=0x7f63d407c5f8, INVITE si ...
)
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d407c818
(2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4080908 next=0x7f63d40849b8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : request resending (t=0x7f63d40806e8, INVITE si ...
)
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4080908
(2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d40849b8 next=0x7f63d4087be8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : request resending (t=0x7f63d4084798, INVITE si ...
)
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d40849b8
(2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer
routine:4,tl=0x7f63d4087be8 next=(nil), timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : request resending (t=0x7f63d40879c8, INVITE si ...
)
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4087be8
(2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
[...cycles of retransmits..]
Jul 28 22:19:07 [21437] DBG:tm:set_timer: relative timeout is 4000000
Jul 28 22:19:07 [21437] DBG:tm:insert_timer_unsafe: [7]: 0x7f63d4097d58
(32800000)
Jul 28 22:19:07 [21437] DBG:tm:retransmission_handler:
retransmission_handler : done
Jul 28 22:19:09 [21442] DBG:tm:timer_routine: timer
routine:0,tl=0x7f63d4074700 next=0x7f63d40787a0, timeout=31
Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: Cancel sent out,
sending 408 (0x7f63d40744b0)
Jul 28 22:19:09 [21442] DBG:tm:t_should_relay_response: T_code=100,
new_code=408
Jul 28 22:19:09 [21442] DBG:tm:t_pick_branch: picked branch 0, code 408
(prio=800)
Jul 28 22:19:09 [21442] DBG:tm:is_3263_failure: dns-failover test:
branch=0, last_recv=408, flags=1
Jul 28 22:19:09 [21442] DBG:tm:t_should_relay_response: trying DNS-based
failover
Jul 28 22:19:09 [21442] DBG:core:parse_headers: flags=40
Jul 28 22:19:09 [21442] DBG:rtpproxy:unforce_rtpproxy: sent unforce command
Jul 28 22:19:09 [21442] DBG:tm:relay_reply: T_state=4, branch=0, save=0,
relay=0, cancel_BM=0
Jul 28 22:19:09 [21442] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 28 22:19:09 [21442] DBG:tm:set_timer: relative timeout is 500000
Jul 28 22:19:09 [21442] DBG:tm:insert_timer_unsafe: [4]: 0x7f63d40745f8
(32200000)
Jul 28 22:19:09 [21442] DBG:tm:insert_timer_unsafe: [0]: 0x7f63d4074628 (61)
Jul 28 22:19:09 [21442] DBG:tm:relay_reply: sent buf=0x7f63d5cfac98:
SIP/2.0 4..., shmem=0x7f63d40776e0: SIP/2.0 4
Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: done
Jul 28 22:19:09 [21442] DBG:tm:timer_routine: timer
routine:0,tl=0x7f63d40787a0 next=0x7f63d407c848, timeout=31
Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: Cancel sent out,
sending 408 (0x7f63d4078550)

On Fri, Jul 28, 2017 at 2:54 AM, Bogdan-Andrei Iancu <bogdan at opensips.org>
wrote:

> Hi Maxim,,
>
> 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.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/devel/attachments/20170731/ebbeea1b/attachment-0001.html>


More information about the Devel mailing list