PJSIP: not forwarding BYE ?!?

Smurf · October 20, 2025, 10:15am

Call from A (10.6.9.10) to B. B answers. Some seconds later, B sends a BYE, which is answered but not forwarded to A:

01201 1760952203 * <== 10.6.9.10:52604          INVITE sip:0911XXX@62.128.1.6:5060 SIP/2.0
01202 1760952203 * ==> 10.6.9.10:52604          SIP/2.0 100 Trying
01203 1760952203 * ==> 213.95.X.X:5060          INVITE sip:+49911XXX@213.95.70.242:5060 SIP/2.0
01204 1760952203 * <== 213.95.X.X:5060          SIP/2.0 100 Trying
01205 1760952203 * <== 213.95.X.X:5060          SIP/2.0 180 Ringing
01206 1760952203 * ==> 10.6.9.10:52604          SIP/2.0 180 Ringing
01209 1760952205 * <== 213.95.X.X:5060          SIP/2.0 200 OK
01210 1760952205 * ==> 213.95.X.X:5060          ACK sip:+49911XXX@213.95.70.242:5060 SIP/2.0
01211 1760952205 * ==> 10.6.9.10:52604          SIP/2.0 200 OK
01212 1760952205 * <== 10.6.9.10:52604          ACK sip:62.128.1.6:5060;transport=TCP SIP/2.0
01215 1760952221 * <== 213.95.X.X:5060          BYE sip:asterisk@62.128.1.6:5060 SIP/2.0
01216 1760952221 * ==> 213.95.X.X:5060          SIP/2.0 200 OK

Note the lack of BYE sent to 10.6.9.10

Does anybody have any idea what’s going on here? The call has vanished from “pjsip show channels”, but obviously it’s still active as far as A is concerned … which is a problem because A is a door station with no hangup button, and even if it had one people typically don’t press that.

jcolp · October 20, 2025, 10:18am

You need to provide an actual full SIP trace, not just the first line of messages. Most likely, though, is the Contact header from the remote side differs and Asterisk is trying to send/connect to it instead of where the other traffic came from and failing. Setting “rewrite_contact” to yes will force it to use the same IP address+port as the original traffic.

Smurf · October 20, 2025, 10:19am

Thanks I’ll do that and report back.

Smurf · October 20, 2025, 10:58am

No, setting that option didn’t change the result.

Packet trace attached. The door station (10.6.9.10) identifies itself as 121, which gets rewritten with prefix +66554433. The call is accepted by the logging system (10.10.10.10) and forwarded to 10.11.12.13, which ends it (or tries to …)

sip01vp*CLI> pjsip show history entry 288
<--- History Entry 288 Received from 10.6.9.10:52604 at 1760956678 --->
INVITE sip:07654321@10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/TCP 10.6.9.10:5060;received=10.6.9.10;branch=z9hG4bK057aefcc
Max-Forwards: 70
From: "DOOR STATION" <sip:121@10.6.9.10>;tag=as0080a51e
To: <sip:07654321@10.10.10.10>
Contact: <sip:121@10.6.9.10:5060;transport=TCP>
Call-ID: 05acbfc96e03e35219c263d36e94aa44@10.6.9.10:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 11.13.1~dfsg-2+deb8u8
Date: Mon, 20 Oct 2025 10:37:58 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 240
Content-Type: application/sdp
Content-Length:   240

v=0
o=root 874136519 874136519 IN IP4 10.6.9.10
s=Asterisk PBX 11.13.1~dfsg-2+deb8u8
c=IN IP4 10.6.9.10
t=0 0
m=audio 16010 RTP/AVP 111 3 8
a=rtpmap:111 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=ptime:20
a=sendrecv

sip01vp*CLI> pjsip show history entry 289
<--- History Entry 289 Sent to 10.6.9.10:52604 at 1760956678 --->
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.6.9.10:5060;rport=52604;received=10.6.9.10;branch=z9hG4bK057aefcc
Call-ID: 05acbfc96e03e35219c263d36e94aa44@10.6.9.10:5060
From: "DOOR STATION" <sip:121@10.6.9.10>;tag=as0080a51e
To: <sip:07654321@10.10.10.10>
CSeq: 102 INVITE
Server: nnAG prod
Content-Length:  0


sip01vp*CLI> pjsip show history entry 290
<--- History Entry 290 Sent to 10.11.12.13:5060 at 1760956678 --->
INVITE sip:+987654321@10.11.12.13:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPj7e22f389-b388-4518-994a-f458caabc952
From: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
To: <sip:+987654321@10.11.12.13>
Contact: <sip:asterisk@10.10.10.10:5060>
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
CSeq: 30074 INVITE
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, INFO, REFER
Supported: 100rel, timer, replaces, norefersub, histinfo
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: nnAG prod
Content-Type: application/sdp
Content-Length:   591

v=0
o=- 184076562 184076562 IN IP4 10.10.10.10
s=Asterisk
c=IN IP4 10.10.10.10
t=0 0
m=audio 16074 RTP/AVP 8 101
a=ice-ufrag:7dae9c1950d0ea32162365d062fb4a6c
a=ice-pwd:303557072d43b6142b1cd183321c8f78
a=candidate:H3e800106 1 UDP 2130706431 10.10.10.10 16074 typ host
a=candidate:H64582464 1 UDP 2130706431 100.88.36.100 16074 typ host
a=candidate:H3e800106 2 UDP 2130706430 10.10.10.10 16075 typ host
a=candidate:H64582464 2 UDP 2130706430 100.88.36.100 16075 typ host
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:140
a=sendrecv

sip01vp*CLI> pjsip show history entry 291
<--- History Entry 291 Received from 10.11.12.13:5060 at 1760956678 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;received=10.10.10.10;branch=z9hG4bKPj7e22f389-b388-4518-994a-f458caabc952
From: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
To: <sip:+987654321@10.11.12.13>
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
CSeq: 30074 INVITE
Server: STARFACE PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:+987654321@10.11.12.13:5060>
Content-Length: 0
Content-Length:  0


sip01vp*CLI> pjsip show history entry 292
<--- History Entry 292 Received from 10.11.12.13:5060 at 1760956678 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;received=10.10.10.10;branch=z9hG4bKPj7e22f389-b388-4518-994a-f458caabc952
From: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
To: <sip:+987654321@10.11.12.13>;tag=as672a7b95
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
CSeq: 30074 INVITE
Server: STARFACE PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:+987654321@10.11.12.13:5060>
Content-Length: 0
Content-Length:  0


sip01vp*CLI> pjsip show history entry 293
<--- History Entry 293 Sent to 10.6.9.10:52604 at 1760956678 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 10.6.9.10:5060;rport=52604;received=10.6.9.10;branch=z9hG4bK057aefcc
Call-ID: 05acbfc96e03e35219c263d36e94aa44@10.6.9.10:5060
From: "DOOR STATION" <sip:121@10.6.9.10>;tag=as0080a51e
To: <sip:07654321@10.10.10.10>;tag=7312b6e1-39a6-4a5d-aae6-3797e3d15aa4
CSeq: 102 INVITE
Server: nnAG prod
Contact: <sip:10.10.10.10:5060;transport=TCP>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, INFO, REFER
Content-Length:  0


