INVITE received but extensions not responding/connecting overtime

General Help
1

Hi, i’ve been trying to setup a small FreePBX system and have mostly got it going after many bumps in the road.

My issue is that, apparently randomly, incoming calls hit the PBX, i get the INVITE listed in sngrp but the extensions(?) don’t connect or respond…
I have two Yealink phones.

A lot of the time the calls are fine and they go thru ok.

I’ve messed around with firewalls / port forwarding /NAT etc and nothing seems to make a difference.
Always seems to be random.

How can i dig down further into this problem?
Any help would be appreciated, feel like i’m going mad!

Here’s one of the INVITE requests:- 192.168.20.10 is the PBX server internal to my network.

`2025/02/13 15:02:20.573469 xx.xxx.xx.116:5060 → 192.168.20.10:5060
INVITE sip:[email protected]:5060;line=zckdunx SIP/2.0
Via: SIP/2.0/UDP xx.xxx.xx.116;branch=z9hG4bK2025021315021600009-1;rport
CSeq: 1 INVITE
Max-Forwards: 67
User-Agent: FireBrick/2.01.111
Call-ID: 2025021315021600009@2900-0601-0284-92
From: “Anonymous” sip:[email protected];tag=2025021315021600009
To: sip:[email protected]:5060;line=zckdunx
Contact: sip:[email protected]
Content-Type: application/sdp
Content-Length: 188

v=0
o=- 27530 0 IN IP4 xx.xxx.xx.116
s=call
c=IN IP4 xx.xxx.xx.116
t=0 0
m=audio 27530 RTP/AVP 8 101
a=rtpmap:8 pcma/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=sendrecv
`

2

I suspect you have a SIP ALG (application level gateway) in your router. These mainly don’t work and should be disabled.

I don’t see any logging of Asterisk;'s responses, or the dialplan execution.

3

There’s no SIP ALG on our network.

User-Agent: FireBrick/2.01.111

Is on our SIP trunk providers network i believe.

How do i see these?
thanks!

4

It also sounds similar like my thread… Without any resolution yet.

Do you see the call arriving in asterisk -rvvvvvvvvv ?

5

I wasn’t but i’ve now turned debugging on in shell, even tho it was already set to on in the GUI…

But typically, now i can see the logs, the calls are connecting ok…

The logs showing up the asterisk CLI seem to be exactly the same as those in sngrep tho?

6

Possibly my extensions aren’t connected properly despite reporting registered in the Freepbx GUI?

Received SIP request (455 bytes) from UDP:192.168.20.6:5060 --->
SUBSCRIBE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.6:5060;branch=z9hG4bK822737078
From: "Studio1" <sip:[email protected]:5060>;tag=822574227
To: <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Accept: application/simple-message-summary
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 3600
Event: message-summary
Content-Length: 0


<--- Transmitting SIP response (479 bytes) to UDP:192.168.20.6:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.20.6:5060;rport=5060;received=192.168.20.6;branch=z9hG4bK822737078
Call-ID: [email protected]
From: "Studio1" <sip:[email protected]>;tag=822574227
To: <sip:[email protected]>;tag=z9hG4bK822737078
CSeq: 1 SUBSCRIBE
WWW-Authenticate: Digest realm="asterisk",nonce="1739471238/3f3b0ddc08e7e72a3028fc0c09110857",opaque="7a40b5807635f36c",algorithm=MD5,qop="auth"
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP request (728 bytes) from UDP:192.168.20.6:5060 --->
SUBSCRIBE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.6:5060;branch=z9hG4bK822840272
From: "Studio1" <sip:[email protected]:5060>;tag=822574227
To: <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 2 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Authorization: Digest username="101", realm="asterisk", nonce="1739471238/3f3b0ddc08e7e72a3028fc0c09110857", uri="sip:[email protected]:5060", response="874513e82216ae46b71a6b651ba14dd8", algorithm=MD5, cnonce="822895289", opaque="7a40b5807635f36c", qop=auth, nc=00000001
Accept: application/simple-message-summary
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 3600
Event: message-summary
Content-Length: 0


<--- Transmitting SIP response (330 bytes) to UDP:192.168.20.6:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.20.6:5060;rport=5060;received=192.168.20.6;branch=z9hG4bK822840272
Call-ID: [email protected]
From: "Studio1" <sip:[email protected]>;tag=822574227
To: <sip:[email protected]>;tag=z9hG4bK822840272
CSeq: 2 SUBSCRIBE
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Transmitting SIP request (422 bytes) to UDP:192.168.20.6:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPja1665132-a3bb-46ef-b120-d7d693812fa3
From: <sip:[email protected]>;tag=86ba4856-8bd8-4b86-a56b-88e8063f29a7
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 1b46ea01-374e-4279-935f-8b98b7a25d8c
CSeq: 7773 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (360 bytes) from UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPja1665132-a3bb-46ef-b120-d7d693812fa3
From: <sip:[email protected]>;tag=86ba4856-8bd8-4b86-a56b-88e8063f29a7
To: <sip:[email protected]>;tag=822977133
Call-ID: 1b46ea01-374e-4279-935f-8b98b7a25d8c
CSeq: 7773 OPTIONS
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


<--- Received SIP request (455 bytes) from UDP:192.168.20.6:5060 --->
SUBSCRIBE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.6:5060;branch=z9hG4bK823185051
From: "Studio1" <sip:[email protected]:5060>;tag=823047361
To: <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Accept: application/simple-message-summary
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 3600
Event: message-summary
Content-Length: 0


<--- Transmitting SIP response (479 bytes) to UDP:192.168.20.6:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.20.6:5060;rport=5060;received=192.168.20.6;branch=z9hG4bK823185051
Call-ID: [email protected]
From: "Studio1" <sip:[email protected]>;tag=823047361
To: <sip:[email protected]>;tag=z9hG4bK823185051
CSeq: 1 SUBSCRIBE
WWW-Authenticate: Digest realm="asterisk",nonce="1739471268/e6076c6afd5cdd4d2611c676941968b4",opaque="031f17f97b239301",algorithm=MD5,qop="auth"
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP request (728 bytes) from UDP:192.168.20.6:5060 --->
SUBSCRIBE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.6:5060;branch=z9hG4bK823304983
From: "Studio1" <sip:[email protected]:5060>;tag=823047361
To: <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 2 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Authorization: Digest username="101", realm="asterisk", nonce="1739471268/e6076c6afd5cdd4d2611c676941968b4", uri="sip:[email protected]:5060", response="a350d6a96d5b27683edf85b57925eed9", algorithm=MD5, cnonce="823343665", opaque="031f17f97b239301", qop=auth, nc=00000001
Accept: application/simple-message-summary
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 3600
Event: message-summary
Content-Length: 0


