[OpenSIPS-Users] B2BUA and BYE message generated from sipp

Konrad Malewski konrad.malewski at motorolasolutions.com
Thu Feb 7 10:17:04 EST 2019 

Hello,

I am new to opensips. I went through proxy tutorials and now I am trying to
configure opensips in b2bua mode. I am using 3 dockers (UAS, UAC and
opensips).

I have problems with BYE message sent by UAC. Opensips is not able to match
it to whole dialog (this is my interpretation) and returns 500 internal
error (due to t_relay call, but without it there is no response at all).

What am I missing from my config ?
Thanks for any hint....

# UAS at 172.18.0.4:
$ sipp --t tn -sn uas

# UAC at 172.18.0.3
$ sipp -t tn -rsa 172.18.0.2 -sn uac -r 1 172.18.0.4

# opensips 2.4.4 (x86_64/linux) at 172.18.0.2

////////opensips.cfg////////////
####### Modules Section ########
#set module path
mpath="/usr/lib/x86_64-linux-gnu/opensips/modules/"
#### StateLess module
loadmodule "sl.so"
#### Transaction Module
loadmodule "tm.so"
modparam("tm", "fr_timeout", 5)
modparam("tm", "fr_inv_timeout", 30)
modparam("tm", "restart_fr_on_each_reply", 0)
modparam("tm", "onreply_avp_mode", 1)
#### Record Route Module
loadmodule "rr.so"
modparam("rr", "append_fromtag", 0)
#### SIP MSG OPerationS module
loadmodule "sipmsgops.so"
#### FIFO Management Interface
loadmodule "mi_fifo.so"
modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo")
modparam("mi_fifo", "fifo_mode", 0666)
#### TCP protocol
loadmodule "proto_tcp.so"
loadmodule "topology_hiding.so"
loadmodule "b2b_entities.so"
loadmodule "b2b_logic.so"