sip01vp*CLI> pjsip show history entry 296
<--- History Entry 296 Received from 10.11.12.13:5060 at 1760956682 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.10.10.10:5060;rport=5060;received=10.10.10.10;branch=z9hG4bKPj7e22f389-b388-4518-994a-f458caabc952
From: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
To: <sip:+987654321@10.11.12.13>;tag=as672a7b95
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
CSeq: 30074 INVITE
Server: STARFACE PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:+987654321@10.11.12.13:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 230
Content-Type: application/sdp
Content-Length:   230

v=0
o=root 1711392094 1711392094 IN IP4 10.11.12.13
s=STARFACE PBX
c=IN IP4 10.11.12.13
t=0 0
m=audio 16690 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

sip01vp*CLI> pjsip show history entry 297
<--- History Entry 297 Sent to 10.11.12.13:5060 at 1760956682 --->
ACK sip:+987654321@10.11.12.13:5060 SIP/2.0
Via: SIP/2.0/UDP 10.10.10.10:5060;rport;branch=z9hG4bKPj808f59c5-77d3-442e-81ca-f549ee7d567a
From: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
To: <sip:+987654321@10.11.12.13>;tag=as672a7b95
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
CSeq: 30074 ACK
Max-Forwards: 70
User-Agent: nnAG prod
Content-Length:  0


sip01vp*CLI> pjsip show history entry 298
<--- History Entry 298 Sent to 10.6.9.10:52604 at 1760956682 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP 10.6.9.10:5060;rport=52604;received=10.6.9.10;branch=z9hG4bK057aefcc
Call-ID: 05acbfc96e03e35219c263d36e94aa44@10.6.9.10:5060
From: "DOOR STATION" <sip:121@10.6.9.10>;tag=as0080a51e
To: <sip:07654321@10.10.10.10>;tag=7312b6e1-39a6-4a5d-aae6-3797e3d15aa4
CSeq: 102 INVITE
Server: nnAG prod
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, INFO, REFER
Contact: <sip:10.10.10.10:5060;transport=TCP>
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   175

v=0
o=- 874136519 874136521 IN IP4 10.10.10.10
s=Asterisk
c=IN IP4 10.10.10.10
t=0 0
m=audio 14096 RTP/AVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20
a=maxptime:140
a=sendrecv

sip01vp*CLI> pjsip show history entry 299
<--- History Entry 299 Received from 10.6.9.10:52604 at 1760956682 --->
ACK sip:10.10.10.10:5060;transport=TCP SIP/2.0
Via: SIP/2.0/TCP 10.6.9.10:5060;received=10.6.9.10;branch=z9hG4bK7ef2f80c
Max-Forwards: 70
From: "DOOR STATION" <sip:121@10.6.9.10>;tag=as0080a51e
To: <sip:07654321@10.10.10.10>;tag=7312b6e1-39a6-4a5d-aae6-3797e3d15aa4
Contact: <sip:121@10.6.9.10:5060;transport=TCP>
Call-ID: 05acbfc96e03e35219c263d36e94aa44@10.6.9.10:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 11.13.1~dfsg-2+deb8u8
Content-Length: 0
Content-Length:  0


sip01vp*CLI> pjsip show history entry 304
<--- History Entry 304 Received from 10.11.12.13:5060 at 1760956691 --->
BYE sip:asterisk@10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.11.12.13:5060;rport=5060;received=10.11.12.13;branch=z9hG4bK3c06ada1
Max-Forwards: 70
From: <sip:+987654321@10.11.12.13>;tag=as672a7b95
To: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
CSeq: 102 BYE
User-Agent: STARFACE PBX
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0
Content-Length:  0


sip01vp*CLI> pjsip show history entry 305
<--- History Entry 305 Sent to 10.11.12.13:5060 at 1760956691 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.11.12.13:5060;rport=5060;received=10.11.12.13;branch=z9hG4bK3c06ada1
Call-ID: 13e489e9-d1e0-422e-9f73-d931d86e805c
From: <sip:+987654321@10.11.12.13>;tag=as672a7b95
To: "DOOR STATION" <sip:+66554433121@pbx1.example>;tag=f45f984c-c1de-43ea-b5cd-075969626a75
CSeq: 102 BYE
Server: nnAG prod
Content-Length:  0

No further messages.

jcolp · October 20, 2025, 11:00am

I’m going to bow out, I’m not going to investigate such an old version of Asterisk.

jcolp · October 20, 2025, 11:01am

Actually, that’s received. What version of Asterisk is this?

Smurf · October 20, 2025, 11:04am

This is 22.5. I can upgrade to 22.6 if that might help.
Can’t do anything about the things I’m talking to; the 10.11.12.13 system is going to be decommissioned in December. The door station would be more difficult.

jcolp · October 20, 2025, 11:05am

Probably won’t. Next step would be a debug log[1] which would include console to show what you’re actually doing with the calls.

[1] Collecting Debug Information - Asterisk Documentation

jcolp · October 20, 2025, 11:07am

And you set rewrite_contact to yes on the endpoint for 10.6.9.10 correct?

jcolp · October 20, 2025, 11:08am

And it is using TCP?

Smurf · October 20, 2025, 11:18am

Here’s the debug log. Yes it’s TCP, both legs. You can ignore the ODBC stuff, the endpoints in question are all configured statically.