<--- Transmitting SIP response (330 bytes) to UDP:192.168.20.6:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.20.6:5060;rport=5060;received=192.168.20.6;branch=z9hG4bK823304983
Call-ID: [email protected]
From: "Studio1" <sip:[email protected]>;tag=823047361
To: <sip:[email protected]>;tag=z9hG4bK823304983
CSeq: 2 SUBSCRIBE
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0
7

That’s a SUBSCRIBE message for MWI, do you have a voicemail setup for 101?

8

I don’t have voicemail setup for 101 but a group voicemail for all extensions.

9

The output you showed is the phone trying to subscribe to MWI for mailbox 101. Turn that off in the phone, those go away.

We need to see what happens when a call actually attempts to call the extension.

10

So here’s a log from a non working call.

Now my local SIP ports on my phones are set to the same as the PBX server 5060, that’s correct right? Same as the ‘listen’ ports on FreePBX server.


<--- Received SIP response (359 bytes) from UDP:xx.xxx.xx.116:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;received=xxx.xxx.xx.98;rport=5060;branch=z9hG4bKPj04b9026c-4dbd-4c8e-a47b-8b1d94d156cb
CSeq: 11433 OPTIONS
Call-ID: df8a50a5-5bfb-43b6-9b58-dd617dd56369
From: <sip:[email protected]>;tag=75c935f9-4b84-4121-aea3-5b019dac7244
To: <sip:[email protected]>
Content-Length: 0


<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.9:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPjef70c324-1aac-4adb-9c58-835d78920e83
From: <sip:[email protected]>;tag=75a60fcd-6b18-42a3-a4f9-e1909d114a85
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 30edbbf5-22f0-4d06-a1c3-c2e593ec5710
CSeq: 16583 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0




<--- Transmitting SIP request (422 bytes) to UDP:192.168.20.7:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj10df4c67-10ad-490a-b3a5-41ab0756d7b4
From: <sip:[email protected]>;tag=ac8d8b54-e07d-48e6-bb12-6794e3f03329
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 5bba4781-35bd-4d71-bd80-57e587aae2d9
CSeq: 4584 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (360 bytes) from UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPj10df4c67-10ad-490a-b3a5-41ab0756d7b4
From: <sip:[email protected]>;tag=ac8d8b54-e07d-48e6-bb12-6794e3f03329
To: <sip:[email protected]>;tag=658832702
Call-ID: 5bba4781-35bd-4d71-bd80-57e587aae2d9
CSeq: 4584 OPTIONS
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.6:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPjb036bd56-ae1f-4500-bcab-8e2d91bac639
From: <sip:[email protected]>;tag=e5ea4104-612a-4f60-84a4-c7bbbe4e365f
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: c860db20-1360-4572-88c1-8e3d62787bdd
CSeq: 39500 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (361 bytes) from UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPjb036bd56-ae1f-4500-bcab-8e2d91bac639
From: <sip:[email protected]>;tag=e5ea4104-612a-4f60-84a4-c7bbbe4e365f
To: <sip:[email protected]>;tag=658660032
Call-ID: c860db20-1360-4572-88c1-8e3d62787bdd
CSeq: 39500 OPTIONS
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


<--- Transmitting SIP request (483 bytes) to UDP:xx.xxx.xx.118:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;rport;branch=z9hG4bKPj0e140396-c83b-4b08-aa37-99961527d89c
From: <sip:[email protected]>;tag=20aad1b7-82f2-429d-b9c5-82457243d200
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: fd0d4935-42a5-4eab-90ea-5814f5b13303
CSeq: 26309 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (359 bytes) from UDP:xx.xxx.xx.118:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;received=xxx.xxx.xx.98;rport=5060;branch=z9hG4bKPj0e140396-c83b-4b08-aa37-99961527d89c
CSeq: 26309 OPTIONS
Call-ID: fd0d4935-42a5-4eab-90ea-5814f5b13303
From: <sip:[email protected]>;tag=20aad1b7-82f2-429d-b9c5-82457243d200
To: <sip:[email protected]>
Content-Length: 0


<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.9:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj1594f295-4b43-411c-a97a-f8175e398d26
From: <sip:[email protected]>;tag=07c450f0-c632-4932-b5b5-1772266855c9
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 2a2594c8-36b5-4bd3-8ef8-f8ae3f549d39
CSeq: 21610 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0




<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.7:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj20bd0e66-625c-44b0-9dc9-dc7071d26874
From: <sip:[email protected]>;tag=9a4b33c6-b104-4c32-9aa4-80af4a850276
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 12844680-2524-4ef5-b53b-c1b2fad5e786
CSeq: 26694 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (361 bytes) from UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPj20bd0e66-625c-44b0-9dc9-dc7071d26874
From: <sip:[email protected]>;tag=9a4b33c6-b104-4c32-9aa4-80af4a850276
To: <sip:[email protected]>;tag=658894366
Call-ID: 12844680-2524-4ef5-b53b-c1b2fad5e786
CSeq: 26694 OPTIONS
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0

Sngrep
      ^Idx Method     SIP From                  SIP To                     Msgs  Source                 Destination            Call State
  [ ] 385  INVITE     [email protected] [email protected] 12    xx.xxx.xx.118:5060     192.168.20.10:5060     CANCELLED

  [ ] 387  OPTIONS    [email protected]         [email protected]           2     192.168.20.10:5060     192.168.20.7:5060
  [ ] 388  OPTIONS    [email protected]         [email protected]           2     192.168.20.10:5060     192.168.20.6:5060
  [ ] 389  OPTIONS    [email protected]. +441234567891@trunkprovider   2     192.168.20.10:5060     xx.xxx.xx.118:5060
 
  [ ] 391  OPTIONS    [email protected]         [email protected]           2     192.168.20.10:5060     192.168.20.7:5060
  [ ] 392  OPTIONS    [email protected]         [email protected]           2     192.168.20.10:5060     192.168.20.6:5060
