search

OpenVPN / openvpn

OpenVPN is an open source VPN daemon
http://openvpn.net
Other
10.64k stars 2.97k forks source link

Error messages being uninformative #582

Open henk84 opened 1 month ago

henk84 commented 1 month ago

Describe the bug I get messages in my log on the openvpn server that are very uninformative regarding both what they are trying to tell me and what condition they really refer to.

The first I encountered was:

read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)

After changing some things in my server config, it seems to have changed to

Connection Attempt read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)

sometimes there are multiple ECONNREFUSED:

Connection Attempt read UDPv4 [ECONNREFUSED|ECONNREFUSED|ECONNREFUSED|ECONNREFUSED]: Connection refused (fd=6,code=111) Connection Attempt read UDPv4 [ECONNREFUSED|ECONNREFUSED]: Connection refused (fd=6,code=111)

I have not the slightest idea what these messages mean or what might cause them. Among others my questions are: Which IP attempted to connect to which IP and port? In particular: is that an incoming or an outgoing connection? What do the multiple ECONNREFUSED mean? What does it mean? What could be wrong?

To Reproduce Generate a key:

openvpn --genkey secret static.key

run a server with following config:

ifconfig 10.19.254.1 10.19.254.2
dev tun
mode server
tls-server
dh none
cert /etc/openvpn/_REPLACE_WITH_INSTANCE_NAME_/server.pem
key /etc/openvpn/_REPLACE_WITH_INSTANCE_NAME_/server.pem
cipher AES-256-GCM
peer-fingerprint _REPLACE_WITH_FINGERPRINT_

keepalive 10 60
push "explicit-exit-notify 3"

Expected behavior I would expect this log message to either contain or be accompanied by some more context to understand what is really happening and why this is worth logging.

Version information (please complete the following information):

WalterFaber commented 1 month ago

Exactly the same issue here. Here are my thoughts and findings about it:

  1. Log mess started most likely after the upgrade of Debian to Bookworm (months ago).
  2. At least in my case, the VPN connections are working anyway
  3. The message seem to appear in the logs after connections end (intentionally or broken)
  4. There are something between 0 to approx. 20 similar messages in the logs as described above
  5. It seems like the tun interface is still forwarding packets to the server process but the process rejects the packets because it has already abandoned the session
  6. "explicit-exit-notify 3" on client side made it even worse @henk84 this is something you could test on your side

My configuration is basically the same:

Dibyajyoti-08 commented 3 weeks ago

Hello,

  1. The first log message that you got is that your server is refusing the connection, it could be because your server is not listening to the ip address, or the port that you have mentioned in the client side, possible could be you port is not opened for the server and to listen your client and second possible reason can be that it is getting blocked by the firewall.

  2. The connection attempt logs justify that the OpenVPN server is actively trying to response the connection attempt from the client and being refused

Solution - try telnet or curl methods to reach out to your server and see whether you can talk to your server in the IP level or not. Try looking for the port opening and the firewall rules for the more debugging purpose.

Regards, DJ

henk84 commented 2 weeks ago

I think I have not been quite clear enough in my report, so I will try to clarify now: My report is exactly that: a report about behaviour that is IMHO really a bug. It is not a request for help. I was (mostly?) able to solve any and all issues related or unrelated to these messages, my connections work, everything seems fine now. My report means just what it says in the words: the mentioned messages are uninformative. There is no implied request for help, no other level of unspoken information, etc. All I’m saying is: please improve the messages so they actually convey useful information.

Nevertheless, I’m grateful for the input and appreciate the intention to help me fix the cause that is producing these errors!

cron2 commented 2 weeks ago

My report means just what it says in the words: the mentioned messages are uninformative.

It's, basically, what the operating system tells us, and "connection refused" is clear enough to someone who has a bit of networking background. Not sure how OpenVPN could report this better except by adding lots of help texts + translations for every possible operating system error that could be returned.

henk84 commented 2 weeks ago

My report means just what it says in the words: the mentioned messages are uninformative.

It's, basically, what the operating system tells us, and "connection refused" is clear enough to someone who has a bit of networking background. Not sure how OpenVPN could report this better except by adding lots of help texts + translations for every possible operating system error that could be returned.

Well, I have a bit of networking background, I’d say, but seemingly not enough to understand it in this context. So given the config I pasted above: which host/IP is the "connection refused" coming from? Where is OpenVPN connecting to and why that might refuse the connection? When that is cleared up, maybe I can make an actual suggestion how to improve the message …

