[OpenSIPS-Users] trouble with event_route.

johan johan at democon.be
Tue Aug 18 16:37:31 EST 2020 

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:1001 at 46.105.105.119>;tag=gW6aCs5kQ#015#012To: 
sip:1003 at 46.105.105.119#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:1003 at 46.105.105.119>;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:1003 at 46.105.105.119}
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]: 
DBG:core:get_hdr_field: <To> [25]; uri=[sip:1003 at 46.105.105.119]
Aug 18 16:25:10 ns365555 /data/opensips/sbin/opensips[8804]: 
DBG:core:get_hdr_field: to body [sip:1003 at 46.105.105.119#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:1003 at 46.105.105.119>
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:1003 at 88.121.152.134: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 ?

More information about the Users mailing list