Script :
...
if (($avp(callpn)!="null") or ($avp(messagepn)!=null))
{
xlog("callid=$ci: Route[userlocation]:we call t_newtran and
subscribe for E_UL_CONTACT_INSERT for $rU");
# prepare transaction for branch injection; it is mandatory
# to create the transaction before the subscription, otherwise
# the EBR module will not pass the transaction ID into the
# notification route
t_newtran();
# keep the transaction alive (even if all branches will
# terminate) until the FR INVITE timer hits (we want to wait
# for new possible contacts being registered)
t_wait_for_new_branches();
# subscribe to new contact registration event,
# but for our callee only
$avp(filter) = "aor="+$rU;
notify_on_event("E_UL_CONTACT_INSERT",$avp(filter),"fork_call", 180);
}
route(relay);
}
route[fork_call]
{
xlog("callid=$ci: Route[fork_call]:user $avp(aor) registered a new
contact $avp(uri), injecting\n");
# take the contact described by the E_UL_CONTACT_INSERT
# event and inject it as a new branch into the original
# transaction
t_inject_branches("event");
}
So we clearly see that the subscribe is working.
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
callid=HthVnaTmMa: Route[userlocation]:we call t_newtran and subscribe
for E_UL_CONTACT_INSERT for 1003
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:t_newtran: transaction on entrance=(nil)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:parse_headers: flags=ffffffffffffffff
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:parse_headers: flags=78
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:t_lookup_request: start searching: hash=44330, isACK=0
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:matching_3261: RFC3261 transaction matching failed
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:t_lookup_request: no transaction found
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:run_reqin_callbacks: trans=0x7f80f51a6cb8, callback type 1, id 0
entered
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:parse_headers: flags=ffffffffffffffff
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:_tcpconn_find: c=0x7f80f519db08, c->id=998933773, port=40726
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:print_ip: ip=149.6.164.90
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:tcp_conn_get: con found in state 0
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:tcp_conn_get: tcp connection found (0x7f80f519db08) already in
this process ( 9 ) , fd = 5
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:proto_tls:proto_tls_send: sending via fd 5...
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:proto_tls:tls_update_fd: New fd is 5
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:proto_tls:tls_write: write was successful (307 bytes)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:proto_tls:proto_tls_send: after write: c= 0x7f80f519db08 n=307 fd=5
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:proto_tls:proto_tls_send: buf=#012SIP/2.0 100 Giving it a
try#015#012Via: SIP/2.0/TLS
10.205.0.39:40726;received=149.6.164.90;branch=z9hG4bK.~dSfpAvIw;rport=40726#015#012From:
"1001" <sip:[email protected]>;tag=gW6aCs5kQ#015#012To:
sip:[email protected]#015#012CSeq: 20 INVITE#015#012Call-ID:
HthVnaTmMa#015#012Server: OpenSIPS (3.1.0
(x86_64/linux))#015#012Content-Length: 0#015#012#015#012
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:_reply_light: reply sent out. buf=0x7f80f8c933d0: SIP/2.0 1...,
shmem=0x7f80f5177c28: SIP/2.0 1
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:_reply_light: finished
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:insert_timer_unsafe: [1]: 0x7f80f51a6f08 (274)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:event_routing:pack_ebr_filters: converted key <aor>(0x7f80f5188a40)
+ val <1003>(0x7f80f5188a44) at 0x7f80f5188a08
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:t_check: start=0x7f80f51a6cb8
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:tm:t_check: transaction already found!
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:event_routing:add_ebr_subscription: transaction reference is
AD2A:1D200B6E
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:event_routing:add_ebr_subscription: new subscription [NOTIFY] on
event E_UL_CONTACT_INSERT/7 successfully added from process 9
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
DBG:core:pv_printf: final buffer length 49
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8806]:
callid=HthVnaTmMa: route[relay]: routing the call
however a little bit further in the log the REGISTER comes is, but
nothing happens.
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg: method: <REGISTER>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg: uri: <sip:46.105.105.119;transport=tls>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg: version: <SIP/2.0>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: flags=ffffffffffffffff
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=6
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK.-FHnT2UUB>; state=6
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_via: end of header reached, state=5
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: via found, flags=ffffffffffffffff
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: this is the first via
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 1, name=<Via>,
body=<SIP/2.0/TLS 192.168.0.12:51130;alias;branch=z9hG4bK.-FHnT2UUB;rport>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 4, name=<From>,
body=<<sip:[email protected]>;tag=nGAaO8ksF>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:_parse_to: end of header reached, state=9
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:_parse_to: display={}, ruri={sip:[email protected]}
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:get_hdr_field: <To> [25]; uri=[sip:[email protected]]
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:get_hdr_field: to body [sip:[email protected]#015#012]
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 3, name=<To>,
body=<sip:[email protected]>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:get_hdr_field: cseq <CSeq>: <252> <REGISTER>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 5, name=<CSeq>, body=<252
REGISTER>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 6, name=<Call-ID>,
body=<YwRIOjnV90>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 8, name=<Max-Forwards>, body=<70>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 17, name=<Supported>,
body=<replaces, outbound, gruu>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 22, name=<Accept>,
body=<application/sdp>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 22, name=<Accept>,
body=<text/plain>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 22, name=<Accept>,
body=<application/vnd.gsma.rcs-ft-http+xml>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 7, name=<Contact>,
body=<<sip:[email protected]:33268;pn-provider=apns;pn-prid=b6d1a91d1c9a4e5e025ff3f17a82dc3767000f9335c24aa8c694721cda8c7e40:remote&5119a83b5ec1d0c2436c55b3b699cb378cb80bb4b7ae28c27b79ea277c9e69b5:voip;pn-param=NA26ULS4WC.com.dustmobile.onsim.voip;transport=tls>;+sip.instance="<urn:uuid:ca48a37e-b9d8-007b-b773-53f72c359228>";+org.linphone.specs="lime">
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 15, name=<Expires>, body=<180>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 27, name=<User-Agent>,
body=<Unknown (belle-sip/4.3.0)>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:get_hdr_field: content_length=0
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 13, name=<Content-Length>,
body=<0>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: header field type 14, name=<Authorization>,
body=<Digest realm="46.105.105.119",
nonce="5f3c01040000001e503fdc80e4bdf53304d16e99790c0556",
username="1003", uri="sip:46.105.105.119;transport=tls",
response="a8bd1aae7275e64d430249cd4afba261", cnonce="uev3BuI-kFVgBwOE",
nc=00000001, qop=auth>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:get_hdr_field: found end of header
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg: first via: <SIP/2.0/TLS> <192.168.0.12:51130(51130)>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg: ;<alias;branch=z9hG4bK.-FHnT2UUB;rport>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg:
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_msg: exiting
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:receive_msg: After parse_msg...
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:receive_msg: preparing to run routing scripts...
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:maxfwd:is_maxfwd_present: value = 70
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:sipmsgops:has_totag: no totag
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: flags=78
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:tm:t_lookup_request: start searching: hash=31189, isACK=0
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:tm:matching_3261: RFC3261 transaction matching failed
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:tm:t_lookup_request: no transaction found
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_headers: flags=200
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:rr:find_first_route: No Route headers found
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:rr:loose_route: There is no Route HF
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: parsed uri:#012 type=1 user=<>(0)#012
passwd=<>(0)#012 host=<46.105.105.119>(14)#012 port=<>(0): 0#012
params=<transport=tls>(13)#012 headers=<>(0)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: uri params:#012 transport=<transport=tls>,
val=<tls>, proto=3
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: user-param=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: method=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: ttl=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: maddr=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: lr=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: r2=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:comp_scriptvar: str 20 : tls
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:setflag: mflags for 0x7f80f8ca08b0 : (1, 0)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:setbflag: bflags for 0x7f80f8ca08b0 : (2, 0)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:isflagset: mflags for 0x7f80f8ca08b0 : (1, 2)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:setbflag: bflags for 0x7f80f8ca08b0 : (4, 2)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: parsed uri:#012 type=1 user=<1003>(4)#012
passwd=<>(0)#012 host=<46.105.105.119>(14)#012 port=<>(0): 0#012
params=<>(0)#012 headers=<>(0)
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: uri params:#012 transport=<>, val=<>, proto=0
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: user-param=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: method=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: ttl=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: maddr=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: lr=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:core:parse_uri: r2=<>, val=<>
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:auth:check_nonce: comparing
[5f3c01040000001e503fdc80e4bdf53304d16e99790c0556] and
[5f3c01040000001e503fdc80e4bdf53304d16e99790c0556]
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]:
DBG:db_mysql:has_stmt_ctx: ctx found for subscriber
Can somebody please explain me what I do wrong ?
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
