Re: [SR-Users] BLFs are not working

Hey Daniel, here is the (hopefully) sanitized syslog parts around the BLF issue. I do appreciate your insights here.. ------------------ Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/726) [[SUBSCRIBEsip:301@domain.net:PORT SIP/2.0 0D  0A Via: SIP/2.0/UDP PRIVATE_IP:44762;br]] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:611]: parse_msg():  method:  <SUBSCRIBE> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:613]: parse_msg():  uri:<sip:301@domain.net:PORT> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:615]: parse_msg():  version: <SIP/2.0> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/parse_via.c:1300]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK1251409407>; state=6 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/parse_via.c:1300]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=17 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:170]: get_hdr_field(): <To> [46]; uri=[sip:301@domain.net:PORT] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body (46)[<sip:301@domain.net:PORT>#015#012], to tag (0)[] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:150]: get_hdr_field(): cseq <CSeq>: <21000> <SUBSCRIBE> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/receive.c:319]: receive_msg(): --- received sip message - request - call-id: [551473572-44762-6(a)BA.CEG.HG.GC] - cseq: [21000 SUBSCRIBE] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/receive.c:379]: receive_msg(): preparing to run routing scripts... Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=533 a=5 n=route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=754 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=759 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=754 a=25 n=mf_process_maxfwd_header Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=764 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=759 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=768 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[REQINIT] c=[/etc/kamailio/kamailio.cfg] l=764 a=26 n=sanity_check Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:318]: check_required_headers(): check_required_headers entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:340]: check_required_headers(): check_required_headers passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:348]: check_via1_header(): check via1 header Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:506]: check_cseq_method(): check_cseq_method entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:539]: check_cseq_method(): check_cseq_method passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:548]: check_cseq_value(): check_cseq_value entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:576]: check_cseq_value(): check_cseq_value passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:585]: check_cl(): check_cl entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:610]: check_cl(): check_cl passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:622]: check_expires_value(): check_expires_value entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:657]: check_expires_value(): check_expires_value passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:759]: check_parse_uris(): check_parse_uris entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:763]: check_parse_uris(): parsing ruri Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:777]: check_parse_uris(): looking up From header Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:791]: check_parse_uris(): parsing From header Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=138358676 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:817]: check_parse_uris(): parsing From URI Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:835]: check_parse_uris(): looking up To header Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:857]: check_parse_uris(): check_parse_uris(): parsing To URI Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity.c:902]: check_parse_uris(): check_parse_uris passed Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sanity [sanity_mod.c:254]: w_sanity_check(): sanity checks result: 1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=536 a=5 n=route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=952 a=55 n=force_rport Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=965 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=953 a=25 n=nat_uac_test Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/msg_translator.c:161]: check_via_address(): (184.148.140.29, PRIVATE_IP, 0) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=954 a=25 n=xinfo Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=961 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=955 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=961 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=958 a=24 n=is_first_hop Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=959 a=24 n=set_contact_alias Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/dset.c:919]: uri_add_rcv_alias(): encoded<sip:305@PRIVATE_IP:44762> => [sip:305@PRIVATE_IP:44762;alias=184.148.140.29~44762~1] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=962 a=39 n=setflag Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[NATDETECT] c=[/etc/kamailio/kamailio.cfg] l=965 a=2 n=return Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=550 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=542 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=559 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=550 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=555 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=551 a=24 n=t_precheck_trans Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=555 a=24 n=t_check_trans Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f1ef9d784e8) id=15/15920 global id=14/15920 T start=0xffffffffffffffff Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=54253, isACK=0 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK1251409407] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:675]: t_lookup_request(): no transaction found Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1104]: t_check_msg(): msg (0x7f1ef9d784e8) id=15/15920 global id=15/15920 T end=(nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=559 a=5 n=route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[WITHINDLG] c=[/etc/kamailio/kamailio.cfg] l=776 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[WITHINDLG] c=[/etc/kamailio/kamailio.cfg] l=772 a=24 n=has_totag Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} siputils [checks.c:120]: has_totag(): no totag Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[WITHINDLG] c=[/etc/kamailio/kamailio.cfg] l=772 a=2 n=return Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=564 a=5 n=route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[AUTH] c=[/etc/kamailio/kamailio.cfg] l=932 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[AUTH] c=[/etc/kamailio/kamailio.cfg] l=920 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[AUTH] c=[/etc/kamailio/kamailio.cfg] l=946 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 29==14 && [domain.net] == [PUBLIC_IP] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:648]: grep_sock_info(): checking if port PORT (advertise 0) matches port PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 29==9 && [domain.net] == [127.0.0.1] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:648]: grep_sock_info(): checking if port 8080 (advertise 0) matches port PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/name_alias.h:62]: grep_aliases(): matching (0:domain.net:PORT) vs. (2:localhost:8080) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/name_alias.h:62]: grep_aliases(): matching (0:domain.net:PORT) vs. (1:Kam01:PORT) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/forward.c:422]: check_self(): host (0:domain.net:PORT) == me Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[AUTH] c=[/etc/kamailio/kamailio.cfg] l=946 a=2 n=return Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=568 a=25 n=remove_hf Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=574 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=569 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=570 a=24 n=record_route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} rr [record.c:479]: record_route(): inserted record route (r2: 1 - plen: 0) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=579 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=574 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=579 a=5 n=route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[SIPOUT] c=[/etc/kamailio/kamailio.cfg] l=1017 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 29==14 && [domain.net] == [PUBLIC_IP] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:648]: grep_sock_info(): checking if port PORT (advertise 0) matches port PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 29==9 && [domain.net] == [127.0.0.1] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:648]: grep_sock_info(): checking if port 8080 (advertise 0) matches port PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/name_alias.h:62]: grep_aliases(): matching (0:domain.net:PORT) vs. (2:localhost:8080) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/name_alias.h:62]: grep_aliases(): matching (0:domain.net:PORT) vs. (1:Kam01:PORT) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/forward.c:422]: check_self(): host (0:domain.net:PORT) == me Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[SIPOUT] c=[/etc/kamailio/kamailio.cfg] l=1015 a=2 n=return Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=584 a=5 n=route Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=877 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=875 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=885 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=877 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=890 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=885 a=24 n=t_newtran Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1328]: t_newtran(): msg (0x7f1ef9d784e8) id=15/15920 global id=15/15920 T start=(nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:497]: t_lookup_request(): start searching: hash=54253, isACK=0 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK1251409407] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:675]: t_lookup_request(): no transaction found Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_hooks.c:346]: run_reqin_callbacks_internal(): trans=0x7f1ef323f8c8, callback type 1, id 0 entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_hooks.c:346]: run_reqin_callbacks_internal(): trans=0x7f1ef323f8c8, callback type 1, id 0 entered Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: 7e9980da4edb60eee121f954c89f5972 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=897 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=890 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=897 a=16 n=if Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=893 a=25 n=is_method Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=894 a=24 n=handle_subscribe Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [event_list.c:324]: search_event(): start event= [dialog/5] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:1312]: extract_sdialog_info_ex(): 'Expires' header found, value= 60 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:1346]: extract_sdialog_info_ex(): 'To' header ALREADY PARSED:<sip:301@domain.net:PORT> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:1403]: extract_sdialog_info_ex(): generating to_tag Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sl [sl.c:354]: get_reply_totag(): totag stateful mode (tm) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:1452]: extract_sdialog_info_ex(): subs->contact=sip:305@PRIVATE_IP:44762;alias=184.148.140.29~44762~1 - len = 55 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:1207]: handle_subscribe(): subscription status= active - inserted Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:562]: update_subscription(): update subscription Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:127]: printf_subs(): pres_uri:sip:301@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:128]: printf_subs(): watcher_user@watcher_domain:305@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:131]: printf_subs(): to_user@to_domain:301@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:133]: printf_subs(): from_user@from_domain:305@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:135]: printf_subs(): callid/from_tag/to_tag:551473572-44762-6@BA.CEG.HG.GC/138358676/5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:138]: printf_subs(): local_cseq/remote_cseq: 0/21000 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:140]: printf_subs(): local_contact/contact:sip:PUBLIC_IP:PORT/sip:305@PRIVATE_IP:44762;alias=184.148.140.29~44762~1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:142]: printf_subs(): record_route: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:144]: printf_subs(): sockinfo_str: udp:PUBLIC_IP:PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:147]: printf_subs(): event: dialog Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:148]: printf_subs(): status: active Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:149]: printf_subs(): reason: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:150]: printf_subs(): version: 1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:151]: printf_subs(): expires: 60 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:153]: printf_subs(): updated/updated_winfo: -1/-1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:625]: update_subscription(): subscription not in dialog Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [subscribe.c:628]: update_subscription(): inserting in shtable Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f1ef9d784e8) id=15/15920 global id=15/15920 T start=0x7f1ef323f8c8 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1109]: t_check_msg(): T (0x7f1ef323f8c8) already found for msg (0x7f1ef9d784e8)! Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_reply.c:1765]: cleanup_uac_timers(): RETR/FR timers reset Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_reply.c:637]: _reply_light(): reply sent out - buf=0x7f1ef9d83a38: SIP/2.0 202 OK#015#012Via:... shmem=0x7f1ef321abc0: SIP/2.0 202 OK#015#012Via: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_reply.c:648]: _reply_light(): finished Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} sl [sl.c:297]: send_reply(): reply in stateful mode (tm) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:1622]: send_notify_request(): dialog info: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:127]: printf_subs(): pres_uri:sip:301@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:128]: printf_subs(): watcher_user@watcher_domain:305@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:131]: printf_subs(): to_user@to_domain:301@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:133]: printf_subs(): from_user@from_domain:305@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:135]: printf_subs(): callid/from_tag/to_tag:551473572-44762-6@BA.CEG.HG.GC/138358676/5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:138]: printf_subs(): local_cseq/remote_cseq: 1/21000 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:140]: printf_subs(): local_contact/contact:sip:PUBLIC_IP:PORT/sip:305@PRIVATE_IP:44762;alias=184.148.140.29~44762~1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:142]: printf_subs(): record_route: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:144]: printf_subs(): sockinfo_str: udp:PUBLIC_IP:PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:147]: printf_subs(): event: dialog Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:148]: printf_subs(): status: active Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:149]: printf_subs(): reason: Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:150]: printf_subs(): version: 1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:151]: printf_subs(): expires: 60 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:153]: printf_subs(): updated/updated_winfo: -1/-1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [hash.c:522]: search_phtable(): pres_uri=sip:301@domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:617]: ps_db_get_p_notify_body(): No record exists in hash_table Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:125]: dlginfo_agg_nbody(): [pres_user]=301 [pres_domain]= domain.net, [n]=0 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:81]: dlginfo_agg_nbody_empty(): creating empty dialog for [pres_user]=301 [pres_domain]= domain.net Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:180]: agregate_xmls(): [pres_user]=301 [pres_domain]= domain.net, [n]=1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:282]: agregate_xmls(): node type: Element, name: dialog Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:103]: dlginfo_agg_nbody_empty(): [n_body]=0x7f1ef9d83b80 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:105]: dlginfo_agg_nbody_empty(): [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="sip:301@domain.net">#012  <dialog id="615293b33c62dec073e05d9421e9f48b" direction="recipient">#011<state>terminated</state>#011</dialog>#012</dialog-info>#012 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence_dialoginfo [notify_body.c:608]: dlginfo_body_setversion(): replace version with "1" Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:1707]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact:<sip:PUBLIC_IP:PORT>#015#012Subscription-State: active;expires=60#015#012Content-Type: application/dialog-info+xml#015#012 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:1131]: ps_build_dlg_t(): CONTACT =sip:305@PRIVATE_IP:44762;alias=184.148.140.29~44762~1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:641]: grep_sock_info(): checking if host==us: 14==14 && [PUBLIC_IP] == [PUBLIC_IP] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/socket_info.c:648]: grep_sock_info(): checking if port PORT (advertise 0) matches port PORT Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:1716]: send_notify_request(): expires 60 status 1 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/dset.c:1026]: uri_restore_rcv_alias(): decoded<sip:305@PRIVATE_IP:44762;alias=184.148.140.29~44762~1> => [sip:305@PRIVATE_IP:44762] [sip:184.148.140.29:44762] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [uac.c:450]: t_uac_prepare(): next_hop=<sip:184.148.140.29:44762> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [uac.c:158]: dlg2hash(): hashid 35506 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [uac.c:678]: send_prepared_request_impl(): uac: 0x7f1ef31d9830  branch: 0  to 184.148.140.29:44762 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/onsend.c:50]: run_onsend(): required parameters are not available - ignoring Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: INFO:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} presence [notify.c:1737]: send_notify_request(): NOTIFYsip:305@domain.net via on behalf ofsip:301@domain.net for event dialog :551473572-44762-6@BA.CEG.HG.GC Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=895 a=24 n=t_release Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1034]: t_check_msg(): msg (0x7f1ef9d784e8) id=15/15920 global id=15/15920 T start=0x7f1ef323f8c8 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_lookup.c:1109]: t_check_msg(): T (0x7f1ef323f8c8) already found for msg (0x7f1ef9d784e8)! Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_reply.c:1765]: cleanup_uac_timers(): RETR/FR timers reset Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/timer.c:557]: timer_add_safe(): timer_add called on an active timer 0x7f1ef323f950 (0x7f1ef2ec8f10, 0x7f1ef323d4a8), flags 201 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} tm [t_funcs.c:146]: put_on_wait(): transaction 0x7f1ef323f8c8 already on wait Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} *** cfgtrace:dbg_cfg_trace(): request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=897 a=2 n=exit Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/receive.c:436]: receive_msg(): request-route executed in: 39617 usec Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6(a)BA.CEG.HG.GC} <core> [core/receive.c:528]: receive_msg(): cleaning up Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/531) [[SIP/2.0 481 Subscription Does Not Exist 0D  0A Via: SIP/2.0/UDP PUBLIC_IP:PORT;branch=z9hG4bK2ba8.5e7]] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): SIP Reply  (status): Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:621]: parse_msg():  version: <SIP/2.0> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:623]: parse_msg():  status:  <481> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:625]: parse_msg():  reason:  <Subscription Does Not Exist> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/parse_via.c:1300]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK2ba8.5e7ce1f0000000000000000000000000.0>; state=16 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=138358676 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:170]: get_hdr_field(): <To> [55]; uri=[sip:305@domain.net] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body (39)[<sip:305@domain.net>], to tag (9)[138358676] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:150]: get_hdr_field(): cseq <CSeq>: <2> <NOTIFY> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/receive.c:319]: receive_msg(): --- received sip message - reply - call-id: [551473572-44762-6(a)BA.CEG.HG.GC] - cseq: [2 NOTIFY] Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0 Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15918]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header ------------- As I said in my last posting, the 1782s are still having issues "481 Subscription Does Not Exist" is response to a NOTIFY for SUBSCRIBE the the device just sent in... Jerry On 2021-10-01 1:11 p.m., Jerry Kendall wrote: __________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions *sr-users(a)lists.kamailio.org Important: keep the mailing list in the recipients, do not reply only to the sender! Edit mailing list options or unsubscribe: *https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users