PJSIP Trunk Troubleshooting

comtech · April 25, 2023, 5:15pm

FYI, the link to Pastebin in the debug instructions is not working (error when clicked): Providing Great Debug - Support Services - Documentation (freepbx.org)

Backround:

We have an Avaya Session Manager we use for our SIP trunking between our carriers and PBXs (Avaya and FreePBX)
We have been trunking to these Avaya Session Managers using Chan SIP trunks for years without issue.
We decided to upgrade PJSIP trunks due to Chan deprecating.
We successfully registered PJSIP trunks from FreePBX to Avaya Session Manager.
Tested, calls to and from complete, good to go.

Issue:
I am noticing the trunks are registering, unregistering, the registering every few minutes. and when the trunks are down (obviously) no calls come through.

Question:
Any ideas on what could be the issue?

I turned on PJSIP logger and here is what it looks like:

[2023-04-25 15:28:02] VERBOSE[27210] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:aaa.aaa.aaa.aaa:5060 SIP/2.0

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport;branch=z9hG4bKPjec2425a6-4625-4e9d-859b-d5c442702562

From: <sip:[email protected]>;tag=5de5e9e9-c7ec-4c28-ad5b-092e38d6344b

To: <sip:aaa.aaa.aaa.aaa>

Contact: <sip:[email protected]:5060>

Call-ID: dd27df1b-dc8b-444a-b9fa-52eb38bf3919

CSeq: 49912 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:04] VERBOSE[27210] res_pjsip_logger.c: <--- Received SIP request (966 bytes) from UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:bbb.bbb.bbb.bbb SIP/2.0

Record-Route: <sip:[email protected];transport=udp;lr;av-asset-uid=5a5d9d4>

Route: <sip:bbb.bbb.bbb.bbb;lr;phase=terminating>

Expires: 0

Contact: <sip:127.0.0.2:15060;transport=udp;av-iptol>

User-Agent: AVAYA-SM-7.1.3.8.713803

Via: SIP/2.0/UDP aaa.aaa.aaa.aaa;rport;branch=z9hG4bK468443983003970-AP;ft=aaa.aaa.aaa.aaa~13c4

Via: SIP/2.0/UDP 127.0.0.2:15060;rport=15060;ibmsid=local.1678946784176_17192562_17293425;branch=z9hG4bK468443983003970

Via: SIP/2.0/UDP 127.0.0.2:15060;rport;ibmsid=local.1678946784176_17192561_17293424;branch=z9hG4bK18404213564229

Via: SIP/2.0/UDP 127.0.0.2:15060;rport;ibmsid=local.1678946784176_17192560_17293423;branch=z9hG4bK582580307778732

From: <sip:aaa.aaa.aaa.aaa>;tag=6807685546153528_local.1678946784176_17192560_17293423

To: <sip:bbb.bbb.bbb.bbb>

Call-ID: [email protected]

Max-Forwards: 67

CSeq: 2 OPTIONS

Av-Global-Session-ID: c5ac6460-e37d-11ed-9b77-000c29838dc6

Content-Length: 0

[2023-04-25 15:28:04] VERBOSE[25128] res_pjsip_logger.c: <--- Transmitting SIP response (1294 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

SIP/2.0 200 OK

Via: SIP/2.0/UDP aaa.aaa.aaa.aaa;rport=5060;received=aaa.aaa.aaa.aaa;branch=z9hG4bK468443983003970-AP;ft=aaa.aaa.aaa.aaa~13c4

Via: SIP/2.0/UDP 127.0.0.2:15060;rport=15060;branch=z9hG4bK468443983003970;ibmsid=local.1678946784176_17192562_17293425

Via: SIP/2.0/UDP 127.0.0.2:15060;rport;branch=z9hG4bK18404213564229;ibmsid=local.1678946784176_17192561_17293424

Via: SIP/2.0/UDP 127.0.0.2:15060;rport;branch=z9hG4bK582580307778732;ibmsid=local.1678946784176_17192560_17293423

Record-Route: <sip:[email protected];transport=udp;lr;av-asset-uid=5a5d9d4>

Call-ID: [email protected]

From: <sip:aaa.aaa.aaa.aaa>;tag=6807685546153528_local.1678946784176_17192560_17293423

To: <sip:bbb.bbb.bbb.bbb>;tag=z9hG4bK468443983003970-AP

CSeq: 2 OPTIONS

Accept: application/dialog-info+xml, application/simple-message-summary, application/pidf+xml, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, application/sdp, message/sipfrag;version=2.0

Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER

Supported: 100rel, timer, replaces, norefersub

Accept-Encoding: text/plain

Accept-Language: en

Server: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:06] VERBOSE[27210] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:aaa.aaa.aaa.aaa:5060 SIP/2.0

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport;branch=z9hG4bKPjec2425a6-4625-4e9d-859b-d5c442702562

From: <sip:[email protected]>;tag=5de5e9e9-c7ec-4c28-ad5b-092e38d6344b

To: <sip:aaa.aaa.aaa.aaa>