11

We need to see the verbose call log from the console. This doesn’t show what happens within Asterisk. It very well could be rejecting the call because it comes from anonymous.

12

Sorry, how do i access that?
I’ll work it out…

I don’t think it’s rejected for anonymous as it works some of the time. I’m always testing from our existing ‘id withheld line’ BT line.

13

Is this it?



[2025-02-14 14:14:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:516 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=59853 (rdata0x7f4c001518).  Using request transaction as basis.
[2025-02-14 14:14:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:124 find_request_serializer: Found transaction tsx0x55947a9b38 for Response msg 200/OPTIONS/cseq=59853 (rdata0x7f4c001518).
[2025-02-14 14:14:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:134 find_request_serializer: Found serializer pjsip/options/101-0000003e on transaction tsx0x55947a9b38
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip.c:1594 endpt_send_request_cb: 0x5594592ec8: PJSIP tsx response received
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip.c:1607 endpt_send_request_cb: 0x5594592ec8: Cancelling timer
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip.c:1616 endpt_send_request_cb: 0x5594592ec8: Timer cancelled
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip.c:1637 endpt_send_request_cb: 0x5594592ec8: Callbacks executed
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x5594592ec8: wrapper destroyed
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact 101/sip:[email protected]:5060 status didn't change: Reachable, RTT: 7.689 msec
[2025-02-14 14:14:31] DEBUG[1301]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR '101' now has 1 available contacts
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_options.c:929 sip_options_qualify_aor: Qualifying all contacts on AOR 'MY-COMPANY_Trunk'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_options.c:858 sip_options_qualify_contact: Qualifying contact 'MY-COMPANY_Trunk@@29c3ad128c862377466a8bf738860b74' on AOR 'MY-COMPANY_Trunk'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1716 endpt_send_request: 0x55940cadc8: Wrapper created
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1731 endpt_send_request: 0x55940cadc8: Set timer to 3000 msec
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target 'trunkprovider.net.uk'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target 'trunkprovider.net.uk' is 'UDP transport'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:545 sip_resolve: [0x5594558b38] Created resolution tracking for target 'trunkprovider.net.uk'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:174 sip_resolve_add: [0x5594558b38] Added target 'trunkprovider.net.uk' with record type '1', transport 'UDP transport', and port '5060'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:616 sip_resolve: [0x5594558b38] Starting initial resolution using parallel queries for target 'trunkprovider.net.uk'
[2025-02-14 14:14:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:273 sip_resolve_callback: [0x5594558b38] All parallel queries completed
[2025-02-14 14:14:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:322 sip_resolve_callback: [0x5594558b38] A record received on target 'trunkprovider.net.uk'
[2025-02-14 14:14:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:322 sip_resolve_callback: [0x5594558b38] A record received on target 'trunkprovider.net.uk'
[2025-02-14 14:14:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:417 sip_resolve_callback: [0x5594558b38] Resolution completed - 2 viable targets
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:199 sip_resolve_invoke_user_callback: [0x5594558b38] Address '0' is xx.xxx.xx.116:5060 with transport 'UDP transport'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:199 sip_resolve_invoke_user_callback: [0x5594558b38] Address '1' is xx.xxx.xx.118:5060 with transport 'UDP transport'
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:205 sip_resolve_invoke_user_callback: [0x5594558b38] Invoking user callback with '2' addresses
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:14:33] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'xx.xxx.xx.116' into...
[2025-02-14 14:14:33] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'xx.xxx.xx.116' and port ''.
<--- Transmitting SIP request (483 bytes) to UDP:xx.xxx.xx.116:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;rport;branch=z9hG4bKPjceb6c2b3-e945-4c77-a736-4b649559c90b
From: <sip:[email protected]>;tag=39be344e-9631-432f-a2b0-98f026693149
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 8b080e1b-b1c7-4030-b09c-808d0c61b0fb
CSeq: 27563 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (359 bytes) from UDP:xx.xxx.xx.116:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;received=xxx.xxx.xx.98;rport=5060;branch=z9hG4bKPjceb6c2b3-e945-4c77-a736-4b649559c90b
CSeq: 27563 OPTIONS
Call-ID: 8b080e1b-b1c7-4030-b09c-808d0c61b0fb
From: <sip:[email protected]>;tag=39be344e-9631-432f-a2b0-98f026693149
To: <sip:[email protected]>
Content-Length: 0


[2025-02-14 14:14:33] DEBUG[1300]: res_pjsip/pjsip_distributor.c:516 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=27563 (rdata0x7f4c001518).  Using request transaction as basis.
[2025-02-14 14:14:33] DEBUG[1300]: res_pjsip/pjsip_distributor.c:124 find_request_serializer: Found transaction tsx0x559456d788 for Response msg 200/OPTIONS/cseq=27563 (rdata0x7f4c001518).
[2025-02-14 14:14:33] DEBUG[1300]: res_pjsip/pjsip_distributor.c:134 find_request_serializer: Found serializer pjsip/options/MY-COMPANY_Trunk-00000041 on transaction tsx0x559456d788
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1594 endpt_send_request_cb: 0x55940cadc8: PJSIP tsx response received
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1607 endpt_send_request_cb: 0x55940cadc8: Cancelling timer
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1616 endpt_send_request_cb: 0x55940cadc8: Timer cancelled
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1637 endpt_send_request_cb: 0x55940cadc8: Callbacks executed
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x55940cadc8: wrapper destroyed
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact MY-COMPANY_Trunk/sip:[email protected]:5060 status didn't change: Reachable, RTT: 12.899 msec
[2025-02-14 14:14:33] DEBUG[1301]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR 'MY-COMPANY_Trunk' now has 1 available contacts
[2025-02-14 14:14:33] DEBUG[12200]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:37] DEBUG[12205]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:40] DEBUG[12210]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:43] DEBUG[12215]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:46] DEBUG[12220]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:47] DEBUG[1315]: res_pjsip_registrar.c:1377 check_expiration_thread: Woke up at 1739542487  Interval: 30
[2025-02-14 14:14:47] DEBUG[1315]: res_pjsip_registrar.c:1384 check_expiration_thread: Expiring 0 contacts
[2025-02-14 14:14:49] DEBUG[12225]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:52] DEBUG[12230]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:55] DEBUG[12235]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:14:58] DEBUG[12240]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:01] DEBUG[12256]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:01] DEBUG[12260]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:01] DEBUG[12257]: config.c:4018 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:4018 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:4018 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:4018 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:4018 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:4018 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2025-02-14 14:15:01] DEBUG[12257]: config.c:3931 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0)
[2025-02-14 14:15:01] DEBUG[12257]: manager.c:7022 process_message: Running action 'Command'
[2025-02-14 14:15:04] DEBUG[12314]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:07] DEBUG[12320]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:10] DEBUG[12325]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:13] DEBUG[12330]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:16] DEBUG[12335]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:17] DEBUG[1315]: res_pjsip_registrar.c:1377 check_expiration_thread: Woke up at 1739542517  Interval: 30
[2025-02-14 14:15:17] DEBUG[1315]: res_pjsip_registrar.c:1384 check_expiration_thread: Expiring 0 contacts
[2025-02-14 14:15:19] DEBUG[12340]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_options.c:929 sip_options_qualify_aor: Qualifying all contacts on AOR '200'
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_options.c:858 sip_options_qualify_contact: Qualifying contact '200;@77706a01b066e6eb2046742769d21817' on AOR '200'
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1716 endpt_send_request: 0x55940caaf8: Wrapper created
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1731 endpt_send_request: 0x55940caaf8: Set timer to 3000 msec
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.9'
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.9' is 'UDP transport'
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.9' is an IP address, skipping resolution
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:21] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.9' into...
[2025-02-14 14:15:21] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.9' and port ''.
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.9:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPjde5d9da4-000d-475e-801b-2c02275aabb4
From: <sip:[email protected]>;tag=51ed3e62-bf51-442a-9fcb-fb8ff139f69e
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 48dcd359-8acf-42d4-a2bb-0bfb39ed9782
CSeq: 55737 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (488 bytes) from UDP:192.168.20.9:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPjde5d9da4-000d-475e-801b-2c02275aabb4
From: <sip:[email protected]>;tag=51ed3e62-bf51-442a-9fcb-fb8ff139f69e
To: <sip:[email protected]>;tag=462683414
Call-ID: 48dcd359-8acf-42d4-a2bb-0bfb39ed9782
CSeq: 55737 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GDS3712 1.0.11.15
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


