[SOLVED - but no solution] Cant Add New Phones: 403 after IP Reconfig

markcrobinson · August 17, 2020, 7:30pm

Ran out of local IP addresses 192.168.1.x so I added 192.168.0.x in pfsense. New Netmask is 255.255.254.0
Since doing that, I can’t add new phones. Existing phones are working fine.

I noticed that in the intrusion detection, the IP of the new phone was banned.
Added to System Admin->Intrusion Detection Whitelist:
192.168.1.0/24
192.168.0.0/24

Checked System Admin->Netmask currently set at
23
Changed it to 255.255.254.0
Changed itself back to 23

(the phone system is at 192.168.1.24)

Log:
Aug 17 15:20:39 [CRITIC] PHN: Warning: Ignore invalid parameter: hidden_tag
Aug 17 15:20:40 [CRITIC] SIP: Registrar [email protected] refused with code 403
Aug 17 15:20:48 [CRITIC] PHN: Warning: Ignore invalid parameter: hidden_tag
Aug 17 15:20:48 [CRITIC] PHN: Warning: Ignore invalid parameter: REREGISTER
Aug 17 15:20:49 [CRITIC] SIP: Registrar [email protected] refused with code 403

Sip Trace:
Sent to udp:224.0.1.75:5060 at Aug 17 19:13:08 (446 bytes):

