Endpoint (PJSIP) becoming unreachable after the registration expiration

There are these Cisco phones on a remote network (connecting through static IP ports forwarded to PBX at main location).

The device becomes unreachable after the register expiration then it comes back 30secs later. the contact is being deleted.

Both locations behind NAT. SIP helper/ALG etc. all turned off at both locations.

There are softphone client apps registered remotely that never have this issue no matter what expiration is set on their end.

For the expirations on the phone, I’ve tried 30 secs/90/100/120/300/600 and after the expiration period it ALWAYS becomes unreachable for a certain period (usually up to 30secs after becoming reachable again) then it becomes reachable again.

The config in Extension settings from FreePBX:
Qualify Frequency: I’ve tried 15 and 25
Minimum expiration: 60 (I’ve tried 30, 60, 90, 100, 120, 300, 600)
Maximum expiration: 7200

10765	[2022-06-02 11:52:56] VERBOSE[11971] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Unreachable. RTT: 0.000 msec	
10766	[2022-06-02 11:53:18] VERBOSE[933] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Reachable. RTT: 31.627 msec	
10767	[2022-06-02 11:55:51] VERBOSE[12924] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Unreachable. RTT: 0.000 msec	
10768	[2022-06-02 11:56:38] VERBOSE[16560] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Reachable. RTT: 37.059 msec	
10769	[2022-06-02 11:56:38] VERBOSE[12924] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 has been deleted	
10770	[2022-06-02 11:56:38] VERBOSE[19855] res_pjsip_registrar.c: Added contact 'sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060' to AOR '123' with expiration of 60 seconds	
10771	[2022-06-02 11:56:38] VERBOSE[19855] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Reachable. RTT: 44.356 msec	
10772	[2022-06-02 11:58:46] VERBOSE[31967] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Unreachable. RTT: 0.000 msec	
10773	[2022-06-02 11:59:21] VERBOSE[19855] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 has been deleted	
10774	[2022-06-02 11:59:42] VERBOSE[19855] res_pjsip_registrar.c: Added contact 'sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060' to AOR '123' with expiration of 60 seconds	
10775	[2022-06-02 11:59:42] VERBOSE[933] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Reachable. RTT: 38.476 msec	
10776	[2022-06-02 12:01:25] VERBOSE[16560] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Unreachable. RTT: 0.000 msec	
10777	[2022-06-02 12:02:12] VERBOSE[16560] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Reachable. RTT: 44.352 msec	
10778	[2022-06-02 12:02:40] VERBOSE[11971] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Unreachable. RTT: 0.000 msec	
10779	[2022-06-02 12:03:03] VERBOSE[25564] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 has been deleted	
10780	[2022-06-02 12:04:18] VERBOSE[19855] res_pjsip_registrar.c: Added contact 'sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060' to AOR '123' with expiration of 60 seconds	
10781	[2022-06-02 12:04:18] VERBOSE[11971] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Reachable. RTT: 38.274 msec	
11265	[2022-06-02 12:05:11] VERBOSE[933] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 is now Unreachable. RTT: 0.000 msec	
11266	[2022-06-02 12:05:26] VERBOSE[12924] res_pjsip/pjsip_options.c: Contact 123/sip:[email protected]:1024;x-ast-orig-host=192.168.2.246:5060 has been deleted	

ideas?

TBH, some Cisco Phones are a PITA to configure.

Do you see the OPTIONS being sent to the phone? And does it respond?

These are Cisco 3PCC phones which are good phones and worked 100% fine on cloud PBXs previously. Sending OPTIONS.

Here are some of the PJSIP logs for this device.
Note it is on a remote network and there are two devices under one extension. One softphone client which receives registration errors sometimes, and the other device is the Cisco-8861-3PCC phone. Max contacts is set to 10 for this extension. Please advise how to fix the registration/unreachability and unauthorized errors.