[2025-02-14 14:15:21] DEBUG[1300]: res_pjsip/pjsip_distributor.c:516 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=55737 (rdata0x7f4c001518).  Using request transaction as basis.
[2025-02-14 14:15:21] DEBUG[1300]: res_pjsip/pjsip_distributor.c:124 find_request_serializer: Found transaction tsx0x559456d788 for Response msg 200/OPTIONS/cseq=55737 (rdata0x7f4c001518).
[2025-02-14 14:15:21] DEBUG[1300]: res_pjsip/pjsip_distributor.c:134 find_request_serializer: Found serializer pjsip/options/200-0000003f on transaction tsx0x559456d788
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1594 endpt_send_request_cb: 0x55940caaf8: PJSIP tsx response received
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1607 endpt_send_request_cb: 0x55940caaf8: Cancelling timer
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1616 endpt_send_request_cb: 0x55940caaf8: Timer cancelled
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1637 endpt_send_request_cb: 0x55940caaf8: Callbacks executed
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x55940caaf8: wrapper destroyed
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact 200/sip:[email protected]:5060 status didn't change: Reachable, RTT: 5.150 msec
[2025-02-14 14:15:21] DEBUG[1301]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR '200' now has 1 available contacts
[2025-02-14 14:15:23] DEBUG[12345]: manager.c:7022 process_message: Running action 'Login'
<--- Received SIP request (744 bytes) from UDP:192.168.20.7:5060 --->
SUBSCRIBE sip:192.168.20.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.7:5060;branch=z9hG4bK661399485;rport
From: "Studio3" <sip:[email protected]>;tag=657375181
To: <sip:*[email protected]>;tag=3c8656f5-4d65-4523-a70c-03393f65b328
Call-ID: [email protected]
CSeq: 4 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Authorization: Digest username="103", realm="asterisk", nonce="1739540127/57f5cbc781258ea1e746a58edf9a6906", uri="sip:192.168.20.10:5060", response="929888d3441bbe91a6f5c42946d62f49", algorithm=MD5, cnonce="657726854", opaque="3f21fe4700563753", qop=auth, nc=00000003
Accept: application/dialog-info+xml
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 1800
Event: dialog
Content-Length: 0