SUBSCRIBE sip:MAC%[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:3072;rport
From: <sip:MAC%[email protected]>;tag=1779870087
To: <sip:MAC%[email protected]>
Call-ID: [email protected]
CSeq: 1 SUBSCRIBE
Event: ua-profile;profile-type=“device”;vendor=“snom”;model=“snom821”;version=“8.7.5.35”
Expires: 0
Accept: application/url
Contact: <sip:192.168.0.35:3072>
User-Agent:
Content-Length: 0

Debug Log, in case this helps:
Aug 17 15:27:01 [INFO ] PHN: new Tag: >kufj5u526qjikyx2< Filename: log.htm

Aug 17 15:27:03 [DEBUG2] PHN: TMR: ‘network.cpp (1315): [bool sip::message_repetition(const sip_message&, const str&, timestamp&)]’ 0x923818

Aug 17 15:27:03 [DEBUG1] SIP: remove receive packet: 12, all 2

Aug 17 15:27:03 [DEBUG2] PHN: TMR: ‘sip.cpp (770): [void sip::handle_message(sip_message&, const TransportAddress&)]’ 0x6d4dc4

Aug 17 15:27:03 [INFO ] SIP: Identity 1 reregister in 291000 ms.

Aug 17 15:27:03 [DEBUG2] PHN: TMR: ‘network.cpp (1315): [bool sip::message_repetition(const sip_message&, const str&, timestamp&)]’ 0x895718

Aug 17 15:27:03 [DEBUG1] SIP: remove receive packet: 13, all 1

Aug 17 15:27:03 [INFO ] PHN: WEB: Request 55/548/0: GET /line_login.htm?l=1 HTTP/1.1

Aug 17 15:27:03 [INFO ] PHN: WEB: 55 Basic authentication.

Aug 17 15:27:03 [INFO ] PHN: new Tag: >z12o6m59co25gx9a< Filename: line_login.htm

Aug 17 15:27:03 [INFO ] PHN: new Tag: >wszqy1g85itnffey< Filename: line_login.htm

Aug 17 15:27:05 [INFO ] PHN: WEB: Request 55/1110/0: POST /line_login.htm?l=1 HTTP/1.1

Aug 17 15:27:05 [INFO ] PHN: WEB: 55 Basic authentication.

Aug 17 15:27:05 [CRITIC] PHN: Warning: Ignore invalid parameter: hidden_tag

Aug 17 15:27:05 [CRITIC] PHN: Warning: Ignore invalid parameter: REREGISTER

Aug 17 15:27:05 [DEBUG2] SIP: sip::send_register: reg=0, ttl=3600

Aug 17 15:27:05 [DEBUG2] PHN: SipRedirectTargets::PopExpired

Aug 17 15:27:05 [DEBUG1] SIP: Routing to outbound proxy: sip:192.168.1.24

Aug 17 15:27:05 [DEBUG1] SIP: route pending packet 1000014: entry=url ? sip:192.168.1.24 all 4

Aug 17 15:27:05 [DEBUG1] SIP: route pending packet 1000014: entry=udp 192.168.1.24 5060 all 4

Aug 17 15:27:05 [DEBUG1] SIP: Identity 3bkooik4 connection id udp:192.168.1.24:5060

Aug 17 15:27:05 [DEBUG0] SIP: Use Connection udp:192.168.1.24:5060 for packet 1000014

Aug 17 15:27:05 [DEBUG0] SIP: send REGISTER (9: 313539373639313539333431343935-19zukfby4v8n) -> udp:192.168.1.24:5060

Aug 17 15:27:05 [DEBUG2] SIP: Updated Transport 0x888760 TTL 60

Aug 17 15:27:05 [DEBUG2] SIP: Registration Metrics start

Aug 17 15:27:05 [DEBUG1] SIP: Routing to outbound proxy: sip:192.168.1.24

Aug 17 15:27:05 [DEBUG1] SIP: route pending packet 1000015: entry=url ? sip:192.168.1.24 all 5

Aug 17 15:27:05 [DEBUG1] SIP: route pending packet 1000015: entry=udp 192.168.1.24 5060 all 5

Aug 17 15:27:05 [DEBUG2] SIP: Trusted IP Addresses: udp:192.168.1.24

Aug 17 15:27:05 [INFO ] PHN: new Tag: >i6miqmlfm5ewlq6b< Filename: line_login.htm

Aug 17 15:27:05 [INFO ] PHN: new Tag: >jh1l19g8gb9lmcwo< Filename: line_login.htm

Aug 17 15:27:06 [NOTICE] PHN: TPL: Socket 56 idle/connect timeout

Aug 17 15:27:06 [DEBUG2] PHN: WEB: HTTP 56/80 disconnected

Aug 17 15:27:06 [DEBUG2] PHN: WEB: HTTP 56/80 deleted

Aug 17 15:27:06 [DEBUG1] SIP: recv 401 REGISTER (9: 313539373639313539333431343935-19zukfby4v8n) <- udp:192.168.1.24:5060

Aug 17 15:27:06 [DEBUG2] SIP: clear message repetition 1000014 313539373639313539333431343935-19zukfby4v8n

Aug 17 15:27:06 [DEBUG2] SIP: sip::process_auth Identity=0, Digest algorithm=MD5, realm=“asterisk”, nonce=“19e8d325”

Aug 17 15:27:06 [WARN ] SIP: process_registrar_packet: 401 needs 128 bit nonce

Aug 17 15:27:06 [NOTICE] SIP: process auth: Match challenge for user=609, realm=asterisk

Aug 17 15:27:06 [DEBUG1] SIP: Routing to explicit plan udp 192.168.1.24 5060

Aug 17 15:27:06 [DEBUG1] SIP: route pending packet 1000016: entry=udp 192.168.1.24 5060 all 6

Aug 17 15:27:06 [DEBUG1] SIP: Identity 3bkooik4 connection id udp:192.168.1.24:5060

Aug 17 15:27:06 [DEBUG0] SIP: Use Connection udp:192.168.1.24:5060 for packet 1000016

Aug 17 15:27:06 [DEBUG0] SIP: send REGISTER (10: 313539373639313539333431343935-19zukfby4v8n) -> udp:192.168.1.24:5060

Aug 17 15:27:06 [DEBUG2] SIP: Updated Transport 0x888760 TTL 60

Aug 17 15:27:06 [DEBUG1] SIP: recv 403 REGISTER (10: 313539373639313539333431343935-19zukfby4v8n) <- udp:192.168.1.24:5060

Aug 17 15:27:06 [DEBUG2] SIP: clear message repetition 1000016 313539373639313539333431343935-19zukfby4v8n

Aug 17 15:27:06 [DEBUG0] SIP: sip::process_registrar_packet: Received 403 Forbidden

Aug 17 15:27:06 [CRITIC] SIP: Registrar [email protected] refused with code 403

Aug 17 15:27:06 [DEBUG2] PHN: SipRedirectTargets::PopExpired

Aug 17 15:27:06 [DEBUG2] PHN: SipRedirectTargets::Clear

Aug 17 15:27:06 [DEBUG2] SIP: Registration Metrics: 403, , 0, 300

Aug 17 15:27:06 [DEBUG2] SIP: registration report 403/0: ‘’

Aug 17 15:27:09 [DEBUG2] PHN: WEB: HTTP accepting from tcp:192.168.1.159:64506

Aug 17 15:27:09 [DEBUG2] PHN: WEB: HTTP 57/80 accepted from tcp:192.168.1.159:64506

Aug 17 15:27:09 [DEBUG2] PHN: WEB: HTTP 57/80 connected

Aug 17 15:27:09 [INFO ] PHN: WEB: Request 55/548/0: GET /log.htm HTTP/1.1

Aug 17 15:27:09 [INFO ] PHN: WEB: 55 Basic authentication.

Aug 17 15:27:09 [INFO ] PHN: new Tag: >yijzkp0d58e02zmy< Filename: log.htm
$\ 12x12$

mbrooks · August 17, 2020, 8:02pm

My guess is that one of the usernames/passwords is invalid on one of the phones. A 403 error typically indicates that there is something wrong with authentication. I wonder if the invalid authentication maybe causing fail2ban to ignore the whitelist rules and ban it anyways.

markcrobinson · August 17, 2020, 10:34pm

I’m really clear that the u/p is correct.
Checked it by adding an identity 2 to an existing phone.

mbrooks · August 18, 2020, 3:08am

Is it possible that two phones are sharing a username and password? This might result in a 403 as well.

markcrobinson · August 18, 2020, 1:37pm

Suddenly just started working! I don’t know why. I didn’t do anything. Is this the new “Self Healing” version of FreePBX?

mbrooks · August 18, 2020, 3:28pm

@markcrobinson Ha! Glad it’s working. It really feels like something strange is happening with fail2ban. This tends to happen when the phones have been blacklisted, and then once the blacklist falls off after a few days, the phones start working again.

system · August 25, 2020, 3:28pm

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