[2025-10-20 12:37:58.020] DEBUG[64871] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:37:58.020] DEBUG[64871] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:37:58.021] DEBUG[64871] res_config_odbc.c: Parameter 1 ('id') = '121@10.6.9.10'
[2025-10-20 12:37:58.022] DEBUG[64871] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:37:58.022] DEBUG[64871] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:37:58.022] DEBUG[64871] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:37:58.023] DEBUG[64871] res_config_odbc.c: Parameter 1 ('id') = '121'
[2025-10-20 12:37:58.023] DEBUG[64871] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  (null session) Request: INVITE 
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  Request: 
[2025-10-20 12:37:58.023] DEBUG[64871] chan_pjsip.c:  intercom
[2025-10-20 12:37:58.023] DEBUG[64871] chan_pjsip.c:  Direct media no glare mitigation
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  intercom Event: TSX_STATE  Inv State: INCOMING
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  intercom TSX State: Proceeding  Inv State: INCOMING
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  intercom TSX State: Proceeding  Inv State: INCOMING
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  Topology: Pending: (null topology)  Active: (null topology)
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  intercom Adding position 0
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  Creating new media session
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  Setting media session as default for audio
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_session.c:  Done
[2025-10-20 12:37:58.023] DEBUG[64871] res_pjsip_sdp_rtp.c:  intercom
[2025-10-20 12:37:58.024] DEBUG[64871] res_pjsip_sdp_rtp.c: Transport main-udp bound to 10.10.10.10: Using it for RTP media.
[2025-10-20 12:37:58.024] DEBUG[64871] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f630013c060'
[2025-10-20 12:37:58.024] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) RTP allocated port 14096
[2025-10-20 12:37:58.024] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE creating session 10.10.10.10:14096 (14096)
[2025-10-20 12:37:58.024] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE create
[2025-10-20 12:37:58.024] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE add system candidates
[2025-10-20 12:37:58.024] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE add candidate: 10.10.10.10:14096, 2130706431
[2025-10-20 12:37:58.024] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE add candidate: 100.88.36.100:14096, 2130706431
[2025-10-20 12:37:58.024] DEBUG[64871] rtp_engine.c: RTP instance '0x7f630013c060' is setup and ready to go
[2025-10-20 12:37:58.025] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE add system candidates
[2025-10-20 12:37:58.025] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE add candidate: 10.10.10.10:14097, 2130706430
[2025-10-20 12:37:58.025] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE add candidate: 100.88.36.100:14097, 2130706430
[2025-10-20 12:37:58.025] DEBUG[64871] res_rtp_asterisk.c: () RTCP setup on RTP instance
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  intercom
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  intercom
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f63780931e0
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f63780931e0
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Crossover copying tx to rx payload mapping 3 (0x7f630003f308) from 0x7f63780931e0 to 0x7f63780931e0
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7f6300125b58) from 0x7f63780931e0 to 0x7f63780931e0
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Crossover copying tx to rx payload mapping 111 (0x7f630005a858) from 0x7f63780931e0 to 0x7f63780931e0
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Copying rx payload mapping 3 (0x7f630003f308) from 0x7f63780931e0 to 0x7f630013c238
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Copying rx payload mapping 8 (0x7f6300125b58) from 0x7f63780931e0 to 0x7f630013c238
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Copying rx payload mapping 111 (0x7f630005a858) from 0x7f63780931e0 to 0x7f630013c238
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Copying tx payload mapping 3 (0x7f630003f308) from 0x7f63780931e0 to 0x7f630013c238
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Copying tx payload mapping 8 (0x7f6300125b58) from 0x7f63780931e0 to 0x7f630013c238
[2025-10-20 12:37:58.025] DEBUG[64871] rtp_engine.c: Copying tx payload mapping 111 (0x7f630005a858) from 0x7f63780931e0 to 0x7f630013c238
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_session.c:  intercom Adding position 0
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_session.c:  Using existing media_session
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_session.c:  intercom Stream: 0:audio-0:audio:sendrecv (alaw)
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  intercom Type: audio 0:audio-0:audio:sendrecv (alaw)
[2025-10-20 12:37:58.025] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) RTCP ignoring duplicate property
[2025-10-20 12:37:58.025] DEBUG[64871] res_rtp_asterisk.c: (0x7f630013c060) ICE stopped
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_sdp_rtp.c:  RC: 1
[2025-10-20 12:37:58.025] DEBUG[64871] res_pjsip_session.c:  Had handler
[2025-10-20 12:37:58.025] DEBUG[64871] chan_pjsip.c:  intercom
[2025-10-20 12:37:58.025] DEBUG[64871] channel_internal_api.c:  <initializing>: Formats: (none)
[2025-10-20 12:37:58.025] DEBUG[64871] channel_internal_api.c:  Channel is being initialized or destroyed
[2025-10-20 12:37:58.025] DEBUG[64871] stasis.c: Creating topic. name: channel:1760956678.3923, detail: 
[2025-10-20 12:37:58.025] DEBUG[64871] stasis.c: Topic 'channel:1760956678.3923': 0x7f630001ec60 created
[2025-10-20 12:37:58.025] DEBUG[64871] channel.c: Channel 0x7f6300c498b0 'PJSIP/intercom-0000066a' allocated
[2025-10-20 12:37:58.025] DEBUG[64871] chan_pjsip.c:  Topology:  <0:audio-0:audio:sendrecv (alaw)> Formats: (alaw)
[2025-10-20 12:37:58.025] DEBUG[64871] chan_pjsip.c:  Compatible? yes
[2025-10-20 12:37:58.025] DEBUG[64871] channel_internal_api.c:  PJSIP/intercom-0000066a: MultistreamFormats: (alaw)
[2025-10-20 12:37:58.025] DEBUG[64871] channel_internal_api.c:  Set native formats but not topology
[2025-10-20 12:37:58.025] DEBUG[64871] channel_internal_api.c:  PJSIP/intercom-0000066a:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:37:58.025] DEBUG[64871] channel_internal_api.c:  Used provided topology
[2025-10-20 12:37:58.025] DEBUG[64871] chan_pjsip.c:  
[2025-10-20 12:37:58.025] DEBUG[64871] chan_pjsip.c:  PJSIP/intercom-0000066a
[2025-10-20 12:37:58.026] DEBUG[64871] chan_pjsip.c:  RC: 0
[2025-10-20 12:37:58.026] DEBUG[64871] res_pjsip_session.c:  Request:  Session: PJSIP/intercom-0000066a
[2025-10-20 12:37:58.026] DEBUG[64871] res_pjsip_session.c:  (null session) Handled request INVITE  ? yes
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] pbx.c: Launching 'Gosub'
[2025-10-20 12:37:58.026] VERBOSE[39061][C-00000407] pbx.c: Executing [07654321@in_intercom:1] Gosub("PJSIP/intercom-0000066a", "aroute,~~s~~,1(intercom,07654321)") in new stack
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] app_stack.c: Channel PJSIP/intercom-0000066a has no datastore, so we're allocating one.
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] app_stack.c: Setting 'ARG1' to 'intercom'
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] app_stack.c: Setting 'ARG2' to '07654321'
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] pbx.c: Launching 'MSet'
[2025-10-20 12:37:58.026] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:1] MSet("PJSIP/intercom-0000066a", "LOCAL(src)=intercom") in new stack
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] pbx.c: Launching 'MSet'
[2025-10-20 12:37:58.026] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:2] MSet("PJSIP/intercom-0000066a", "LOCAL(ext)=07654321") in new stack
[2025-10-20 12:37:58.026] DEBUG[39061][C-00000407] pbx_variables.c: Function CALLERID(num) result is '121'
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx_variables.c: Function CURL(http://localhost:50080/route/intercom:121:07654321) result is 'pbx1:+466554433121:+987654321:PJSIP'
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:37:58.030] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:3] Set("PJSIP/intercom-0000066a", "res=pbx1:+466554433121:+987654321:PJSIP") in new stack
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx_variables.c: Function CALLERID(num) result is '121'
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx.c: Launching 'Verbose'
[2025-10-20 12:37:58.030] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:4] Verbose("PJSIP/intercom-0000066a", "0, CURL intercom:121:07654321 => pbx1:+466554433121:+987654321:PJSIP") in new stack
[2025-10-20 12:37:58.030] VERBOSE[39061][C-00000407] app_verbose.c:  CURL intercom:121:07654321 => pbx1:+466554433121:+987654321:PJSIP
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx_variables.c: Variable res result is 'pbx1:+466554433121:+987654321:PJSIP' from channel
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx_variables.c: Function CUT(res,:,1) result is 'pbx1'
[2025-10-20 12:37:58.030] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:37:58.030] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:5] Set("PJSIP/intercom-0000066a", "dst=pbx1") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Expression result is '0'
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'GotoIf'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:6] GotoIf("PJSIP/intercom-0000066a", "0?7:12") in new stack
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx_builtins.c: Goto (aroute,~~s~~,12)
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Variable res result is 'pbx1:+466554433121:+987654321:PJSIP' from channel
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Function CUT(res,:,2) result is '+466554433121'
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:12] Set("PJSIP/intercom-0000066a", "snr=+466554433121") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Variable res result is 'pbx1:+466554433121:+987654321:PJSIP' from channel
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Function CUT(res,:,3) result is '+987654321'
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:13] Set("PJSIP/intercom-0000066a", "dnr=+987654321") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Variable res result is 'pbx1:+466554433121:+987654321:PJSIP' from channel
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Function CUT(res,:,4) result is 'PJSIP'
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:14] Set("PJSIP/intercom-0000066a", "channel=PJSIP") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx_variables.c: Expression result is '0'
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'GotoIf'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:15] GotoIf("PJSIP/intercom-0000066a", "0?16:17") in new stack
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx_builtins.c: Goto (aroute,~~s~~,17)
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'NoOp'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:17] NoOp("PJSIP/intercom-0000066a", "Finish if_if_aroute_1_2") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:18] Set("PJSIP/intercom-0000066a", "CALLERID(num)=+466554433121") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] pbx.c: Launching 'Dial'
[2025-10-20 12:37:58.031] VERBOSE[39061][C-00000407] pbx.c: Executing [~~s~~@aroute:19] Dial("PJSIP/intercom-0000066a", "PJSIP/+987654321@pbx1") in new stack
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] app_dial.c:  PJSIP/intercom-0000066a: Data: PJSIP/+987654321@pbx1
[2025-10-20 12:37:58.031] DEBUG[39061][C-00000407] chan_pjsip.c:  +987654321@pbx1 Topology:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:37:58.031] DEBUG[36922] chan_pjsip.c:  +987654321@pbx1
[2025-10-20 12:37:58.031] DEBUG[36922] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:37:58.031] DEBUG[36922] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:37:58.032] DEBUG[36922] res_config_odbc.c: Parameter 1 ('id') = '+987654321@pbx1'
[2025-10-20 12:37:58.032] DEBUG[36922] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:37:58.032] DEBUG[36922] res_pjsip_session.c:  pbx1 +987654321 Topology:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:37:58.032] DEBUG[36922] chan_pjsip.c:  pbx1
[2025-10-20 12:37:58.032] DEBUG[36922] chan_pjsip.c:  Direct media no glare mitigation
[2025-10-20 12:37:58.032] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:37:58.032] DEBUG[36922] chan_pjsip.c:  
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] chan_pjsip.c:  pbx1
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel_internal_api.c:  <initializing>: Formats: (none)
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel_internal_api.c:  Channel is being initialized or destroyed
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] stasis.c: Creating topic. name: channel:1760956678.3924, detail: 
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] stasis.c: Topic 'channel:1760956678.3924': 0x7f6374018890 created
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel.c: Channel 0x7f637400e630 'PJSIP/pbx1-0000066b' allocated
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] chan_pjsip.c:  Topology:  <0:audio-0:audio:sendrecv (alaw)> Formats: (alaw)
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] chan_pjsip.c:  Compatible? yes
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel_internal_api.c:  PJSIP/pbx1-0000066b: MultistreamFormats: (alaw)
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel_internal_api.c:  Set native formats but not topology
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel_internal_api.c:  PJSIP/pbx1-0000066b:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:37:58.032] DEBUG[39061][C-00000407] channel_internal_api.c:  Used provided topology
[2025-10-20 12:37:58.033] DEBUG[39061][C-00000407] chan_pjsip.c:  
[2025-10-20 12:37:58.033] DEBUG[39061][C-00000407] chan_pjsip.c:  Channel: PJSIP/pbx1-0000066b
[2025-10-20 12:37:58.033] DEBUG[39061][C-00000407] chan_pjsip.c:  PJSIP/pbx1-0000066b Topology:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:37:58.033] DEBUG[64871] chan_pjsip.c:  PJSIP/pbx1-0000066b Topology:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Adding position 0
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_session.c:  Creating new media session
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_session.c:  Setting media session as default for audio
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_session.c:  Done
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Stream: 0:audio-0:audio:sendrecv (alaw)
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_sdp_rtp.c:  PJSIP/pbx1-0000066b Type: audio 0:audio-0:audio:sendrecv (alaw)
[2025-10-20 12:37:58.033] DEBUG[64871] res_pjsip_sdp_rtp.c: Transport main-udp bound to 10.10.10.10: Using it for RTP media.
[2025-10-20 12:37:58.033] DEBUG[64871] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f63000e25a0'
[2025-10-20 12:37:58.033] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) RTP allocated port 16074
[2025-10-20 12:37:58.033] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE creating session 10.10.10.10:16074 (16074)
[2025-10-20 12:37:58.033] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE create
[2025-10-20 12:37:58.033] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE add system candidates
[2025-10-20 12:37:58.033] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE add candidate: 10.10.10.10:16074, 2130706431
[2025-10-20 12:37:58.033] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE add candidate: 100.88.36.100:16074, 2130706431
[2025-10-20 12:37:58.033] DEBUG[64871] rtp_engine.c: RTP instance '0x7f63000e25a0' is setup and ready to go
[2025-10-20 12:37:58.034] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE add system candidates
[2025-10-20 12:37:58.034] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE add candidate: 10.10.10.10:16075, 2130706430
[2025-10-20 12:37:58.034] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE add candidate: 100.88.36.100:16075, 2130706430
[2025-10-20 12:37:58.034] DEBUG[64871] res_rtp_asterisk.c: () RTCP setup on RTP instance
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_sdp_rtp.c:  RC: 1
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  Handled
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.11.12.13'
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip/pjsip_resolver.c: Transport type for target '10.11.12.13' is 'UDP transport'
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip/pjsip_resolver.c: Target '10.11.12.13' is an IP address, skipping resolution
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Event: TSX_STATE  Inv State: CALLING
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Calling  Inv State: CALLING
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Calling  Inv State: CALLING
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  Topology: Pending:  <0:audio-0:audio:sendrecv (alaw)>  Active: (null topology)
[2025-10-20 12:37:58.034] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.034] DEBUG[64871] chan_pjsip.c:  RC: 0
[2025-10-20 12:37:58.034] DEBUG[39061][C-00000407] chan_pjsip.c:  'call' task pushed
[2025-10-20 12:37:58.034] VERBOSE[39061][C-00000407] app_dial.c: Called PJSIP/+987654321@pbx1
[2025-10-20 12:37:58.034] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/pbx1-0000066b setting read format path: alaw -> alaw
[2025-10-20 12:37:58.034] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/intercom-0000066a setting write format path: alaw -> alaw
[2025-10-20 12:37:58.034] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/intercom-0000066a setting read format path: alaw -> alaw
[2025-10-20 12:37:58.034] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/pbx1-0000066b setting write format path: alaw -> alaw
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Method: INVITE Status: 100
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Proceeding  Inv State: CALLING
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Proceeding  Inv State: CALLING
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  Topology: Pending:  <0:audio-0:audio:sendrecv (alaw)>  Active: (null topology)
[2025-10-20 12:37:58.036] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b Method: INVITE Status: 180
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b Event: TSX_STATE  Inv State: EARLY
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Proceeding  Inv State: EARLY
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Proceeding  Inv State: EARLY
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  Topology: Pending:  <0:audio-0:audio:sendrecv (alaw)>  Active: (null topology)
[2025-10-20 12:37:58.147] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:37:58.147] VERBOSE[39061][C-00000407] app_dial.c: PJSIP/pbx1-0000066b is ringing
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a Event: TSX_STATE  Inv State: EARLY
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Proceeding  Inv State: EARLY
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Proceeding  Inv State: EARLY
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  Topology: Pending:  <0:audio-0:audio:sendrecv (alaw)>  Active: (null topology)
[2025-10-20 12:37:58.148] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:37:58.491] DEBUG[36922] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:37:58.491] DEBUG[36922] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:37:58.492] DEBUG[36922] res_config_odbc.c: Parameter 1 ('id') = '@159.124.0.84'
[2025-10-20 12:37:58.492] DEBUG[36922] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Method: INVITE Status: 200
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Event: TSX_STATE  Inv State: CONNECTING
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:38:02.909] DEBUG[64871] res_pjsip_sdp_rtp.c:  PJSIP/pbx1-0000066b Stream: 0:audio-0:audio:sendrecv (alaw)
[2025-10-20 12:38:02.909] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) RTCP ignoring duplicate property
[2025-10-20 12:38:02.910] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) RTCP setting address on RTP instance
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c: (0x7f63000e25a0) ICE process attributes