[2025-02-14 14:15:24] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x5594564ea8 for Request msg SUBSCRIBE/cseq=4 (rdata0x7f4c001518)
[2025-02-14 14:15:24] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-0000003b associated with dialog dlg0x5594564ea8
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_pubsub.c:4082 pubsub_on_rx_refresh: evsub 0x5594049bc0 sub_tree 0x5593f0d2e8 sub_tree state Normal
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '103->*98600'  prune on boot: no
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_pubsub.c:3965 pubsub_on_refresh_timeout: sub_tree 0x5593f0d2e8 sub_tree state Normal
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '103->*98600'  prune on boot: no
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:24] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.7' into...
[2025-02-14 14:15:24] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.7' and port ''.
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP response (561 bytes) to UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.7:5060;rport=5060;received=192.168.20.7;branch=z9hG4bK661399485
Call-ID: [email protected]
From: "Studio3" <sip:[email protected]>;tag=657375181
To: <sip:*[email protected]>;tag=3c8656f5-4d65-4523-a70c-03393f65b328
CSeq: 4 SUBSCRIBE
Expires: 1800
Contact: <sip:192.168.20.10:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, INFO, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.7'
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.7' is 'UDP transport'
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.7' is an IP address, skipping resolution
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:24] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.7' into...
[2025-02-14 14:15:24] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.7' and port ''.
[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (826 bytes) to UDP:192.168.20.7:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPjebcc8f97-183d-46a1-91b9-ce1767396b5f
From: <sip:*[email protected]>;tag=3c8656f5-4d65-4523-a70c-03393f65b328
To: "Studio3" <sip:[email protected]>;tag=657375181
Contact: <sip:192.168.20.10:5060>
Call-ID: [email protected]
CSeq: 8693 NOTIFY
Event: dialog
Subscription-State: active;expires=1799
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Type: application/dialog-info+xml
Content-Length:   236

<?xml version="1.0" encoding="UTF-8"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="0" state="full" entity="sip:*[email protected]:5060">
 <dialog id="*98600">
  <state>terminated</state>
 </dialog>
</dialog-info>

[2025-02-14 14:15:24] DEBUG[1301]: res_pjsip_pubsub.c:3927 pubsub_on_evsub_state: evsub 0x5594049bc0 state ACTIVE event USER sub_tree 0x5593f0d2e8 sub_tree state Normal
<--- Received SIP response (399 bytes) from UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPjebcc8f97-183d-46a1-91b9-ce1767396b5f
From: <sip:*[email protected]>;tag=3c8656f5-4d65-4523-a70c-03393f65b328
To: "Studio3" <sip:[email protected]>;tag=657375181
Call-ID: [email protected]
CSeq: 8693 NOTIFY
Contact: <sip:[email protected]:5060>
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


[2025-02-14 14:15:24] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x5594564ea8 for Response msg 200/NOTIFY/cseq=8693 (rdata0x7f4c001518)
[2025-02-14 14:15:24] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-0000003b associated with dialog dlg0x5594564ea8
<--- Received SIP request (741 bytes) from UDP:192.168.20.7:5060 --->
SUBSCRIBE sip:192.168.20.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.7:5060;branch=z9hG4bK661672406;rport
From: "Studio3" <sip:[email protected]>;tag=656423480
To: <sip:[email protected]>;tag=d9a9c657-1b27-4cf5-bcb3-32ee72d2180a
Call-ID: [email protected]
CSeq: 4 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Authorization: Digest username="103", realm="asterisk", nonce="1739540127/57f5cbc781258ea1e746a58edf9a6906", uri="sip:192.168.20.10:5060", response="1d2bfcb54f10d1d83c7cdf6a22483b6f", algorithm=MD5, cnonce="657123066", opaque="4d26bfcf15b1e34b", qop=auth, nc=00000003
Accept: application/dialog-info+xml
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 1800
Event: dialog
Content-Length: 0


[2025-02-14 14:15:25] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x559456b3a8 for Request msg SUBSCRIBE/cseq=4 (rdata0x7f4c001518)
[2025-02-14 14:15:25] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-0000002b associated with dialog dlg0x559456b3a8
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_pubsub.c:4082 pubsub_on_rx_refresh: evsub 0x559480d9e0 sub_tree 0x559402ab58 sub_tree state Normal
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '103->101'  prune on boot: no
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_pubsub.c:3965 pubsub_on_refresh_timeout: sub_tree 0x559402ab58 sub_tree state Normal
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '103->101'  prune on boot: no
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:25] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.7' into...
[2025-02-14 14:15:25] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.7' and port ''.
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP response (558 bytes) to UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.7:5060;rport=5060;received=192.168.20.7;branch=z9hG4bK661672406
Call-ID: [email protected]
From: "Studio3" <sip:[email protected]>;tag=656423480
To: <sip:[email protected]>;tag=d9a9c657-1b27-4cf5-bcb3-32ee72d2180a
CSeq: 4 SUBSCRIBE
Expires: 1800
Contact: <sip:192.168.20.10:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, INFO, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.7'
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.7' is 'UDP transport'
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.7' is an IP address, skipping resolution
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:25] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.7' into...
[2025-02-14 14:15:25] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.7' and port ''.
[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (818 bytes) to UDP:192.168.20.7:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPjc0b963ab-944b-440e-a936-3a848a509832
From: <sip:[email protected]>;tag=d9a9c657-1b27-4cf5-bcb3-32ee72d2180a
To: "Studio3" <sip:[email protected]>;tag=656423480
Contact: <sip:192.168.20.10:5060>
Call-ID: [email protected]
CSeq: 27881 NOTIFY
Event: dialog
Subscription-State: active;expires=1799
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Type: application/dialog-info+xml
Content-Length:   230

<?xml version="1.0" encoding="UTF-8"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="5" state="full" entity="sip:[email protected]:5060">
 <dialog id="101">
  <state>terminated</state>
 </dialog>
</dialog-info>

[2025-02-14 14:15:25] DEBUG[1301]: res_pjsip_pubsub.c:3927 pubsub_on_evsub_state: evsub 0x559480d9e0 state ACTIVE event USER sub_tree 0x559402ab58 sub_tree state Normal
<--- Received SIP response (397 bytes) from UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPjc0b963ab-944b-440e-a936-3a848a509832
From: <sip:[email protected]>;tag=d9a9c657-1b27-4cf5-bcb3-32ee72d2180a
To: "Studio3" <sip:[email protected]>;tag=656423480
Call-ID: [email protected]
CSeq: 27881 NOTIFY
Contact: <sip:[email protected]:5060>
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


[2025-02-14 14:15:25] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x559456b3a8 for Response msg 200/NOTIFY/cseq=27881 (rdata0x7f4c001518)
[2025-02-14 14:15:25] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-0000002b associated with dialog dlg0x559456b3a8
[2025-02-14 14:15:26] DEBUG[12350]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_options.c:929 sip_options_qualify_aor: Qualifying all contacts on AOR '103'
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_options.c:858 sip_options_qualify_contact: Qualifying contact '103;@6390a3e492851b9cf68bd89b10a33653' on AOR '103'
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1716 endpt_send_request: 0x559455c378: Wrapper created
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1731 endpt_send_request: 0x559455c378: Set timer to 3000 msec
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.7'
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.7' is 'UDP transport'
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.7' is an IP address, skipping resolution
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:27] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.7' into...
[2025-02-14 14:15:27] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.7' and port ''.
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.7:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj2510dab9-8216-4b7e-bf65-f1230b0727c8
From: <sip:[email protected]>;tag=a6041d3e-62c3-4682-a7a5-ea8cd274424d
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 9e341d5e-53f6-476f-959e-4af72554147b
CSeq: 54244 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (361 bytes) from UDP:192.168.20.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPj2510dab9-8216-4b7e-bf65-f1230b0727c8
From: <sip:[email protected]>;tag=a6041d3e-62c3-4682-a7a5-ea8cd274424d
To: <sip:[email protected]>;tag=661929552
Call-ID: 9e341d5e-53f6-476f-959e-4af72554147b
CSeq: 54244 OPTIONS
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