modparam("tm", "pass_provisional_replies", 1)
####### Routing Logic ########
route{
        route(relay);
}
route[b2b_request] {
  xlog("B2B request - callid: $ci time [$Tf] method ($rm) r-uri ($ru) 2nd
via ($hdr(via[1]))\n");

}
route[b2b_reply] {
  xlog("B2B reply - callid %ci time [$Tf] method ($rm) r-uri ($ru) 2nd via
($hdr(via[1]))\n");

}
route[relay] {
        if (is_method("INVITE") && !($si=="172.18.0.2" && $sp==5060))
        {
                xlog("B2B init - callid $ci time [$Tf] method ($rm) r-uri
($ru) 2nd via ($hdr(via[1]))\n");
                b2b_init_request("top hiding");
                exit;
        }

        xlog("t_relay - callid $ci time [$Tf] method ($rm) r-uri ($ru) 2nd
via ($hdr(via[1]))\n");
        if (!t_relay())
        {
                sl_reply_error();
        };
        exit;
}
////////////////////////////////

//////NGREP/////////////////////
T 172.18.0.3:60750 -> 172.18.0.2:5060 [AP]
INVITE sip:service at 172.18.0.4:5060 SIP/2.0.
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-0.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 1 INVITE.
Contact: sip:sipp at 172.18.0.3:5060.
Max-Forwards: 70.
Subject: Performance Test.
Content-Type: application/sdp.
Content-Length:   131.
.
v=0.
o=user1 53655765 2353687637 IN IP4 172.18.0.3.
s=-.
c=IN IP4 172.18.0.3.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.


T 172.18.0.2:5060 -> 172.18.0.3:60750 [AP]
SIP/2.0 100 Giving a try.
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-0.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 1 INVITE.
Server: OpenSIPS (2.4.4 (x86_64/linux)).
Content-Length: 0.
.


T 172.18.0.2:43989 -> 172.18.0.4:5060 [AP]
INVITE sip:service at 172.18.0.4:5060 SIP/2.0.
Via: SIP/2.0/TCP 172.18.0.2:5060;branch=z9hG4bK0c85.96049b37.0.
To: sip:service at 172.18.0.4:5060.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=42494589cc6520b7535401b81466113d.
CSeq: 2 INVITE.
Call-ID: B2B.95.8135310.1549535500.
Max-Forwards: 70.
Content-Length: 131.
User-Agent: OpenSIPS (2.4.4 (x86_64/linux)).
Content-Type: application/sdp.
Contact: <sip:172.18.0.2:5060;transport=tcp>.
.
v=0.
o=user1 53655765 2353687637 IN IP4 172.18.0.3.
s=-.
c=IN IP4 172.18.0.3.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.


T 172.18.0.4:5060 -> 172.18.0.2:43989 [AP]
SIP/2.0 180 Ringing.
Via: SIP/2.0/TCP 172.18.0.2:5060;branch=z9hG4bK0c85.96049b37.0.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=42494589cc6520b7535401b81466113d.
To: sip:service at 172.18.0.4:5060;tag=370SIPpTag0130.
Call-ID: B2B.95.8135310.1549535500.
CSeq: 2 INVITE.
Contact: <sip:172.18.0.4:5060;transport=TCP>.
Content-Length: 0.
.
T 172.18.0.4:5060 -> 172.18.0.2:43989 [AP]
SIP/2.0 200 OK.
Via: SIP/2.0/TCP 172.18.0.2:5060;branch=z9hG4bK0c85.96049b37.0.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=42494589cc6520b7535401b81466113d.
To: sip:service at 172.18.0.4:5060;tag=370SIPpTag0130.
Call-ID: B2B.95.8135310.1549535500.
CSeq: 2 INVITE.
Contact: <sip:172.18.0.4:5060;transport=TCP>.
Content-Type: application/sdp.
Content-Length:   131.
.
v=0.
o=user1 53655765 2353687637 IN IP4 172.18.0.4.
s=-.
c=IN IP4 172.18.0.4.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.


T 172.18.0.2:5060 -> 172.18.0.3:60750 [AP]
SIP/2.0 180 Ringing.
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-0.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>;tag=B2B.407.108.1549535500.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 1 INVITE.
Contact: <sip:172.18.0.2:5060;transport=tcp>.
Server: OpenSIPS (2.4.4 (x86_64/linux)).
Content-Length: 0.
.


T 172.18.0.2:5060 -> 172.18.0.3:60750 [AP]
SIP/2.0 200 OK.
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-0.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>;tag=B2B.407.108.1549535500.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 1 INVITE.
Content-Type: application/sdp.
Contact: <sip:172.18.0.2:5060;transport=tcp>.
Server: OpenSIPS (2.4.4 (x86_64/linux)).
Content-Length: 131.
.
v=0.
o=user1 53655765 2353687637 IN IP4 172.18.0.4.
s=-.
c=IN IP4 172.18.0.4.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.


T 172.18.0.3:60750 -> 172.18.0.2:5060 [AP]
ACK sip:service at 172.18.0.4:5060 SIP/2.0.
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-5.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>;tag=B2B.407.108.1549535500.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 1 ACK.
Contact: sip:sipp at 172.18.0.3:5060.
Max-Forwards: 70.
Subject: Performance Test.
Content-Length: 0.
.


T 172.18.0.2:43989 -> 172.18.0.4:5060 [AP]
ACK sip:172.18.0.4:5060;transport=TCP SIP/2.0.
Via: SIP/2.0/TCP 172.18.0.2:5060;branch=z9hG4bK0c85.a6049b37.0.
To: <sip:service at 172.18.0.4:5060>;tag=370SIPpTag0130.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=42494589cc6520b7535401b81466113d.
CSeq: 2 ACK.
Call-ID: B2B.95.8135310.1549535500.
Max-Forwards: 70.
Content-Length: 0.
User-Agent: OpenSIPS (2.4.4 (x86_64/linux)).
Contact: <sip:172.18.0.2:5060;transport=tcp>.
.
T 172.18.0.3:60750 -> 172.18.0.2:5060 [AP]
BYE sip:service at 172.18.0.4:5060 SIP/2.0.
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-7.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>;tag=B2B.407.108.1549535500.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 2 BYE.
Contact: sip:sipp at 172.18.0.3:5060.
Max-Forwards: 70.
Subject: Performance Test.
Content-Length: 0.
.


T 172.18.0.2:5060 -> 172.18.0.3:60750 [AP]
SIP/2.0 500 Server error occurred (7/TM).
Via: SIP/2.0/TCP 172.18.0.3:5060;branch=z9hG4bK-382-1-7.
From: sipp <sip:sipp at 172.18.0.3:5060>;tag=382SIPpTag001.
To: sut <sip:service at 172.18.0.4:5060>;tag=B2B.407.108.1549535500.
Call-ID: 1-382 at 172.18.0.3.
CSeq: 2 BYE.
Server: OpenSIPS (2.4.4 (x86_64/linux)).
Content-Length: 0.
.


///////////////////////////////////

////////////opensips.log///////////
=> DBG:core:parse_msg: SIP Request:
=> DBG:core:parse_msg:  method:  <ACK>
=> DBG:core:parse_msg:  uri:     <sip:service at 172.18.0.4: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> =
<z9hG4bK-382-1-5>; 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: too late to be a local ACK!
=> DBG:core:parse_headers: flags=ffffffffffffffff
=> DBG:core:parse_to_param: tag=B2B.407.108.1549535500
=> DBG:core:_parse_to: end of header reached, state=29
=> DBG:core:_parse_to: display={sut}, ruri={sip:service at 172.18.0.4:5060}
=> DBG:core:get_hdr_field: <To> [62]; uri=[sip:service at 172.18.0.4:5060]
=> DBG:core:get_hdr_field: to body [sut <sip:service at 172.18.0.4:5060>]
=> DBG:core:get_hdr_field: cseq <CSeq>: <1> <ACK>
=> DBG:core:get_hdr_field: content_length=0
=> DBG:core:get_hdr_field: found end of header
=> DBG:b2b_entities:b2b_prescript_f: start - method = ACK
=> DBG:core:parse_to_param: tag=382SIPpTag001
=> DBG:core:_parse_to: end of header reached, state=29
=> DBG:core:_parse_to: display={sipp}, ruri={sip:sipp at 172.18.0.3:5060}
=> DBG:b2b_entities:b2b_parse_key: hash_index = [407]  - local_index= [108]
=> DBG:b2b_entities:b2b_prescript_f: Received a b2b server request [ACK]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil),
table=0x7fdc845a2110, hash=407, label=108
=> DBG:b2b_entities:b2b_search_htable_next_dlg: searching  callid 16[
1-382 at 172.18.0.3]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: searching   totag
22[B2B.407.108.1549535500]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag
13[382SIPpTag001]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg
[0x7fdc845bea48] dlg->uas_tran=[(nil)]
=> DBG:b2b_entities:b2b_prescript_f: Received request method[ACK] for
dialog[0x7fdc845bea48]
=> 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=47941, isACK=1
=> DBG:core:parse_headers: flags=38
=> DBG:tm:t_lookup_request: REF_UNSAFE:[0x7fdc845bec78] after is 1
=> DBG:tm:t_lookup_request: e2e proxy ACK found
=> DBG:tm:cleanup_uac_timers: RETR/FR timers reset
=> DBG:tm:insert_timer_unsafe: [2]: 0x7fdc845becf8 (51)
=> DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7fdc845bec78] after is 0
=> DBG:b2b_logic:b2bl_parse_key: hash_index = [95]  - local_index= [0]
=> DBG:core:parse_headers: flags=ffffffffffffffff
=> DBG:core:parse_headers: flags=ffffffffffffffff
=> DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [95.0]
with entity [B2B.407.108.1549535500]
=> DBG:b2b_logic:b2bl_search_entity: Key [B2B.407.108.1549535500]
=> DBG:b2b_logic:b2b_logic_notify_request: b2b_entity key =
B2B.407.108.1549535500
=> DBG:b2b_logic:b2b_logic_notify_request: request received for
tuple[0x7fdc845be810]->[95.0]
=> DBG:b2b_logic:b2b_logic_notify_request: Send request [ACK] to peer
[B2B.95.8135310.1549535500]
=> DBG:b2b_entities:b2b_parse_key: hash_index = [95]  - local_index=
[8135310]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil),
table=0x7fdc845a4128, hash=95, label=8135310
=> DBG:b2b_entities:b2b_search_htable_next_dlg: searching  callid
25[B2B.95.8135310.1549535500]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: searching   totag
32[42494589cc6520b7535401b81466113d]
=> DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag
14[370SIPpTag0130]
=> DBG:b2b_entities:b2b_send_request: Send request [ACK] for entity type
[1] for dlg[0x7fdc845c43c0]->[B2B.95.8135310.1549535500]
=> DBG:b2b_entities:b2b_client_build_dlg: Rem_target = sip:172.18.0.4:5060
;transport=TCP
=> DBG:b2b_entities:b2b_client_build_dlg: send sock= 172.18.0.2
=> DBG:tm:t_uac: next_hop=<sip:172.18.0.4:5060;transport=TCP>
=> DBG:core:mk_proxy: doing DNS lookup...
=> DBG:tm:t_uac: sending socket is 172.18.0.2
=> DBG:tm:dlg2hash: 22720
=> DBG:tm:print_request_uri: sip:172.18.0.4:5060;transport=TCP
=> DBG:core:tcp_conn_get: con found in state 0
=> DBG:core:tcp_conn_get: tcp connection found (0x7fdc845c3f68), acquiring
fd
=> DBG:core:tcp_conn_get: c= 0x7fdc845c3f68, n=16, Usock=42
=> DBG:core:handle_worker: read response= 7fdc845c3f68, 1, fd -1 from 4
(1827)
=> DBG:core:tcp_conn_get: after receive_fd: c= 0x7fdc845c3f68 n=8 fd=43
=> DBG:core:proto_tcp_send: sending via fd 43...
=> DBG:core:async_tsend_stream: Async successful write from first try on
0x7fdc845c3f68
=> DBG:core:proto_tcp_send: after write: c= 0x7fdc845c3f68 n/len=420/420
fd=43
=> DBG:tm:cleanup_uac_timers: RETR/FR timers reset
=> DBG:tm:insert_timer_unsafe: [2]: 0x7fdc845c48a0 (51)
=> DBG:core:destroy_avp_list: destroying list (nil)
=> DBG:core:receive_msg: cleaning up
=> DBG:core:tcp_read_req: tcp_read_req end
=> DBG:core:tcp_read_req: Using the global ( per process ) buff
=> DBG:core:tcp_handle_req: content-length= 0
=> DBG:core:tcp_handle_req: Nothing more to read on TCP conn
0x7fdc845be558, currently in state 0
=> DBG:core:parse_msg: SIP Request:
=> DBG:core:parse_msg:  method:  <BYE>
=> DBG:core:parse_msg:  uri:     <sip:service at 172.18.0.4: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> =
<z9hG4bK-382-1-7>; 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:core:parse_headers: flags=ffffffffffffffff
=> DBG:core:parse_to_param: tag=B2B.407.108.1549535500
=> DBG:core:_parse_to: end of header reached, state=29
=> DBG:core:_parse_to: display={sut}, ruri={sip:service at 172.18.0.4:5060}
=> DBG:core:get_hdr_field: <To> [62]; uri=[sip:service at 172.18.0.4:5060]
=> DBG:core:get_hdr_field: to body [sut <sip:service at 172.18.0.4:5060>]
=> DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
=> DBG:core:get_hdr_field: content_length=0
=> DBG:core:get_hdr_field: found end of header
=> DBG:b2b_entities:b2b_prescript_f: start - method = BYE
=> DBG:b2b_entities:b2b_prescript_f: <uri> host:port [172.18.0.4][5060]
=> DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [172.18.0.4]
== [172.18.0.2]
=> DBG:core:grep_sock_info: checking if port 5060 matches port 5060
=> DBG:core:check_self: host != me
=> DBG:b2b_entities:b2b_prescript_f: RURI does not point to me
=> DBG:core:parse_headers: flags=ffffffffffffffff
=> t_relay - callid 1-382 at 172.18.0.3 time [Thu Feb  7 10:31:41 2019] method
(BYE) r-uri (sip:service at 172.18.0.4:5060) 2nd via (<null>)
///////////////////////////////////

-- 
Konrad Malewski
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20190207/74804495/attachment-0001.html>

More information about the Users mailing list