5478	[2022-06-03 08:34:38] VERBOSE[26243] res_pjsip_logger.c: <--- Received SIP request (661 bytes) from UDP:REMOTEIPOFPHONE:1024 --->	
5479	NOTIFY sip:PUBLICIPOFPBX:42859 SIP/2.0	
5480	Via: SIP/2.0/UDP 192.168.2.246:42859;branch=z9hG4bK-778f61bd;rport	
5481	From: "100" <sip:[email protected]>;tag=5cb4254e299fa210o0	
5482	To: <sip:PUBLICIPOFPBX>	
5483	Call-ID: [email protected]	
5484	CSeq: 1509 NOTIFY	
5485	Max-Forwards: 70	
5486	Authorization: Digest username="100",realm="asterisk",nonce="1654259571/53d5e971fed4efde0c34edce03e00ca8",uri="sip:PUBLICIPOFPBX:42859",algorithm=MD5,response="d5014c512ccd1c11491a3a6f31edd201",opaque="2ad33ab80429cf62",qop=auth,nc=00000004,cnonce="2a717ab3"	
5487	Contact: "100" <sip:[email protected]:42859>	
5488	Event: keep-alive	
5489	User-Agent: Cisco-CP-8861-3PCC/11.3.2	
5490	Content-Length: 0	
5491		
5492		
5493	[2022-06-03 08:34:38] VERBOSE[16560] res_pjsip_logger.c: <--- Transmitting SIP response (504 bytes) to UDP:REMOTEIPOFPHONE:1024 --->	
5494	SIP/2.0 401 Unauthorized	
5495	Via: SIP/2.0/UDP 192.168.2.246:42859;rport=1024;received=REMOTEIPOFPHONE;branch=z9hG4bK-778f61bd	
5496	Call-ID: [email protected]	
5497	From: "100" <sip:[email protected]>;tag=5cb4254e299fa210o0	
5498	To: <sip:PUBLICIPOFPBX>;tag=z9hG4bK-778f61bd	
5499	CSeq: 1509 NOTIFY	
5500	WWW-Authenticate: Digest realm="asterisk",nonce="1654259678/6b6cf73501e742348c45dcfe9c060e58",opaque="5754fec277c046b3",stale=true,algorithm=MD5,qop="auth"	
5501	Server: PBXact-15.0.23(16.26.0)	
5502	Content-Length: 0	
5503		
5504		
5505	[2022-06-03 08:34:38] VERBOSE[26243] res_pjsip_logger.c: <--- Received SIP request (511 bytes) from UDP:REMOTEIPOFPHONE:1024 --->	
5506	REGISTER sip:PUBLICIPOFPBX:42859 SIP/2.0	
5507	Via: SIP/2.0/UDP 192.168.2.246:42859;branch=z9hG4bK-23b9caa1;rport	
5508	From: "100" <sip:[email protected]>;tag=5cb4254e299fa210o0	
5509	To: "100" <sip:[email protected]>	
5510	Call-ID: [email protected]	
5511	CSeq: 59796 REGISTER	
5512	Max-Forwards: 70	
5513	Contact: "100" <sip:[email protected]:42859>;expires=300	
5514	User-Agent: Cisco-CP-8861-3PCC/11.3.2	
5515	Content-Length: 0	
5516	Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE	
5517	Supported: replaces, sec-agree	
5518		
5519		
5520	[2022-06-03 08:34:38] VERBOSE[11971] res_pjsip_logger.c: <--- Transmitting SIP response (506 bytes) to UDP:REMOTEIPOFPHONE:1024 --->	
5521	SIP/2.0 401 Unauthorized	
5522	Via: SIP/2.0/UDP 192.168.2.246:42859;rport=1024;received=REMOTEIPOFPHONE;branch=z9hG4bK-23b9caa1	
5523	Call-ID: [email protected]	
5524	From: "100" <sip:[email protected]>;tag=5cb4254e299fa210o0	
5525	To: "100" <sip:[email protected]>;tag=z9hG4bK-23b9caa1	
5526	CSeq: 59796 REGISTER	
5527	WWW-Authenticate: Digest realm="asterisk",nonce="1654259678/6b6cf73501e742348c45dcfe9c060e58",opaque="6557a01d0c6cfe5c",algorithm=MD5,qop="auth"	
5528	Server: PBXact-15.0.23(16.26.0)	
5529	Content-Length: 0	
5530		
5531		
5532	[2022-06-03 08:34:39] VERBOSE[26243] res_pjsip_logger.c: <--- Received SIP request (511 bytes) from UDP:REMOTEIPOFPHONE:1024 --->	
5533	REGISTER sip:PUBLICIPOFPBX:42859 SIP/2.0	
5534	Via: SIP/2.0/UDP 192.168.2.246:42859;branch=z9hG4bK-23b9caa1;rport	
5535	From: "100" <sip:[email protected]>;tag=5cb4254e299fa210o0	
5536	To: "100" <sip:[email protected]>	
5537	Call-ID: [email protected]	
5538	CSeq: 59796 REGISTER	
5539	Max-Forwards: 70	
5540	Contact: "100" <sip:[email protected]:42859>;expires=300	
5541	User-Agent: Cisco-CP-8861-3PCC/11.3.2	
5542	Content-Length: 0	
5543	Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE	
5544	Supported: replaces, sec-agree	
5545		
5546		
5547	[2022-06-03 08:34:39] VERBOSE[12924] res_pjsip_logger.c: <--- Transmitting SIP response (506 bytes) to UDP:REMOTEIPOFPHONE:1024 --->	
5548	SIP/2.0 401 Unauthorized	
5549	Via: SIP/2.0/UDP 192.168.2.246:42859;rport=1024;received=REMOTEIPOFPHONE;branch=z9hG4bK-23b9caa1	
5550	Call-ID: [email protected]	
5551	From: "100" <sip:[email protected]>;tag=5cb4254e299fa210o0	
5552	To: "100" <sip:[email protected]>;tag=z9hG4bK-23b9caa1	
5553	CSeq: 59796 REGISTER	
5554	WWW-Authenticate: Digest realm="asterisk",nonce="1654259679/737f3022a76d1da1d77deb18188560bb",opaque="5a4142802add0238",algorithm=MD5,qop="auth"	
5555	Server: PBXact-15.0.23(16.26.0)	
5556	Content-Length: 0