(second half follows)

Smurf · October 20, 2025, 11:19am


[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c: (0x7f63000e25a0) ICE no, or invalid ice-ufrag
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c:  PJSIP/pbx1-0000066b ANSWER
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:38:02.910] DEBUG[64871] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f6378092e60
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:38:02.910] DEBUG[64871] rtp_engine.c: Copying tx payload mapping 8 (0x7f6300010dd8) from 0x7f6378092e60 to 0x7f63000e2778
[2025-10-20 12:38:02.910] DEBUG[64871] rtp_engine.c: Copying tx payload mapping 101 (0x7f6300159998) from 0x7f6378092e60 to 0x7f63000e2778
[2025-10-20 12:38:02.910] DEBUG[64871] channel_internal_api.c:  PJSIP/pbx1-0000066b: MultistreamFormats: (alaw)
[2025-10-20 12:38:02.910] DEBUG[64871] channel_internal_api.c:  Set native formats but not topology
[2025-10-20 12:38:02.910] DEBUG[64871] channel.c: Channel PJSIP/pbx1-0000066b setting read format path: alaw -> alaw
[2025-10-20 12:38:02.910] DEBUG[64871] channel.c: Channel PJSIP/pbx1-0000066b setting write format path: alaw -> alaw
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_sdp_rtp.c:  Handled
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2025-10-20 12:38:02.910] DEBUG[64871] channel_internal_api.c:  PJSIP/pbx1-0000066b:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:02.910] DEBUG[64871] channel_internal_api.c:  Used provided topology
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '10.11.12.13'
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip/pjsip_resolver.c: Transport type for target '10.11.12.13' is 'UDP transport'
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip/pjsip_resolver.c: Target '10.11.12.13' is an IP address, skipping resolution
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Event: TX_MSG  Inv State: CONFIRMED
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Terminated  Inv State: CONFIRMED
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Terminated  Inv State: CONFIRMED
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:02.910] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.910] VERBOSE[39061][C-00000407] app_dial.c: PJSIP/pbx1-0000066b answered PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/pbx1-0000066b setting read format path: alaw -> alaw
[2025-10-20 12:38:02.910] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/intercom-0000066a setting write format path: alaw -> alaw
[2025-10-20 12:38:02.910] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/intercom-0000066a setting read format path: alaw -> alaw
[2025-10-20 12:38:02.910] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/pbx1-0000066b setting write format path: alaw -> alaw
[2025-10-20 12:38:02.910] DEBUG[39061][C-00000407] features.c: Answering channel for bridge: PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[39061][C-00000407] chan_pjsip.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[36922] chan_pjsip.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_sdp_rtp.c:  PJSIP/intercom-0000066a Stream: 0:audio-0:audio:sendrecv (alaw)
[2025-10-20 12:38:02.910] DEBUG[36922] res_rtp_asterisk.c: (0x7f630013c060) RTCP ignoring duplicate property
[2025-10-20 12:38:02.910] DEBUG[36922] res_rtp_asterisk.c: (0x7f630013c060) RTCP setting address on RTP instance
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_sdp_rtp.c: (0x7f630013c060) ICE process attributes
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_sdp_rtp.c: (0x7f630013c060) ICE no, or invalid ice-ufrag
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_sdp_rtp.c:  PJSIP/intercom-0000066a ANSWER
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_sdp_rtp.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:02.910] DEBUG[36922] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f6351156060
[2025-10-20 12:38:02.910] DEBUG[36922] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f6351156060
[2025-10-20 12:38:02.910] DEBUG[36922] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:38:02.911] DEBUG[36922] rtp_engine.c: Copying tx payload mapping 3 (0x7f62f51646c8) from 0x7f6351156060 to 0x7f630013c238
[2025-10-20 12:38:02.911] DEBUG[36922] rtp_engine.c: Copying tx payload mapping 8 (0x7f62f4001b48) from 0x7f6351156060 to 0x7f630013c238
[2025-10-20 12:38:02.911] DEBUG[36922] rtp_engine.c: Copying tx payload mapping 111 (0x7f62f4dcb678) from 0x7f6351156060 to 0x7f630013c238
[2025-10-20 12:38:02.911] DEBUG[36922] channel_internal_api.c:  PJSIP/intercom-0000066a: MultistreamFormats: (alaw)
[2025-10-20 12:38:02.911] DEBUG[36922] channel_internal_api.c:  Set native formats but not topology
[2025-10-20 12:38:02.911] DEBUG[36922] channel.c: Channel PJSIP/intercom-0000066a setting read format path: alaw -> alaw
[2025-10-20 12:38:02.911] DEBUG[36922] channel.c: Channel PJSIP/intercom-0000066a setting write format path: alaw -> alaw
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_sdp_rtp.c:  
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_sdp_rtp.c:  Handled
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a: Applied negotiated SDP media stream 'audio' using audio SDP handler
[2025-10-20 12:38:02.911] DEBUG[36922] channel_internal_api.c:  PJSIP/intercom-0000066a:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:02.911] DEBUG[36922] channel_internal_api.c:  Used provided topology
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a Event: TSX_STATE  Inv State: CONNECTING
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Completed  Inv State: CONNECTING
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Completed  Inv State: CONNECTING
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:02.911] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:02.911] DEBUG[36922] chan_pjsip.c:  
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] chan_pjsip.c:  
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] stasis.c: Creating topic. name: bridge:all/bridge:122f8daf-49ca-4f32-a182-53103b5a43c7, detail: 
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] stasis.c: Topic 'bridge:all/bridge:122f8daf-49ca-4f32-a182-53103b5a43c7': 0x7f6374017df0 created
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): base_init
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge_native_rtp.c: Bridge '122f8daf-49ca-4f32-a182-53103b5a43c7' can not use native RTP bridge as two channels are required
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping.
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Chose bridge technology simple_bridge
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: calling simple_bridge technology constructor
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: calling simple_bridge technology start
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): base_init complete
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): registering
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: 0x7f6374017ff0(PJSIP/pbx1-0000066b) is joining
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: pushing 0x7f6374017ff0(PJSIP/pbx1-0000066b)
[2025-10-20 12:38:02.911] VERBOSE[39071][C-00000407] bridge_channel.c: Channel PJSIP/pbx1-0000066b joined 'simple_bridge' basic-bridge <122f8daf-49ca-4f32-a182-53103b5a43c7>
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge_native_rtp.c: Bridge '122f8daf-49ca-4f32-a182-53103b5a43c7' can not use native RTP bridge as two channels are required
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge.c: Bridge technology softmix does not have any capabilities we want.
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge.c: Chose bridge technology simple_bridge
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7 is already using the new technology.
[2025-10-20 12:38:02.911] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: 0x7f6374017ff0(PJSIP/pbx1-0000066b) is joining simple_bridge technology
[2025-10-20 12:38:02.911] DEBUG[39061][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: 0x7f6374018190(PJSIP/intercom-0000066a) is joining
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: pushing 0x7f6374018190(PJSIP/intercom-0000066a)
[2025-10-20 12:38:02.912] VERBOSE[39061][C-00000407] bridge_channel.c: Channel PJSIP/intercom-0000066a joined 'simple_bridge' basic-bridge <122f8daf-49ca-4f32-a182-53103b5a43c7>
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge_native_rtp.c: Bridge '122f8daf-49ca-4f32-a182-53103b5a43c7'.  Checking compatability for channels 'PJSIP/pbx1-0000066b' and 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge_native_rtp.c: Bridge '122f8daf-49ca-4f32-a182-53103b5a43c7' can not use local native RTP bridge as local bridge or DTMF is not compatible
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge.c: Bridge technology softmix does not have any capabilities we want.
[2025-10-20 12:38:02.912] DEBUG[34386] cdr.c: Finalized CDR for PJSIP/pbx1-0000066b - start 1760956678.032930 answer 1760956682.910493 end 1760956682.911804 dur 4.878 bill 0.001 dispo ANSWERED
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge.c: Chose bridge technology simple_bridge
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7 is already using the new technology.
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: 0x7f6374018190(PJSIP/intercom-0000066a) is joining simple_bridge technology
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/intercom-0000066a setting read format path: alaw -> alaw
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/pbx1-0000066b setting write format path: alaw -> alaw
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/pbx1-0000066b setting read format path: alaw -> alaw
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] channel.c: Channel PJSIP/intercom-0000066a setting write format path: alaw -> alaw
[2025-10-20 12:38:02.912] DEBUG[39061][C-00000407] channel.c: PJSIP/pbx1-0000066b: Topologies already match. Current:  <0:audio-0:audio:sendrecv (alaw)>  Requested:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Terminated  Inv State: CONNECTING
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Terminated  Inv State: CONNECTING
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a Event: RX_MSG  Inv State: CONFIRMED
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a Request: ACK 
[2025-10-20 12:38:02.913] DEBUG[64871] res_pjsip_session.c:  PJSIP/intercom-0000066a Handled request ACK  ? yes
[2025-10-20 12:38:02.926] DEBUG[39071][C-00000407] res_rtp_asterisk.c: (1760956678.3924) RTP ooh, format changed from none to alaw
[2025-10-20 12:38:02.926] DEBUG[39071][C-00000407] res_rtp_asterisk.c: (1760956678.3924) RTCP starting transmission in 5000 ms
[2025-10-20 12:38:02.983] DEBUG[39061][C-00000407] res_rtp_asterisk.c: (1760956678.3923) RTP ooh, format changed from none to alaw
[2025-10-20 12:38:04.341] DEBUG[38976] threadpool.c: Worker thread idle timeout reached. Dying.
[2025-10-20 12:38:07.925] DEBUG[39061][C-00000407] res_rtp_asterisk.c: (1760956678.3923) RTCP got report of 64 bytes from 10.6.9.10:16011
[2025-10-20 12:38:07.925] DEBUG[39061][C-00000407] res_rtp_asterisk.c: 1760956678.3923: rtt: 0.000000000 j: 0.000125000 sjh: 0.000000000 lost: 0.000000000 mes: 88.1
[2025-10-20 12:38:07.925] DEBUG[34425] res_rtp_asterisk.c:    1760956678.3923: rtt: 0.000000000 j: 0.000125000 sjh: 0.000440872 lost: 0.000000000 mes: 88.1
[2025-10-20 12:38:07.925] DEBUG[34425] res_rtp_asterisk.c:    1760956678.3924: rtt: 0.000000000 j: 0.000125000 sjh: 0.000050555 lost: 0.000000000 mes: 88.1
[2025-10-20 12:38:07.927] DEBUG[39071][C-00000407] res_rtp_asterisk.c: (1760956678.3924) RTCP got report of 64 bytes from 10.11.12.13:16691
[2025-10-20 12:38:07.927] DEBUG[39071][C-00000407] res_rtp_asterisk.c: 1760956678.3924: rtt: 0.001586000 j: 0.000125000 sjh: 0.000000000 lost: 0.000000000 mes: 88.1
[2025-10-20 12:38:10.042] DEBUG[36922] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:38:10.042] DEBUG[36922] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:38:10.042] DEBUG[36922] res_config_odbc.c: Parameter 1 ('id') = 'STARFACE@10.11.12.13'
[2025-10-20 12:38:10.042] DEBUG[36922] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:38:10.043] DEBUG[36922] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:38:10.043] DEBUG[36922] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:38:10.043] DEBUG[36922] res_config_odbc.c: Parameter 1 ('id') = 'STARFACE'
[2025-10-20 12:38:10.043] DEBUG[36922] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:38:10.953] DEBUG[64871] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:38:10.953] DEBUG[64871] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:38:10.954] DEBUG[64871] res_config_odbc.c: Parameter 1 ('id') = 'STARFACE@10.11.12.13'
[2025-10-20 12:38:10.954] DEBUG[64871] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:38:10.954] DEBUG[64871] res_odbc.c: Reusing ODBC handle 0x561d27719540 from class 'asterisk'
[2025-10-20 12:38:10.954] DEBUG[64871] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[2025-10-20 12:38:10.956] DEBUG[64871] res_config_odbc.c: Parameter 1 ('id') = 'STARFACE'
[2025-10-20 12:38:10.956] DEBUG[64871] res_odbc.c: Releasing ODBC handle 0x561d27719540 into pool
[2025-10-20 12:38:11.649] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Trying  Inv State: CONFIRMED
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Completed  Inv State: CONFIRMED
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Completed  Inv State: CONFIRMED
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b Event: TSX_STATE  Inv State: DISCONNECTED
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  PJSIP/pbx1-0000066b TSX State: Completed  Inv State: DISCONNECTED
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[2025-10-20 12:38:11.650] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:11.650] DEBUG[36922] chan_pjsip.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:38:11.651] DEBUG[36922] chan_pjsip.c:  
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge_channel.c: Setting 0x7f6374017ff0(PJSIP/pbx1-0000066b) state from:0 to:1
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: pulling 0x7f6374017ff0(PJSIP/pbx1-0000066b)
[2025-10-20 12:38:11.651] VERBOSE[39071][C-00000407] bridge_channel.c: Channel PJSIP/pbx1-0000066b left 'simple_bridge' basic-bridge <122f8daf-49ca-4f32-a182-53103b5a43c7>
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: 0x7f6374017ff0(PJSIP/pbx1-0000066b) is leaving simple_bridge technology
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): dissolving with cause 16(Normal Clearing)
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): kicking channel PJSIP/intercom-0000066a
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge_channel.c: Setting 0x7f6374018190(PJSIP/intercom-0000066a) state from:0 to:2
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: queueing action type:13 sub:1001
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): DEFERRED_DISSOLVING queued.  current refcound: 4
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7 is dissolved, not performing smart bridge operation.
[2025-10-20 12:38:11.651] DEBUG[34386] cdr.c: Finalized CDR for PJSIP/intercom-0000066a - start 1760956678.025776 answer 1760956682.910674 end 1760956691.651623 dur 13.625 bill 8.740 dispo ANSWERED
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] channel.c: Channel 0x7f637400e630 'PJSIP/pbx1-0000066b' hanging up.  Refs: 2
[2025-10-20 12:38:11.651] DEBUG[39061][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: pulling 0x7f6374018190(PJSIP/intercom-0000066a)
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] chan_pjsip.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:38:11.651] VERBOSE[39061][C-00000407] bridge_channel.c: Channel PJSIP/intercom-0000066a left 'simple_bridge' basic-bridge <122f8daf-49ca-4f32-a182-53103b5a43c7>
[2025-10-20 12:38:11.651] DEBUG[39061][C-00000407] bridge_channel.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: 0x7f6374018190(PJSIP/intercom-0000066a) is leaving simple_bridge technology
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[2025-10-20 12:38:11.651] DEBUG[39061][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7 is dissolved, not performing smart bridge operation.
[2025-10-20 12:38:11.651] DEBUG[39071][C-00000407] chan_pjsip.c:  Cause: 0
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): unlinking bridge.  Refcount: 3
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): unlinked bridge.  Refcount: 2
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): actually destroying basic bridge, nobody wants it anymore
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] stasis_bridges.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): destroying topics
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] stasis.c: Destroying topic. name: bridge:all/bridge:122f8daf-49ca-4f32-a182-53103b5a43c7, detail: 
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] stasis.c: Topic 'bridge:all/bridge:122f8daf-49ca-4f32-a182-53103b5a43c7': 0x7f6374017df0 destroyed
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: calling basic bridge destructor
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): destroying bridge (noop)
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: calling simple_bridge technology stop
[2025-10-20 12:38:11.651] DEBUG[64871] chan_pjsip.c:  PJSIP/pbx1-0000066b
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7: calling simple_bridge technology destructor
[2025-10-20 12:38:11.651] DEBUG[34377][C-00000407] bridge.c: Bridge 122f8daf-49ca-4f32-a182-53103b5a43c7(<unknown>)(0x7f63740168f0): destroyed
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] app_dial.c:  PJSIP/intercom-0000066a: Done
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Spawn extension (aroute,~~s~~,19) exited non-zero on 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Spawn extension (aroute, ~~s~~, 19) exited non-zero on 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] channel.c: Soft-Hanging (0x80) up channel 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'Goto'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@aroute:1] Goto("PJSIP/intercom-0000066a", "9991") in new stack
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx_builtins.c: Goto (aroute,h,9991)
[2025-10-20 12:38:11.652] DEBUG[64871] res_pjsip_session.c:  PJSIP/pbx1-0000066b Response 0
[2025-10-20 12:38:11.652] DEBUG[64871] res_rtp_asterisk.c: (1760956678.3924) RTP Stop
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx_variables.c: Function STACK_PEEK(1,c,1) result is 'in_intercom'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'Set'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@aroute:9991] Set("PJSIP/intercom-0000066a", "~~parentcxt~~=in_intercom") in new stack
[2025-10-20 12:38:11.652] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE RTP transport deallocating
[2025-10-20 12:38:11.652] DEBUG[64871] res_rtp_asterisk.c: (0x7f63000e25a0) ICE stopped
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx_variables.c: Expression result is '0'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'GotoIf'
[2025-10-20 12:38:11.652] DEBUG[64871] rtp_engine.c: Destroyed RTP instance '0x7f63000e25a0'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@aroute:9992] GotoIf("PJSIP/intercom-0000066a", "0?9996") in new stack
[2025-10-20 12:38:11.652] DEBUG[64871] res_pjsip_session.c:  
[2025-10-20 12:38:11.652] DEBUG[64871] channel.c: Channel 0x7f637400e630 'PJSIP/pbx1-0000066b' destroying
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx_builtins.c: Not taking any branch
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx_variables.c: Function DIALPLAN_EXISTS(in_intercom,h,1) result is '1'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'GotoIf'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@aroute:9993] GotoIf("PJSIP/intercom-0000066a", "1?9994:9996") in new stack
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx_builtins.c: Goto (aroute,h,9994)
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'StackPop'
[2025-10-20 12:38:11.652] DEBUG[64871] stasis.c: Destroying topic. name: channel:1760956678.3924, detail: 
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@aroute:9994] StackPop("PJSIP/intercom-0000066a", "") in new stack
[2025-10-20 12:38:11.652] DEBUG[64871] stasis.c: Topic 'channel:1760956678.3924': 0x7f6374018890 destroyed
[2025-10-20 12:38:11.652] DEBUG[34386] cdr.c: CDR for PJSIP/pbx1-0000066b is dialed and has no Party B; discarding
[2025-10-20 12:38:11.652] DEBUG[64871] channel_internal_api.c:  <initializing>: MultistreamFormats: (nothing)
[2025-10-20 12:38:11.652] DEBUG[64871] channel_internal_api.c:  Channel is being initialized or destroyed
[2025-10-20 12:38:11.652] DEBUG[64871] chan_pjsip.c:  
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'Goto'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@aroute:9995] Goto("PJSIP/intercom-0000066a", "in_intercom,h,1") in new stack
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx_builtins.c: Goto (in_intercom,h,1)
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Launching 'Hangup'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Executing [h@in_intercom:1] Hangup("PJSIP/intercom-0000066a", "") in new stack
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] pbx.c: Spawn extension (in_intercom,h,1) exited non-zero on 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] VERBOSE[39061][C-00000407] pbx.c: Spawn extension (in_intercom, h, 1) exited non-zero on 'PJSIP/intercom-0000066a'
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] channel.c: Channel 0x7f6300c498b0 'PJSIP/intercom-0000066a' hanging up.  Refs: 2
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] chan_pjsip.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP)
[2025-10-20 12:38:11.652] DEBUG[39061][C-00000407] chan_pjsip.c:  Cause: 0
[2025-10-20 12:38:11.653] DEBUG[36922] chan_pjsip.c:  PJSIP/intercom-0000066a
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a Response 0
[2025-10-20 12:38:11.653] DEBUG[36922] res_rtp_asterisk.c: (1760956678.3923) RTP Stop
[2025-10-20 12:38:11.653] DEBUG[36922] res_rtp_asterisk.c: (0x7f630013c060) ICE RTP transport deallocating
[2025-10-20 12:38:11.653] DEBUG[36922] rtp_engine.c: Destroyed RTP instance '0x7f630013c060'
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a Event: TSX_STATE  Inv State: DISCONNECTED
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Terminated  Inv State: DISCONNECTED
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  Nothing delayed
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  PJSIP/intercom-0000066a TSX State: Terminated  Inv State: DISCONNECTED
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  Topology: Pending: (null topology)  Active: (null topology)
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:11.653] DEBUG[36922] res_pjsip_session.c:  
[2025-10-20 12:38:11.653] DEBUG[36922] channel.c: Channel 0x7f6300c498b0 'PJSIP/intercom-0000066a' destroying
[2025-10-20 12:38:11.653] DEBUG[36922] stasis.c: Destroying topic. name: channel:1760956678.3923, detail: 
[2025-10-20 12:38:11.653] DEBUG[36922] stasis.c: Topic 'channel:1760956678.3923': 0x7f630001ec60 destroyed
[2025-10-20 12:38:11.653] DEBUG[36922] channel_internal_api.c:  <initializing>: MultistreamFormats: (nothing)
[2025-10-20 12:38:11.653] DEBUG[36922] channel_internal_api.c:  Channel is being initialized or destroyed
[2025-10-20 12:38:11.653] DEBUG[36922] chan_pjsip.c:  
[2025-10-20 12:38:11.653] DEBUG[36922] chan_pjsip.c:  intercom
[2025-10-20 12:38:11.653] DEBUG[34386] stasis.c: Creating topic. name: channel:1760956691.3925, detail: 
[2025-10-20 12:38:11.653] DEBUG[36922] chan_pjsip.c:  No channel
[2025-10-20 12:38:11.653] DEBUG[34386] stasis.c: Topic 'channel:1760956691.3925': 0x7f630c002e10 created
[2025-10-20 12:38:11.653] DEBUG[34386] stasis.c: Destroying topic. name: channel:1760956691.3925, detail: 
[2025-10-20 12:38:11.653] DEBUG[34386] stasis.c: Topic 'channel:1760956691.3925': 0x7f630c002e10 destroyed