Contact: <sip:[email protected]:5060>

Call-ID: dd27df1b-dc8b-444a-b9fa-52eb38bf3919

CSeq: 49912 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:10] VERBOSE[27210] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:aaa.aaa.aaa.aaa:5060 SIP/2.0

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport;branch=z9hG4bKPjec2425a6-4625-4e9d-859b-d5c442702562

From: <sip:[email protected]>;tag=5de5e9e9-c7ec-4c28-ad5b-092e38d6344b

To: <sip:aaa.aaa.aaa.aaa>

Contact: <sip:[email protected]:5060>

Call-ID: dd27df1b-dc8b-444a-b9fa-52eb38bf3919

CSeq: 49912 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:14] VERBOSE[27210] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:aaa.aaa.aaa.aaa:5060 SIP/2.0

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport;branch=z9hG4bKPjec2425a6-4625-4e9d-859b-d5c442702562

From: <sip:[email protected]>;tag=5de5e9e9-c7ec-4c28-ad5b-092e38d6344b

To: <sip:aaa.aaa.aaa.aaa>

Contact: <sip:[email protected]:5060>

Call-ID: dd27df1b-dc8b-444a-b9fa-52eb38bf3919

CSeq: 49912 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:18] VERBOSE[27210] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:aaa.aaa.aaa.aaa:5060 SIP/2.0

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport;branch=z9hG4bKPjec2425a6-4625-4e9d-859b-d5c442702562

From: <sip:[email protected]>;tag=5de5e9e9-c7ec-4c28-ad5b-092e38d6344b

To: <sip:aaa.aaa.aaa.aaa>

Contact: <sip:[email protected]:5060>

Call-ID: dd27df1b-dc8b-444a-b9fa-52eb38bf3919

CSeq: 49912 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:47] VERBOSE[14167] res_pjsip_logger.c: <--- Transmitting SIP request (424 bytes) to UDP:aaa.aaa.aaa.aaa:5060 --->

OPTIONS sip:aaa.aaa.aaa.aaa:5060 SIP/2.0

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport;branch=z9hG4bKPj41d13c65-8356-4a9b-b02e-ab9ffbfb3fb0

From: <sip:[email protected]>;tag=099455b0-e0dd-4e87-a233-902cb80b7b78

To: <sip:aaa.aaa.aaa.aaa>

Contact: <sip:[email protected]:5060>

Call-ID: 6b7b6b32-8adf-491e-b4ea-20e5ca128ad8

CSeq: 47004 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-15.0.37(16.13.0)

Content-Length: 0

[2023-04-25 15:28:47] VERBOSE[27210] res_pjsip_logger.c: <--- Received SIP response (571 bytes) from UDP:aaa.aaa.aaa.aaa:5060 --->

SIP/2.0 200 OK

Call-ID: 6b7b6b32-8adf-491e-b4ea-20e5ca128ad8

CSeq: 47004 OPTIONS

From: <sip:[email protected]>;tag=099455b0-e0dd-4e87-a233-902cb80b7b78

To: <sip:public.violet.uw.edu>;tag=385353311942778_local.1678946784176_17192883_17293756

Via: SIP/2.0/UDP bbb.bbb.bbb.bbb:5060;rport=5060;branch=z9hG4bKPj41d13c65-8356-4a9b-b02e-ab9ffbfb3fb0

Record-Route: <sip:[email protected];av-asset-uid=rw-5a5d9d4;lr>

Av-Global-Session-ID: df027210-e37d-11ed-9b77-000c29838dc6

Server: AVAYA-SM-7.1.3.8.713803

Contact: <sip:aaa.aaa.aaa.aaa:5060>

Content-Length: 0

[2023-04-25 15:28:47] VERBOSE[25128] res_pjsip/pjsip_configuration.c: Endpoint AVAYA-1-PJ is now Reachable

[2023-04-25 15:28:47] VERBOSE[25128] res_pjsip/pjsip_options.c: Contact AVAYA-1-PJ/sip:aaa.aaa.aaa.aaa:5060 is now Reachable. RTT: 26.715 msec

dobrosavljevic · April 25, 2023, 5:59pm

This log seems to be from when the session is setup at first. You may need to keep an eye on it and provide a log for when it unregisters and becomes unavailable.

comtech · April 27, 2023, 7:27am

Here is a bigger pull with the trunk going up then down then up.

Anyone have any ideas?

BlazeStudios · April 27, 2023, 11:12am

The Avaya isn’t responding to the keepalives from Asterisk.

Now I don’t know why the CSeq is jumping all over the place for them but there are at least three different keep alive attempts where the Avaya does not response and Asterisk resends the same OPTIONS request 6-7 times in a row.

It kind of seems like towards the end when the Avaya sends its own keepalive to Asterisk does it then respond to Asterisk’s keepalive requests.

dazzagrant · April 27, 2023, 1:07pm

Try connecting via ssh to FreePBX run sngrep
Filter for the Avaya IP and hopefully you’ll see the issue

system · May 28, 2023, 1:07pm

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.