5612	[2022-06-03 08:34:40] VERBOSE[26243] res_pjsip_logger.c: <--- Transmitting SIP request (431 bytes) to UDP:REMOTEIPOFPHONE:1024 --->	
5613	OPTIONS sip:[email protected]:1024 SIP/2.0	
5614	Via: SIP/2.0/UDP PUBLICIPOFPBX:42859;rport;branch=z9hG4bKPj61a229b2-1d67-42d6-a981-89170af7f348	
5615	From: <sip:[email protected]>;tag=986b8343-fce2-494b-9891-bac910d0104c	
5616	To: <sip:[email protected]>	
5617	Contact: <sip:[email protected]:42859>	
5618	Call-ID: 2044debd-932f-43c4-a38d-f7a3c5545a64	
5619	CSeq: 37773 OPTIONS	
5620	Max-Forwards: 70	
5621	User-Agent: PBXact-15.0.23(16.26.0)	
5622	Content-Length: 0

The Cisco is registering as though it were on the same LAN as Asterisk, and Asterisk is believing that. If that is not true, the responses to the REGISTER requests won’t get through, which is consistent with the Cisco failing to authenticate itself, although that could also mean that the Cisco doesn’t know any password.

The OPTIONS is being sent to a public address, which is not consistent with the above interpretation of the Cisco’s address. It is not getting a reply. If the Cisco really is local, the router may not like trying to send things to one of its own public addresses. If it is remote, the problem may well be that Cisco phones are designed for large corporate intranets, not for lots of remote workers.

This address conflict may also mean, depending on how you are trying to identify the Cisco, that the REGISERs from the LAN address are being treated as from an unknown caller, and 401 is being faked so as not to give clues as to valid URIs.

