So, I went for dinner and one of the BLFs started working while I was away from my desk... I left sngrep running and it captured something puzzling....
------ BEFORE - NOT WORKING ---------
2021/10/02 19:05:43.842970 CLIENT_IP:55318 -> PUBLIC_IP:PORT SUBSCRIBE sip:301@domain.net:PORT SIP/2.0 Via: SIP/2.0/UDP 10.10.10.62:55318;branch=z9hG4bK89955442;rport From: <sip:305@domain.net:PORT>;tag=1703808353 To: <sip:301@domain.net:PORT> Call-ID: 2104033891-55318-6@BA.CEG.HG.GC CSeq: 86910 SUBSCRIBE Contact: <sip:305@10.10.10.62:55318> X-Grandstream-PBX: true Max-Forwards: 70 User-Agent: Grandstream GXP1782 1.0.1.116 Expires: 60 Supported: replaces, path, timer, eventlist Event: dialog Accept: application/dialog-info+xml,multipart/related,application/rlmi+xml Accept-Encoding: zlib+base64 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 2021/10/02 19:05:43.843367 PUBLIC_IP:PORT -> CLIENT_IP:55318 SIP/2.0 202 OK Via: SIP/2.0/UDP 10.10.10.62:55318;branch=z9hG4bK89955442;rport=55318;received=CLIENT_IP From: <sip:305@domain.net:PORT>;tag=1703808353 To: <sip:301@domain.net:PORT>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6 Call-ID: 2104033891-55318-6@BA.CEG.HG.GC CSeq: 86910 SUBSCRIBE Expires: 60 Contact: <sip:PUBLIC_IP:PORT> Server: kamailio (5.4.4 (x86_64/linux)) Content-Length: 0 2021/10/02 19:05:43.844037 PUBLIC_IP:PORT -> CLIENT_IP:55318 NOTIFY sip:305@10.10.10.62:55318 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:PORT;branch=z9hG4bKffd9.6b44c1b2000000000000000000000000.0 To: <sip:305@domain.net>;tag=1703808353 From: <sip:301@domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6 CSeq: 2 NOTIFY Call-ID: 2104033891-55318-6@BA.CEG.HG.GC Content-Length: 273 User-Agent: kamailio (5.4.4 (x86_64/linux)) Max-Forwards: 70 Event: dialog Contact: <sip:PUBLIC_IP:PORT> Subscription-State: active;expires=60 Content-Type: application/dialog-info+xml <?xml version="1.0"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="1" state="full" entity="sip:301@domain.net"> <dialog id="615293b33c62dec073e05d9421e9f48b" direction="recipient"> <state>terminated</state> </dialog> </dialog-info> ------ BEFORE - NOT WORKING ---------
------ AFTER - WORKING ---------
2021/10/02 19:06:04.291019 CLIENT_IP:55318 -> PUBLIC_IP:PORT SUBSCRIBE sip:301@domain.net:PORT SIP/2.0 Via: SIP/2.0/UDP 10.10.10.62:55318;branch=z9hG4bK1198306856;rport From: <sip:305@domain.net:PORT>;tag=998538926 To: <sip:301@domain.net:PORT> Call-ID: 2104033891-55318-6@BA.CEG.HG.GC CSeq: 86920 SUBSCRIBE Contact: <sip:305@10.10.10.62:55318> X-Grandstream-PBX: true Max-Forwards: 70 User-Agent: Grandstream GXP1782 1.0.1.116 Expires: 60 Supported: replaces, path, timer, eventlist Event: dialog Accept: application/dialog-info+xml,multipart/related,application/rlmi+xml Accept-Encoding: zlib+base64 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE Content-Length: 0 2021/10/02 19:06:04.291688 PUBLIC_IP:PORT -> CLIENT_IP:55318 SIP/2.0 202 OK Via: SIP/2.0/UDP 10.10.10.62:55318;branch=z9hG4bK1198306856;rport=55318;received=CLIENT_IP From: <sip:305@domain.net:PORT>;tag=998538926 To: <sip:301@domain.net:PORT>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6 Call-ID: 2104033891-55318-6@BA.CEG.HG.GC CSeq: 86920 SUBSCRIBE Expires: 60 Contact: <sip:PUBLIC_IP:PORT> Server: kamailio (5.4.4 (x86_64/linux)) Content-Length: 0 2021/10/02 19:06:04.292671 PUBLIC_IP:PORT -> CLIENT_IP:55318 NOTIFY sip:305@10.10.10.62:55318 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:PORT;branch=z9hG4bKffd9.40e91c22000000000000000000000000.0 To: <sip:305@domain.net>;tag=998538926 From: <sip:301@domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6 CSeq: 2 NOTIFY Call-ID: 2104033891-55318-6@BA.CEG.HG.GC Content-Length: 273 User-Agent: kamailio (5.4.4 (x86_64/linux)) Max-Forwards: 70 Event: dialog Contact: <sip:PUBLIC_IP:PORT> Subscription-State: active;expires=60 Content-Type: application/dialog-info+xml <?xml version="1.0"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="1" state="full" entity="sip:301@domain.net"> <dialog id="615293b33c62dec073e05d9421e9f48b" direction="recipient"> <state>terminated</state> </dialog> </dialog-info> ------ AFTER - WORKING ---------
The careful eye will notice NOTHING CHANGED.....
Almost nothing... Of course the branch and (from/from/to) tags are different BUT THATS IT...
So, not working, go for food, working... I changed nothing.
I thought it was the never change version attribute in the dialog-info but, maybe not.
Has anyone seen this ? If so, how did you get past it ?
In case you're new to this thread, these are Grandstream GXP1782 desk phones.
When I change the DNS A record for the host and point it to a FreeSWITCH system, the BLFs are fine. It's just when they reach Kamailio 5.4.4 that they don't sync up properly.
Any pointers are welcome...
Jerry
So, after much more testing and staring at logs....
The BLFs ARE indeed working for all my Yealinks and MOST of my Grandstreams
The ones that are not working don't like the 'version=1' - these are sending back "481 Subscription Does Not Exist"
---------
NOTIFY sip:305@PRIVATE_IP:55318 SIP/2.0
Via: SIP/2.0/UDP IP_ADDRESS:PORT;branch=z9hG4bKffd9.a74b11b5000000000000000000000000.0
To: <sip:305@domain.net>;tag=2001402711
From: <sip:301@domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6
CSeq: 2 NOTIFY
Call-ID: 2104033891-55318-6@BA.CEG.HG.GC
Content-Length: 273
User-Agent: kamailio (5.4.4 (x86_64/linux))
Max-Forwards: 70
Event: dialog
Contact: <sip:IP_ADDRESS:PORT>
Subscription-State: active;expires=60
Content-Type: application/dialog-info+xml
<?xml version="1.0"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="1" state="full" entity="sip:301@domain.net">
<dialog id="615293b33c62dec073e05d9421e9f48b" direction="recipient"> <state>terminated</state> </dialog>
</dialog-info>
--------------
Other wise everything seems OK.
So, any ideas why Kamilio is sending Version=1 repeatedly?
Jerry
On 2021-10-01 1:33 p.m., Jerry Kendall wrote:
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) [[SUBSCRIBE sip: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@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@BA.CEG.HG.GC} presence [notify.c:149]: printf_subs(): reason: Oct 1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@BA.CEG.HG.GC} presence [notify.c:149]: printf_subs(): reason: Oct 1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@BA.CEG.HG.GC} tm [uac.c:158]: dlg2hash(): hashid 35506 Oct 1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@BA.CEG.HG.GC} presence [notify.c:1737]: send_notify_request(): NOTIFY sip:305@domain.net via on behalf of sip: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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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 SUBSCRIBE 551473572-44762-6@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@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... JerryOn 2021-10-01 1:11 p.m., Jerry Kendall wrote:
Thanks Daniel,
Now it seems almost done.... I have 6 Grandstream phones connected and they all have 4-6 BLFs watching each other.
(I also have Yealink/Cisco/SNOM/Polycom phones to test later - one thing at a time.....)
The 2x GRP2604P all look great
The GXP2130 seems OK as well
The GXP2170 with side car seems OK
But, the 2x GXP1782 are not quit working yet.
A couple of the BLFs are OK but most are sending back 481 Subscription Does Not Exist... See blow (gotta love sngrep)
--------------------------------
2021/10/01 12:31:13.024698 SITE_IP:44762 -> PUBLIC_IP:8081
SUBSCRIBE sip:301@domain.net:8081 SIP/2.0
Via: SIP/2.0/UDP PRIVATE_IP:44762;branch=z9hG4bK806864449;rport
From: <sip:305@domain.net:8081>;tag=1883014019
To: <sip:301@domain.net:8081>
Call-ID: 551473572-44762-6@BA.CEG.HG.GC
CSeq: 27840 SUBSCRIBE
Contact: <sip:305@PRIVATE_IP:44762>
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP1782 1.0.1.116
Expires: 60
Supported: replaces, path, timer, eventlist
Event: dialog
Accept: application/dialog-info+xml,multipart/related,application/rlmi+xml
Accept-Encoding: zlib+base64
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
2021/10/01 12:31:13.026561 PUBLIC_IP:8081 -> SITE_IP:44762
SIP/2.0 202 OK
Via: SIP/2.0/UDP PRIVATE_IP:44762;branch=z9hG4bK806864449;rport=44762;received=SITE_IP
From: <sip:305@domain.net:8081>;tag=1883014019
To: <sip:301@domain.net:8081>;tag=5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
Call-ID: 551473572-44762-6@BA.CEG.HG.GC
CSeq: 27840 SUBSCRIBE
Expires: 60
Contact: <sip:PUBLIC_IP:8081>
Server: kamailio (5.4.4 (x86_64/linux))
Content-Length: 0
2021/10/01 12:31:13.027436 PUBLIC_IP:8081 -> SITE_IP:44762
NOTIFY sip:305@PRIVATE_IP:44762 SIP/2.0
Via: SIP/2.0/UDP PUBLIC_IP:8081;branch=z9hG4bK2ba8.555213e5000000000000000000000000.0
To: <sip:305@domain.net>;tag=1883014019
From: <sip:301@domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
CSeq: 2 NOTIFY
Call-ID: 551473572-44762-6@BA.CEG.HG.GC
Content-Length: 273
User-Agent: kamailio (5.4.4 (x86_64/linux))
Max-Forwards: 70
Event: dialog
Contact: <sip:PUBLIC_IP:8081>
Subscription-State: active;expires=60
Content-Type: application/dialog-info+xml
<?xml version="1.0"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="1" state="full" entity="sip:301@domain.net">
<dialog id="615293b33c62dec073e05d9421e9f48b" direction="recipient"> <state>terminated</state> </dialog>
</dialog-info>
2021/10/01 12:31:13.332763 SITE_IP:44762 -> PUBLIC_IP:8081
SIP/2.0 481 Subscription Does Not Exist
Via: SIP/2.0/UDP PUBLIC_IP:8081;branch=z9hG4bK2ba8.555213e5000000000000000000000000.0
From: <sip:301@domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
To: <sip:305@domain.net>;tag=1883014019
Call-ID: 551473572-44762-6@BA.CEG.HG.GC
CSeq: 2 NOTIFY
Supported: replaces, path, timer
User-Agent: Grandstream GXP1782 1.0.1.116
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
--------------------------------
Now, I am sure it's not likely the phone setup as I have a FreeSWITCH system that these 6 phones normally talk to.
All i do is change the DNS A Record between the IP of the Kamailio server and the FreeSWITCH server... This way I don't touch the phone configs..
I just change the A Records and take an hour long break...
On the FreeSWITCH server, the phones do exactly as expected...
I am trying to stick the Kamailio server between the phones and FS but, one step at a time.
So, any thoughts as to why the GXP1782 BLFs are not accepting the NOTIFY messages?
Jerry
__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions
* sr-users@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
__________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions * sr-users@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
__________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions * sr-users@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