jcolp · October 20, 2025, 11:28am

Did you follow the instructions for logging? I would expect more.

david551 · October 20, 2025, 2:23pm

BYE is never forwarded as such. It is converted into AST_CONTROL_HANGUP, which is passed to the controlling application. That logic may call hangup on a chan_pjsip driver on the other side, which will cause that driver to send BYE, but could just wait for actions by that side. Without details of the dialplan, or other call control logic, it is not even possible to say that there is anything wrong here.

Smurf · October 20, 2025, 2:53pm

The dialplan essentially consists of a Dial() followed by a Hangup(); also, afterwards pjsip as well as core show zero open channels.

Presumably, closing an active call’s pjsip channel without sending or receiving a BYE for it should be impossible, no? (And if sending that BYE is not possible for some reason I’d expect a big fat warning. Keeping a call open can cost real money, after all.)

Sorry about the missing logging, log levels got reset from under my feet by our automagic config management. Will recreate later.

Smurf · October 20, 2025, 4:33pm

Ok so I found the root cause, which is partly egg-on-my-face (and/or on the person who wrote the Ansible script) but also partly what-the-heck-PJSIP.

The problem was that, while both sides of the call were happily connecting to my server using TCP, the corresponding endpoints in pjsip.conf referred to a UDP transport (same address and port). Interestingly (and IMHO buggily) this didn’t prevent the incoming call from being accepted, associated with the endpoint (and its channel), forwarded, and subsequently getting terminated. The only missing piece was sending a BYE to the call’s originator.