cron2 commented 2 weeks ago

The problem here is "we don't know".

OpenVPN sends out an UDP packet, which succeeds (this can only fail with things like "this is not a valid socket file descriptor" or "out of kernel memory").

The system ends out the UDP packet to the remote host, and it gets refused by a firewall, a service that is no longer listening to that port, ..., and the system gets back an ICMP error packet.

The kernel maps that to the socket where the UDP packet was sent, and on the next socket action the error messages is "piggybacked" on another send/receive operation - and it can be more than one error at the same time - but these errors are always related to "something we've done some time before". If there is only one peer (like, on the client) it's pretty clear which host is "not reachable anymore", but on the server it could be any one of the clients currently considered "active" (= keepalives and other packets are sent).

We do not get back anything more useful from the kernel, like "which packet does this error relate to?" or "which intermediate host sent an ICMP error?".

(Linux is actually much more verbose than most other OSes, who do not give us anything)

henk84 commented 2 weeks ago

The problem here is "we don't know".

OpenVPN sends out an UDP packet, which succeeds (this can only fail with things like "this is not a valid socket file descriptor" or "out of kernel memory").

I’m not sure whether I’m missing something or you are. My main question for the particular config I pasted is: where to would openvpn send a UDP packet that could cause this error? and why? This is a very private system. For this particular config I have only one client and it was not active when these messages occured. The config does not tell openvpn any hostname or IP address to connect to. So why would it send out anything anywhere?

The system ends out the UDP packet to the remote host, and it gets refused by a firewall, a service that is no longer listening to that port, ..., and the system gets back an ICMP error packet.

The kernel maps that to the socket where the UDP packet was sent, and on the next socket action the error messages is "piggybacked" on another send/receive operation - and it can be more than one error at the same time - but these errors are always related to "something we've done some time before". If there is only one peer (like, on the client) it's pretty clear which host is "not reachable anymore", but on the server it could be any one of the clients currently considered "active" (= keepalives and other packets are sent).

We do not get back anything more useful from the kernel, like "which packet does this error relate to?" or "which intermediate host sent an ICMP error?".

Thank you very much for elaborating, I was not aware of how this works. For the reasons given for the question above, I’m not sure it’s of much relevance, though.

cron2 commented 2 weeks ago

If you have no "remote" in your config, OpenVPN would send packets back to "the other end that contacted it", so, reply packets only (and it should never send anything "just so", because there is nothing to send to).

To be sure what is going on, run the server with verb 4 and follow the log - it should see something incoming, reply to it, and if that does not work (firewalls, routing, whatever) the next socket operation will show the error.

(As a side note, you explain that you generate a static key, and then show a server config with TLS and no static key, so "the particular config" is not exactly clear to me)

WalterFaber commented 2 weeks ago

@cron2 may I add a remark based on my first comment #2 on this topic?

I still think there is something wrong with the version 2.6.3-1+deb12u2 on a debian 12 server. In addition to my comment, I want to be more precis:

  1. I have an active VPN connection (exactly 1 tun-connection at this time, but others are configured)
  2. The client config contains "explicit-exit-notify 3" (it applies to an Android phone but also to a laptop with Ubuntu 22.04)
  3. If i gracefully end the connection on the client, I SOMETIMES but quite frequent get 10-20 error messages in my server logs "read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)"
  4. The server even indicates, that it received the explicit exit notification
  5. The same server- and client-configuration did not create the log entries on debian 11 server (and of course other OpenVPN version)

So for me it looks like there is some timing/sequence issue. Something is closed/removed too early on the server side or something is sent out even if it should respect the exit notification of the client.

Here is a full server log after I ended the connection on the client. verb 4 on server There is no indication what came in and what might cause this message as you stated above:

27.8.2024, 19:09:34 OpenVPNClient/1.2.3.4:7933 Exit message received by peer
27.8.2024, 19:09:34 OpenVPNClient/1.2.3.4:7933 Delayed exit in 5 seconds
27.8.2024, 19:09:34 read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)
27.8.2024, 19:09:35 read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)
27.8.2024, 19:09:35 read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)
27.8.2024, 19:09:35 read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)
27.8.2024, 19:09:36 read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)
27.8.2024, 19:09:37 read UDPv4 [ECONNREFUSED]: Connection refused (fd=6,code=111)
27.8.2024, 19:09:40 OpenVPNClient/1.2.3.4:7933 SIGTERM[soft,delayed-exit] received, client-instance exiting