PS In general it is not realistic to ask for specific fixes, a things are seldom that simple. You should really expect hints as to problem areas, which you need to integrate with knowledge of your own system.

Thanks for your analysis and insights

The Cisco is on a totally separate network, not on the LAN. It should be connecting to the PBX through NAT. I also noticed that it was sending some requests with its’ internal IP - any idea how to correct this?

yes that’s what I mean thanks

Would you have ideas based on experience how to go about this
I really need it to stop becoming unreachable as it’s unusable that way
P.S. same thing’s happening with Grandstream phones on another external network so I believe this must be with PBX config i.e. what to adjust with qualify/expiration/timers etc.

On the Firewall of the PBX’s network the UDP session timeout is 120 (the recommended level) and I’ve checked all the logs and it is not blocking any traffic from the phones. Maybe SIP helper or ALG should be enabled - isn’t that supposed to help translate the internal IPs to communicate better?

Actually I didn’t scroll the logs far enough right. Asterisk isn’t being confused by the wrong address in the request, probably because of rport parameter.

In that case, it looks like the things are getting lost between Asterisk and the Cisco. You will just have to monitor at various points until you find out where they are getting lost.

You probably can’t fix the wrong addresses, because you are simply using the Cisco out of its intended environment.

IMO, this is a simple networking problem.

Cisco sends REGISTER, starting on line 5505.
PBX sends 401, as expected, starting on line 5520.
Cisco re-transmits REGISTER, starting on line 5532.

IMO, it’s clear that Cisco did not ‘hear’ the 401, because the second register lacks an Authorization header and has the same CSeq as the first. So, capture traffic at the Cisco and see what’s there, then continue to debug accordingly. The problem may be a NAT timeout, bad SIP ALG in the path, etc.

Thanks. Attached are logs from the phone itself which show all of the SIP traffic/requests.
First I make a few successful calls to voicemail *97 then it becomes unreachable (and the PBX logs are just like the ones I showed earlier).
Cisco8861Logs.tgz (47.5 KB)

[WANIPOFPBX]:42859 SIP MSG

Your NAT router is being too clever for its own good. Either it is doing SIP Application Level Gateway, which is never a good idea with Asterisk, or it thinks this is a second dialogue, so port 5060 is busy and it has allocated a random port number, which fails to get translated back when the response reaches your router on its way back.

I setup phones to connect to the PBX through port 42859 on purpose, not 5060 since 5060 resulted in so many SIP scanners trying to break in
can you clarify?
SIP ALG is definitely turned off on both sides.

Apologies. I didn’t check carefully enough to see if you were using 5060 at the other side.

What is being shown is that some of the responses from the Cisco are reaching Asterisk, but others are not, which is weird.

Next thing is to use sngrep to see what is arriving at the Asterisk machine.

CORRECTION: The Cisco log is showing successful transactions. You need to provide a Cisco log from when it is failing. There is no way the Cisco can receive an OK to a REGISTER without Asterisk sending it.

Ok here is a full packet capture
during this period it becomes unreachable and then reachable several times
logcat-20220603-180013.log.tgz (78.8 KB)

Here is actually a log where the issue happens more frequently and there are more errors
Newciscologs.tgz (28.9 KB)

In the logcat log, we see the Cisco repeatedly sending REGISTER requests with no reply, lines 4578, 4580, 4584, 4591. Finally, the retransmit on line 4669 gets a response. But that is 11 seconds after the initial request, late enough that the previous registration has expired. We know from the PBX log that it’s the 401 responses that got dropped, not the REGISTER requests.

Capture traffic on the WAN interfaces to determine whether the trouble is with the branch network, the headquarters network, or the internet connection between them.

Attached is Firewall log from the WAN of the PBX (headquarters)
FirewallLog.tgz (132.7 KB)

You need to do some of the work and locate the registers and responses and where any are missing.

There was some deeper problem with the phones doing NAT traversal or qualify… so I just setup IPSEC site2site VPN between the sites Fortigates and haven’t any issues whatsoever since.

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