[SR-Users] BLFs are not working

Jerry Kendall Jerry.Kendall at BishopHosting.com
Sun Oct 3 01:58:03 CEST 2021


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 at domain.net:PORT SIP/2.0
Via: SIP/2.0/UDP 10.10.10.62:55318;branch=z9hG4bK89955442;rport
From: <sip:305 at domain.net:PORT>;tag=1703808353
To: <sip:301 at domain.net:PORT>
Call-ID: 2104033891-55318-6 at BA.CEG.HG.GC
CSeq: 86910 SUBSCRIBE
Contact: <sip:305 at 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 at domain.net:PORT>;tag=1703808353
To: <sip:301 at domain.net:PORT>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6
Call-ID: 2104033891-55318-6 at 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 at 10.10.10.62:55318 SIP/2.0
Via: SIP/2.0/UDP PUBLIC_IP:PORT;branch=z9hG4bKffd9.6b44c1b2000000000000000000000000.0
To: <sip:305 at domain.net>;tag=1703808353
From: <sip:301 at domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6
CSeq: 2 NOTIFY
Call-ID: 2104033891-55318-6 at 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 at 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 at domain.net:PORT SIP/2.0
Via: SIP/2.0/UDP 10.10.10.62:55318;branch=z9hG4bK1198306856;rport
From: <sip:305 at domain.net:PORT>;tag=998538926
To: <sip:301 at domain.net:PORT>
Call-ID: 2104033891-55318-6 at BA.CEG.HG.GC
CSeq: 86920 SUBSCRIBE
Contact: <sip:305 at 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 at domain.net:PORT>;tag=998538926
To: <sip:301 at domain.net:PORT>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6
Call-ID: 2104033891-55318-6 at 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 at 10.10.10.62:55318 SIP/2.0
Via: SIP/2.0/UDP PUBLIC_IP:PORT;branch=z9hG4bKffd9.40e91c22000000000000000000000000.0
To: <sip:305 at domain.net>;tag=998538926
From: <sip:301 at domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6
CSeq: 2 NOTIFY
Call-ID: 2104033891-55318-6 at 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 at 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



On 2021-10-02 7:07 p.m., Jerry Kendall wrote:
>
> 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 at PRIVATE_IP:55318 SIP/2.0
> Via: SIP/2.0/UDP 
> IP_ADDRESS:PORT;branch=z9hG4bKffd9.a74b11b5000000000000000000000000.0
> To: <sip:305 at domain.net>;tag=2001402711
> From: <sip:301 at domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-270107a6
> CSeq: 2 NOTIFY
> Call-ID: 2104033891-55318-6 at 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 at 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) [[SUBSCRIBEsip:301 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} <core> [core/dset.c:919]: uri_add_rcv_alias(): encoded<sip:305 at PRIVATE_IP:44762>  => [sip:305 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} presence [subscribe.c:1346]: extract_sdialog_info_ex(): 'To' header ALREADY PARSED:<sip:301 at domain.net:PORT>
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at 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 at 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 at BA.CEG.HG.GC} presence [subscribe.c:1452]: extract_sdialog_info_ex(): subs->contact=sip:305 at 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 at 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 at 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 at BA.CEG.HG.GC} presence [notify.c:127]: printf_subs(): pres_uri:sip:301 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:128]: printf_subs(): watcher_user at watcher_domain:305 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:131]: printf_subs(): to_user at to_domain:301 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:133]: printf_subs(): from_user at from_domain:305 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:135]: printf_subs(): callid/from_tag/to_tag:551473572-44762-6 at BA.CEG.HG.GC/138358676/5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at 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 at BA.CEG.HG.GC} presence [notify.c:140]: printf_subs(): local_contact/contact:sip:PUBLIC_IP:PORT/sip:305 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} presence [notify.c:127]: printf_subs(): pres_uri:sip:301 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:128]: printf_subs(): watcher_user at watcher_domain:305 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:131]: printf_subs(): to_user at to_domain:301 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:133]: printf_subs(): from_user at from_domain:305 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at BA.CEG.HG.GC} presence [notify.c:135]: printf_subs(): callid/from_tag/to_tag:551473572-44762-6 at BA.CEG.HG.GC/138358676/5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at 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 at BA.CEG.HG.GC} presence [notify.c:140]: printf_subs(): local_contact/contact:sip:PUBLIC_IP:PORT/sip:305 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} presence [hash.c:522]: search_phtable(): pres_uri=sip:301 at domain.net
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: DEBUG: {1 21000 SUBSCRIBE551473572-44762-6 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} presence [notify.c:1131]: ps_build_dlg_t(): CONTACT =sip:305 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} <core> [core/dset.c:1026]: uri_restore_rcv_alias(): decoded<sip:305 at PRIVATE_IP:44762;alias=184.148.140.29~44762~1>  => [sip:305 at 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 at 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 at 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 at 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 at 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 at BA.CEG.HG.GC} presence [notify.c:1737]: send_notify_request(): NOTIFYsip:305 at domain.net  via on behalf ofsip:301 at domain.net  for event dialog :551473572-44762-6 at BA.CEG.HG.GC
>> Oct  1 11:31:37 Kam01 /usr/sbin/kamailio[15920]: exec:  {1 21000 SUBSCRIBE551473572-44762-6 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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:
>>> 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 at domain.net:8081 SIP/2.0
>>> Via: SIP/2.0/UDP PRIVATE_IP:44762;branch=z9hG4bK806864449;rport
>>> From: <sip:305 at domain.net:8081>;tag=1883014019
>>> To: <sip:301 at domain.net:8081>
>>> Call-ID: 551473572-44762-6 at BA.CEG.HG.GC
>>> CSeq: 27840 SUBSCRIBE
>>> Contact: <sip:305 at 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 at domain.net:8081>;tag=1883014019
>>> To: 
>>> <sip:301 at domain.net:8081>;tag=5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
>>> Call-ID: 551473572-44762-6 at 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 at PRIVATE_IP:44762 SIP/2.0
>>> Via: SIP/2.0/UDP 
>>> PUBLIC_IP:8081;branch=z9hG4bK2ba8.555213e5000000000000000000000000.0
>>> To: <sip:305 at domain.net>;tag=1883014019
>>> From: 
>>> <sip:301 at domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
>>> CSeq: 2 NOTIFY
>>> Call-ID: 551473572-44762-6 at 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 at 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 at domain.net>;tag=5e1ee053cf7168b9d3ee9c05740f837c-eb6836a8
>>> To: <sip:305 at domain.net>;tag=1883014019
>>> Call-ID: 551473572-44762-6 at 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 at 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 at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20211002/0d4d7325/attachment.htm>


More information about the sr-users mailing list