[2025-02-14 14:15:27] DEBUG[1300]: res_pjsip/pjsip_distributor.c:516 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=54244 (rdata0x7f4c001518).  Using request transaction as basis.
[2025-02-14 14:15:27] DEBUG[1300]: res_pjsip/pjsip_distributor.c:124 find_request_serializer: Found transaction tsx0x559456d788 for Response msg 200/OPTIONS/cseq=54244 (rdata0x7f4c001518).
[2025-02-14 14:15:27] DEBUG[1300]: res_pjsip/pjsip_distributor.c:134 find_request_serializer: Found serializer pjsip/options/103-00000040 on transaction tsx0x559456d788
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1594 endpt_send_request_cb: 0x559455c378: PJSIP tsx response received
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1607 endpt_send_request_cb: 0x559455c378: Cancelling timer
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1616 endpt_send_request_cb: 0x559455c378: Timer cancelled
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1637 endpt_send_request_cb: 0x559455c378: Callbacks executed
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x559455c378: wrapper destroyed
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact 103/sip:[email protected]:5060 status didn't change: Reachable, RTT: 5.750 msec
[2025-02-14 14:15:27] DEBUG[1301]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR '103' now has 1 available contacts
[2025-02-14 14:15:29] DEBUG[12355]: manager.c:7022 process_message: Running action 'Login'
<--- Received SIP request (744 bytes) from UDP:192.168.20.6:5060 --->
SUBSCRIBE sip:192.168.20.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.6:5060;branch=z9hG4bK661805714;rport
From: "Studio1" <sip:[email protected]>;tag=657306061
To: <sip:*[email protected]>;tag=d5532b60-5fc8-49f1-9790-11389c978da8
Call-ID: [email protected]
CSeq: 4 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Authorization: Digest username="101", realm="asterisk", nonce="1739540133/793dc7cda616f2aaf2ee6264edfbf3dc", uri="sip:192.168.20.10:5060", response="ade360a9e9be60caab4080b7bd2cd31f", algorithm=MD5, cnonce="657712174", opaque="6175722e10fe2863", qop=auth, nc=00000003
Accept: application/dialog-info+xml
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 1800
Event: dialog
Content-Length: 0
14 


