write TCPv4_CLIENT: Permission Denied on OpenVPN client 24.03 RC
-
But are the WANs still reloading continually during that test?
Any time it kills the states on the WAN TCP connections will fail and have to be re-established. UDP connections would not though which seems to match what you're seeing.
-
Hi Steve,
I didn't notice any issue with the WAN. Also why there are no TCP write errors on 23.09.1?
I am sharing some more logs. This time from a given specific TCP client.
Apr 25 21:44:36 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:36 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:35 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:35 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:34 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:34 trail2 openvpn[88426]: MANAGEMENT: Client disconnected
Apr 25 21:44:34 trail2 openvpn[88426]: MANAGEMENT: CMD 'status 2'
Apr 25 21:44:34 trail2 openvpn[88426]: MANAGEMENT: CMD 'state 1'
Apr 25 21:44:34 trail2 openvpn[88426]: MANAGEMENT: Client connected from /var/etc/openvpn/client6/sock
Apr 25 21:44:34 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:33 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:33 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:32 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:32 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:31 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:31 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:30 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:30 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:29 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:29 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:28 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:28 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:27 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:27 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:26 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:25 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:25 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:24 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:24 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:23 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:23 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:22 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:22 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:21 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:21 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:20 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:20 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:19 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:19 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:18 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:18 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:17 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:17 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:16 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:16 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:15 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:15 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:14 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:14 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:13 trail2 openvpn[88426]: write TCPv4_CLIENT: Permission denied (fd=5,code=13)
Apr 25 21:44:11 trail2 openvpn[88426]: Timers: ping 10, ping-restart 120
Apr 25 21:44:11 trail2 openvpn[88426]: Data Channel: cipher 'AES-256-GCM', peer-id: 0, compression: 'stub'
Apr 25 21:44:11 trail2 openvpn[88426]: Initialization Sequence Completed
Apr 25 21:44:11 trail2 openvpn[88426]: /usr/local/sbin/ovpn-dnslinkup ovpnc6 1500 0 10.59.74.40 255.255.255.224 init
Apr 25 21:44:11 trail2 openvpn[88426]: /sbin/ifconfig ovpnc6 10.59.74.40/27 mtu 1500 up
Apr 25 21:44:11 trail2 openvpn[88426]: TUN/TAP device /dev/tun6 opened
Apr 25 21:44:11 trail2 openvpn[88426]: TUN/TAP device ovpnc6 exists previously, keep at program end
Apr 25 21:44:11 trail2 openvpn[88426]: Using peer cipher 'AES-256-GCM'
Apr 25 21:44:11 trail2 openvpn[88426]: OPTIONS IMPORT: route-related options modified
Apr 25 21:44:11 trail2 openvpn[88426]: OPTIONS IMPORT: --ifconfig/up options modified
Apr 25 21:44:11 trail2 openvpn[88426]: Socket Buffers: R=[65700->393216] S=[65700->393216]
Apr 25 21:44:11 trail2 openvpn[88426]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
Apr 25 21:44:11 trail2 openvpn[88426]: Options error: option 'dhcp-option' cannot be used in this context ([PUSH-OPTIONS])
Apr 25 21:44:11 trail2 openvpn[88426]: Options error: option 'dhcp-option' cannot be used in this context ([PUSH-OPTIONS])
Apr 25 21:44:11 trail2 openvpn[88426]: Options error: option 'redirect-gateway' cannot be used in this context ([PUSH-OPTIONS])
Apr 25 21:44:11 trail2 openvpn[88426]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 206.123.151.129,dhcp-option DNS 206.123.151.131,sndbuf 393216,rcvbuf 393216,comp-lzo no,route-gateway 10.59.74.33,topology subnet,ping 10,ping-restart 120,ifconfig 10.59.74.40 255.255.255.224,peer-id 0'
Apr 25 21:44:11 trail2 openvpn[88426]: SENT CONTROL [Secure-Server]: 'PUSH_REQUEST' (status=1)
Apr 25 21:44:10 trail2 openvpn[88426]: TLS: tls_multi_process: initial untrusted session promoted to trusted
Apr 25 21:44:10 trail2 openvpn[88426]: TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
Apr 25 21:44:10 trail2 openvpn[88426]: [Secure-Server] Peer Connection Initiated with [AF_INET]138.199.60.100:443 -
Are the WANs flapping like that in 23.09.1?
-
Hi Steve,
On 23.09.1, based on system logs, the WAN IP Address does change too but the TCP clients are more resilient and do not have the write / permission denied issue.
I am not sure how to fix the issue. I plan to change to a different ISP and test. I am not certain if changing to 24.03 aggravated the TCP issue.
Any suggestion on how to get the issue resolved?
Thx.
-
But are they what I would 'flapping' in the same way? In the logs from 24.03 it's pulling a new IP address every minute which cannot be right. And it logs killing the states on the interface every time that happens.
-
Hi Steve,
Whether WAN flapping was observed on 23.09.1, I didn't make a note. The next time I change the boot environment to 23.09.1, I will extract the WAN logs.
On 24.03, I extracted the WAN logs
Apr 26 21:32:54 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:32:03 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.7 -> 10.7.7.12 - Restarting packages.
Apr 26 21:31:14 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 21:30:43 trail2 php-fpm[30768]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:29:03 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 21:28:32 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:27:38 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.5 -> 10.7.7.7 - Restarting packages.
Apr 26 21:26:46 trail2 php-fpm[67201]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 21:26:21 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:24:55 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.6 -> 10.7.7.5 - Restarting packages.
Apr 26 21:24:24 trail2 php-fpm[30768]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:24:10 trail2 php-fpm[67201]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 21:22:30 trail2 php-fpm[30768]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 21:21:59 trail2 php-fpm[10821]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:21:11 trail2 php-fpm[10821]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.5 -> 10.7.7.6 - Restarting packages.
Apr 26 21:20:19 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 21:19:48 trail2 php-fpm[85785]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:18:08 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 21:17:37 trail2 php-fpm[85785]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:16:48 trail2 php-fpm[85783]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.3 -> 10.7.7.5 - Restarting packages.
Apr 26 21:15:57 trail2 php-fpm[85785]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:15:26 trail2 php-fpm[10821]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 21:13:46 trail2 php-fpm[10821]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:13:23 trail2 php-fpm[85783]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use WAN_DHCP.
Apr 26 21:13:22 trail2 check_reload_status[594]: updating dyndns WAN_DHCP
Apr 26 21:13:22 trail2 rc.gateway_alarm[51512]: >>> Gateway alarm: WAN_DHCP (Addr:1.1.1.1 Alarm:0 RTT:2.146ms RTTsd:.236ms Loss:0%)
Apr 26 21:13:15 trail2 php-fpm[30768]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 21:13:12 trail2 check_reload_status[594]: updating dyndns WAN_DHCP
Apr 26 21:13:12 trail2 rc.gateway_alarm[59627]: >>> Gateway alarm: WAN_DHCP (Addr:1.1.1.1 Alarm:1 RTT:2.244ms RTTsd:.080ms Loss:33%)
Apr 26 21:12:24 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.6 -> 10.7.7.3 - Restarting packages.
Apr 26 21:11:03 trail2 php-fpm[85783]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.40 -> 10.59.74.36 - Restarting packages.
Apr 26 21:09:53 trail2 php-fpm[67201]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 21:08:52 trail2 php-fpm[85783]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.40 - Restarting packages.
Apr 26 21:07:42 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:07:16 trail2 php-fpm[30768]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.15.19.6 -> 10.14.19.7 - Restarting packages.
Apr 26 21:06:52 trail2 php-fpm[85783]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.3 -> 10.7.7.6 - Restarting packages.
Apr 26 21:06:41 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:05:31 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 21:04:30 trail2 php-fpm[85785]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 21:03:37 trail2 php-fpm[67201]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.11 -> 10.7.7.3 - Restarting packages.
Apr 26 21:03:20 trail2 php-fpm[85783]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 21:02:19 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 21:01:08 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.7 -> 10.59.74.2 - Restarting packages.
Apr 26 21:00:08 trail2 php-fpm[85783]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 20:59:13 trail2 php-fpm[67201]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.8 -> 10.7.7.11 - Restarting packages.
Apr 26 20:58:57 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.7 - Restarting packages.
Apr 26 20:57:57 trail2 php-fpm[9587]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.39 -> 10.59.74.36 - Restarting packages.
Apr 26 20:56:46 trail2 php-fpm[30768]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.2 -> 10.59.74.3 - Restarting packages.
Apr 26 20:56:01 trail2 php-fpm[10821]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.7.7.3 -> 10.7.7.8 - Restarting packages.
Apr 26 20:55:46 trail2 php-fpm[45205]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.36 -> 10.59.74.39 - Restarting packages.
Apr 26 20:54:41 trail2 php-fpm[67201]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use WAN_DHCP.
Apr 26 20:54:40 trail2 check_reload_status[594]: updating dyndns WAN_DHCP
Apr 26 20:54:40 trail2 rc.gateway_alarm[3697]: >>> Gateway alarm: WAN_DHCP (Addr:1.1.1.1 Alarm:0 RTT:2.072ms RTTsd:.203ms Loss:0%)
Apr 26 20:54:35 trail2 php-fpm[10821]: /rc.newwanip: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - 10.59.74.3 -> 10.59.74.2 - Restarting packages.
Apr 26 20:54:31 trail2 php-fpm[30768]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed IP addresses. Reloading endpoints that may use WAN_DHCP.
Apr 26 20:54:30 trail2 check_reload_status[594]: updating dyndns WAN_DHCP
Apr 26 20:54:30 trail2 rc.gateway_alarm[33313]: >>> Gateway alarm: WAN_DHCP (Addr:1.1.1.1 Alarm:1 RTT:2.087ms RTTsd:.010ms Loss:33%)Thx
-
Ok are those IPs we see changing there, 10.59.74.X, the WAN IPs ? Or is that a VPN interface perhaps?
Edit: Yes it is.
-
Ok so that's probably a symptom not a cause then.
Permission denied like that pretty much MUST be a local firewall rule blocking it.
If you have no dynamic packages adding rules and no custom block rules I have to go back the Interface Binding state change in 24.03.
But you didn't see any blocked traffic in the firewall logs?
-
10.59.74.X, -> VPN Interface
I don't have any custom block rules; only the default deny rules. I have changed back the Firewall State Policy to Interface Bound States.
-
On 23.09.1 too, the WAN IPs are flapping the same way.
-
Hmm, still the openvpn clients changing address every minute? That sounds like it would be unusable if so.
-
I deleted the TCP clients as I couldn't get rid of the errors. Looks okay now w/o the TCP clients.