I changed the transport to its TCP sibling, pjsip reloaded. and the problem went away.

However. While this solves the immediate problem, I do wonder why the call was accepted in the first place.

jcolp · October 20, 2025, 4:39pm

The transport setting doesn’t stop other transports or types from being used on inbound traffic, it only affects new outgoing requests in-dialog.

You also generally don’t need to specify it, unless you have multiple transports of the same type.

david551 · October 20, 2025, 6:51pm

It’s a feature. Asterisk will accept a call over any transport; the transport setting only controls outbound operations.

Smurf · October 20, 2025, 7:40pm

Mmh. That seems to be a problem in this case as sending a BYE is an outbound operation … which (I’m assuming) ends up not matching the inbound call because of the mismatched transport? and thus doesn’t get sent at all, without a notification that something’s gone wrong … which I’d argue is not the intended result.

david551 · October 21, 2025, 2:49pm

If it doesn’t match based on the call ID, and tags, the remote party is broken. Unless the remote side has explicitly included a transport in their Contact header, any transport can be used (if the contact header uses a SIPS: URI, a secure transport must be used.)

Topic		Replies	Views
Responding to SIP messages on a different IP Asterisk Support	4	746	July 12, 2020
SIP call transfers Asterisk Support	0	277	March 24, 2006
Possible Major Bug: Reinvites with Multiple Switches Asterisk Support	1	369	June 16, 2007
X-Asterisk-HangupCause: Unknown X-Asterisk-HangupCauseCode:0 Asterisk Support	4	664	April 14, 2010
One way sound for sip calls Asterisk Support	0	318	February 26, 2006

PJSIP: not forwarding BYE ?!?

Related topics