[2025-02-14 14:15:30] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x5594181d68 for Request msg SUBSCRIBE/cseq=4 (rdata0x7f4c001518)
[2025-02-14 14:15:30] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-00000025 associated with dialog dlg0x5594181d68
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_pubsub.c:4082 pubsub_on_rx_refresh: evsub 0x55947a4580 sub_tree 0x5593ecccd8 sub_tree state Normal
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '101->*98600'  prune on boot: no
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_pubsub.c:3965 pubsub_on_refresh_timeout: sub_tree 0x5593ecccd8 sub_tree state Normal
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '101->*98600'  prune on boot: no
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:30] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.6' into...
[2025-02-14 14:15:30] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.6' and port ''.
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP response (561 bytes) to UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.6:5060;rport=5060;received=192.168.20.6;branch=z9hG4bK661805714
Call-ID: [email protected]
From: "Studio1" <sip:[email protected]>;tag=657306061
To: <sip:*[email protected]>;tag=d5532b60-5fc8-49f1-9790-11389c978da8
CSeq: 4 SUBSCRIBE
Expires: 1800
Contact: <sip:192.168.20.10:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, INFO, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.6'
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.6' is 'UDP transport'
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.6' is an IP address, skipping resolution
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:30] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.6' into...
[2025-02-14 14:15:30] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.6' and port ''.
[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (826 bytes) to UDP:192.168.20.6:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj2f7c7cea-72ea-4cbf-8ac0-0d38cef8ce10
From: <sip:*[email protected]>;tag=d5532b60-5fc8-49f1-9790-11389c978da8
To: "Studio1" <sip:[email protected]>;tag=657306061
Contact: <sip:192.168.20.10:5060>
Call-ID: [email protected]
CSeq: 2872 NOTIFY
Event: dialog
Subscription-State: active;expires=1799
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Type: application/dialog-info+xml
Content-Length:   236

<?xml version="1.0" encoding="UTF-8"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="0" state="full" entity="sip:*[email protected]:5060">
 <dialog id="*98600">
  <state>terminated</state>
 </dialog>
</dialog-info>

[2025-02-14 14:15:30] DEBUG[1301]: res_pjsip_pubsub.c:3927 pubsub_on_evsub_state: evsub 0x55947a4580 state ACTIVE event USER sub_tree 0x5593ecccd8 sub_tree state Normal
<--- Received SIP response (399 bytes) from UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPj2f7c7cea-72ea-4cbf-8ac0-0d38cef8ce10
From: <sip:*[email protected]>;tag=d5532b60-5fc8-49f1-9790-11389c978da8
To: "Studio1" <sip:[email protected]>;tag=657306061
Call-ID: [email protected]
CSeq: 2872 NOTIFY
Contact: <sip:[email protected]:5060>
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


[2025-02-14 14:15:30] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x5594181d68 for Response msg 200/NOTIFY/cseq=2872 (rdata0x7f4c001518)
[2025-02-14 14:15:30] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-00000025 associated with dialog dlg0x5594181d68
<--- Received SIP request (741 bytes) from UDP:192.168.20.6:5060 --->
SUBSCRIBE sip:192.168.20.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.6:5060;branch=z9hG4bK662066785;rport
From: "Studio1" <sip:[email protected]>;tag=656846228
To: <sip:[email protected]>;tag=def75754-92b0-4b4e-85b3-ee8d6f0099ae
Call-ID: [email protected]
CSeq: 4 SUBSCRIBE
Contact: <sip:[email protected]:5060>
Authorization: Digest username="101", realm="asterisk", nonce="1739540133/793dc7cda616f2aaf2ee6264edfbf3dc", uri="sip:192.168.20.10:5060", response="3f101b03a4304a0d59b856480485dec7", algorithm=MD5, cnonce="657178218", opaque="458586b5757337a6", qop=auth, nc=00000003
Accept: application/dialog-info+xml
Max-Forwards: 70
User-Agent: Yealink SIP-T58 58.86.0.160
Expires: 1800
Event: dialog
Content-Length: 0


[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x5594832108 for Request msg SUBSCRIBE/cseq=4 (rdata0x7f4c001518)
[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-00000031 associated with dialog dlg0x5594832108
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_pubsub.c:4082 pubsub_on_rx_refresh: evsub 0x559457ac40 sub_tree 0x5594811d48 sub_tree state Normal
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '101->103'  prune on boot: no
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_pubsub.c:3965 pubsub_on_refresh_timeout: sub_tree 0x5594811d48 sub_tree state Normal
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_pubsub.c:686 subscription_persistence_update: Updating persistence for '101->103'  prune on boot: no
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:31] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.6' into...
[2025-02-14 14:15:31] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.6' and port ''.
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP response (558 bytes) to UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.6:5060;rport=5060;received=192.168.20.6;branch=z9hG4bK662066785
Call-ID: [email protected]
From: "Studio1" <sip:[email protected]>;tag=656846228
To: <sip:[email protected]>;tag=def75754-92b0-4b4e-85b3-ee8d6f0099ae
CSeq: 4 SUBSCRIBE
Expires: 1800
Contact: <sip:192.168.20.10:5060>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, INFO, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.6'
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.6' is 'UDP transport'
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.6' is an IP address, skipping resolution
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:31] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.6' into...
[2025-02-14 14:15:31] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.6' and port ''.
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (818 bytes) to UDP:192.168.20.6:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj54f953a2-806e-445f-9cb4-3c8643cce201
From: <sip:[email protected]>;tag=def75754-92b0-4b4e-85b3-ee8d6f0099ae
To: "Studio1" <sip:[email protected]>;tag=656846228
Contact: <sip:192.168.20.10:5060>
Call-ID: [email protected]
CSeq: 26985 NOTIFY
Event: dialog
Subscription-State: active;expires=1799
Allow-Events: message-summary, presence, dialog, refer
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Type: application/dialog-info+xml
Content-Length:   230

<?xml version="1.0" encoding="UTF-8"?>
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="2" state="full" entity="sip:[email protected]:5060">
 <dialog id="103">
  <state>terminated</state>
 </dialog>
</dialog-info>

[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_pubsub.c:3927 pubsub_on_evsub_state: evsub 0x559457ac40 state ACTIVE event USER sub_tree 0x5594811d48 sub_tree state Normal
<--- Received SIP response (397 bytes) from UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPj54f953a2-806e-445f-9cb4-3c8643cce201
From: <sip:[email protected]>;tag=def75754-92b0-4b4e-85b3-ee8d6f0099ae
To: "Studio1" <sip:[email protected]>;tag=656846228
Call-ID: [email protected]
CSeq: 26985 NOTIFY
Contact: <sip:[email protected]:5060>
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x5594832108 for Response msg 200/NOTIFY/cseq=26985 (rdata0x7f4c001518)
[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-00000031 associated with dialog dlg0x5594832108
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_options.c:929 sip_options_qualify_aor: Qualifying all contacts on AOR '101'
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_options.c:858 sip_options_qualify_contact: Qualifying contact '101;@41a750faea500a76640b1b4ba70a6998' on AOR '101'
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1716 endpt_send_request: 0x5594588488: Wrapper created
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1731 endpt_send_request: 0x5594588488: Set timer to 3000 msec
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target '192.168.20.6'
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target '192.168.20.6' is 'UDP transport'
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target '192.168.20.6' is an IP address, skipping resolution
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:31] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '192.168.20.6' into...
[2025-02-14 14:15:31] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '192.168.20.6' and port ''.
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip_nat.c:349 process_nat: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP request (423 bytes) to UDP:192.168.20.6:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.20.10:5060;rport;branch=z9hG4bKPj5e71bb9e-feae-4828-91b4-6ca560b4bb07
From: <sip:[email protected]>;tag=9373318b-3a10-47ee-9d2b-0026bf56a63f
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: e590ad2b-8dc4-4409-a2f4-ca089ceafd62
CSeq: 45957 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (361 bytes) from UDP:192.168.20.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.20.10:5060;rport=5060;branch=z9hG4bKPj5e71bb9e-feae-4828-91b4-6ca560b4bb07
From: <sip:[email protected]>;tag=9373318b-3a10-47ee-9d2b-0026bf56a63f
To: <sip:[email protected]>;tag=662317104
Call-ID: e590ad2b-8dc4-4409-a2f4-ca089ceafd62
CSeq: 45957 OPTIONS
User-Agent: Yealink SIP-T58 58.86.0.160
Content-Length: 0


[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:516 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=45957 (rdata0x7f4c001518).  Using request transaction as basis.
[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:124 find_request_serializer: Found transaction tsx0x5594572548 for Response msg 200/OPTIONS/cseq=45957 (rdata0x7f4c001518).
[2025-02-14 14:15:31] DEBUG[1300]: res_pjsip/pjsip_distributor.c:134 find_request_serializer: Found serializer pjsip/options/101-0000003e on transaction tsx0x5594572548
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1594 endpt_send_request_cb: 0x5594588488: PJSIP tsx response received
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1607 endpt_send_request_cb: 0x5594588488: Cancelling timer
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1616 endpt_send_request_cb: 0x5594588488: Timer cancelled
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1637 endpt_send_request_cb: 0x5594588488: Callbacks executed
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x5594588488: wrapper destroyed
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact 101/sip:[email protected]:5060 status didn't change: Reachable, RTT: 4.850 msec
[2025-02-14 14:15:31] DEBUG[1301]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR '101' now has 1 available contacts
[2025-02-14 14:15:32] DEBUG[12360]: manager.c:7022 process_message: Running action 'Login'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_options.c:929 sip_options_qualify_aor: Qualifying all contacts on AOR 'MY-COMPANY_Trunk'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_options.c:858 sip_options_qualify_contact: Qualifying contact 'MY-COMPANY_Trunk@@29c3ad128c862377466a8bf738860b74' on AOR 'MY-COMPANY_Trunk'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1716 endpt_send_request: 0x559402dec8: Wrapper created
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1731 endpt_send_request: 0x559402dec8: Set timer to 3000 msec
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target 'trunkprovider.net.uk'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target 'trunkprovider.net.uk' is 'UDP transport'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:545 sip_resolve: [0x5594558b38] Created resolution tracking for target 'trunkprovider.net.uk'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:174 sip_resolve_add: [0x5594558b38] Added target 'trunkprovider.net.uk' with record type '1', transport 'UDP transport', and port '5060'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:616 sip_resolve: [0x5594558b38] Starting initial resolution using parallel queries for target 'trunkprovider.net.uk'
[2025-02-14 14:15:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:273 sip_resolve_callback: [0x5594558b38] All parallel queries completed
[2025-02-14 14:15:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:322 sip_resolve_callback: [0x5594558b38] A record received on target 'trunkprovider.net.uk'
[2025-02-14 14:15:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:322 sip_resolve_callback: [0x5594558b38] A record received on target 'trunkprovider.net.uk'
[2025-02-14 14:15:33] DEBUG[1277]: res_pjsip/pjsip_resolver.c:417 sip_resolve_callback: [0x5594558b38] Resolution completed - 2 viable targets
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:199 sip_resolve_invoke_user_callback: [0x5594558b38] Address '0' is xx.xxx.xx.118:5060 with transport 'UDP transport'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:199 sip_resolve_invoke_user_callback: [0x5594558b38] Address '1' is xx.xxx.xx.116:5060 with transport 'UDP transport'
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_resolver.c:205 sip_resolve_invoke_user_callback: [0x5594558b38] Invoking user callback with '2' addresses
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.20.10:5060 (this may be re-written again later)
[2025-02-14 14:15:33] DEBUG[1301]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'xx.xxx.xx.118' into...
[2025-02-14 14:15:33] DEBUG[1301]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'xx.xxx.xx.118' and port ''.
<--- Transmitting SIP request (483 bytes) to UDP:xx.xxx.xx.118:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;rport;branch=z9hG4bKPj055fde5b-032b-4214-bbe6-51d5dc6e3ecd
From: <sip:[email protected]>;tag=e11c030e-c9ca-4f72-b677-073d4586682a
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 5b14c885-90a3-4c63-b1ea-26b5947e4203
CSeq: 46328 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-17.0.19.23(22.1.1)
Content-Length:  0


<--- Received SIP response (359 bytes) from UDP:xx.xxx.xx.118:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xx.98:5060;received=xxx.xxx.xx.98;rport=5060;branch=z9hG4bKPj055fde5b-032b-4214-bbe6-51d5dc6e3ecd
CSeq: 46328 OPTIONS
Call-ID: 5b14c885-90a3-4c63-b1ea-26b5947e4203
From: <sip:[email protected]>;tag=e11c030e-c9ca-4f72-b677-073d4586682a
To: <sip:[email protected]>
Content-Length: 0


[2025-02-14 14:15:33] DEBUG[1300]: res_pjsip/pjsip_distributor.c:516 distributor: No dialog serializer for Response msg 200/OPTIONS/cseq=46328 (rdata0x7f4c001518).  Using request transaction as basis.
[2025-02-14 14:15:33] DEBUG[1300]: res_pjsip/pjsip_distributor.c:124 find_request_serializer: Found transaction tsx0x559456d788 for Response msg 200/OPTIONS/cseq=46328 (rdata0x7f4c001518).
[2025-02-14 14:15:33] DEBUG[1300]: res_pjsip/pjsip_distributor.c:134 find_request_serializer: Found serializer pjsip/options/MY-COMPANY_Trunk-00000041 on transaction tsx0x559456d788
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1594 endpt_send_request_cb: 0x559402dec8: PJSIP tsx response received
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1607 endpt_send_request_cb: 0x559402dec8: Cancelling timer
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1616 endpt_send_request_cb: 0x559402dec8: Timer cancelled
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1637 endpt_send_request_cb: 0x559402dec8: Callbacks executed
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip.c:1693 send_request_wrapper_destructor: 0x559402dec8: wrapper destroyed
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_options.c:757 sip_options_contact_status_notify_task: Contact MY-COMPANY_Trunk/sip:[email protected]:5060 status didn't change: Reachable, RTT: 14.408 msec
[2025-02-14 14:15:33] DEBUG[1301]: res_pjsip/pjsip_options.c:777 sip_options_contact_status_notify_task: AOR 'MY-COMPANY_Trunk' now has 1 available contacts
<--- Received SIP request (411 bytes) from UDP:xx.xxx.xx.118:5060 --->
CANCEL sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP xx.xxx.xx.118;branch=z9hG4bK2025021414150300002-1;rport
CSeq: 1 CANCEL
Max-Forwards: 68
User-Agent: FireBrick/2.01.111
Call-ID: 2025021414150300002@2900-0602-0292-86
From: "Anonymous" <sip:[email protected]>;tag=2025021414150300002
To: <sip:[email protected]>
Reason: SIP;cause=487;text="Hung up"
Content-Length: 0


[2025-02-14 14:15:34] DEBUG[1300]: res_pjsip/pjsip_distributor.c:390 find_dialog: Could not find matching transaction for Request msg CANCEL/cseq=1 (rdata0x7f4c001518)
[2025-02-14 14:15:34] DEBUG[1300]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting 'xx.xxx.xx.118' into...
[2025-02-14 14:15:34] DEBUG[1300]: netsock2.c:224 ast_sockaddr_split_hostport: ...host 'xx.xxx.xx.118' and port ''.
<--- Transmitting SIP response (416 bytes) to UDP:xx.xxx.xx.118:5060 --->
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP xx.xxx.xx.118;rport=5060;received=xx.xxx.xx.118;branch=z9hG4bK2025021414150300002-1
Call-ID: 2025021414150300002@2900-0602-0292-86
From: "Anonymous" <sip:[email protected]>;tag=2025021414150300002
To: <sip:[email protected]>;tag=z9hG4bK2025021414150300002-1
CSeq: 1 CANCEL
Server: FPBX-17.0.19.23(22.1.1)
Content-Length:  0
15

No, you do core set verbose 10 and make the test call… no pjsip logger no debug.

16

Ok thanks
PJSIP logging now on, but of course now it’s started to connect calls!

17 
FreePBX*CLI> pjsip set logger on
PJSIP Logging enabled
18

Deleted

19

I can’t see the INVITE in those logs, although it’s there in sngrep?

The packet capture at the bottom is from the pbx server at the time of the log.

I also did a packet capture on one of the phones at the same time and i couldn’t see any traffic from PBX server.

20

You keep giving things I specially said not to and not providing the one thing I asked for.