search

OpenVPN / openvpn3

OpenVPN 3 is a C++ class library that implements the functionality of an OpenVPN client, and is protocol-compatible with the OpenVPN 2.x branch.
https://openvpn.net
Other
987 stars 392 forks source link

Randomly getting this exception on macOS #295

Open savely-krasovsky opened 7 months ago

savely-krasovsky commented 7 months ago

UDP send exception: send: No buffer space available

We are using 3.8.3 with ovpnagent, without any special patches. Problem occurs relatively rarely on both Intel and Apple Silicon based machines. We are not getting anything else suspicious in log files except this line and subsequent connection crash. Could try to provide addition details but for know that's all we observe.

dsommers commented 7 months ago

Which kind of OS platform is this? Device type/model?

savely-krasovsky commented 7 months ago

@dsommers we see this problem only at macOS. Currently got it on Monteray and Ventura.

schwabe commented 7 months ago

Could you provide more logs? No buffer space might be result of a broken connection or of the client trying to send more than the OS side buffers cna accept.

savely-krasovsky commented 7 months ago

@schwabe we will try, but in our currently logging implementation there are so many lines with this error that user cannot capture any useful logs above (log file has size limit):

time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:45.330+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
schwabe commented 7 months ago

Yeah unfortunately with that log, it is just guesswork what is really going on and what the root cause of the problem is. My guess siince the message is repeated over and over is that the socket is not in a working state anymore cause by some external event like loosing network connection or similar.

savely-krasovsky commented 7 months ago

@schwabe @dsommers we've successfully captured the start of problem, but unfortunately it seems not very useful:

time=2024-02-21T20:52:31.702+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="SetupClient: transmitting tun setup list to /var/run/openvpnagent.sock JSON CONFIG WAS HERE \nPOST unix://[/var/run/openvpnagent.sock]/tun-setup : 200 OK\n{\n\t\"iface_name\" : \"utun6\",\n\t\"layer\" : \"OSI_LAYER_3\",\n\t\"tun_prefix\" : true\n}\n/sbin/ifconfig utun6 down\n/sbin/ifconfig utun6 maskedip maskedip netmask 255.255.255.128 mtu 1400 up\n/sbin/route add -net maskedip -netmask 255.255.255.128 maskedip\nadd net maskedip: gateway maskedip\nMacDNSAction: FLAGS=F RD=0 SO=5000 DNS=maskedip DOM=masked domains ADS=\nopen utun6 SUCCEEDED\n"
time=2024-02-21T20:52:31.702+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="Connected via utun6\n"
time=2024-02-21T20:52:31.715+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="fixed mssfix=1360\n"
time=2024-02-21T20:52:31.715+03:00 level=INFO msg="Event received" openvpn.conn.event_name=CONNECTED openvpn.conn.event_msg="maskeduser@MASKEDIP:1194 (MASKEDIP) via /UDP on utun6/maskedip/ gw=[maskedip/] mtu=(default)"
time=2024-02-21T20:52:31.716+03:00 level=INFO msg="POST /connect? HTTP/1.1" status_code=200 bytes=0 elapsed=984.081625ms
time=2024-02-21T21:09:22.367+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T21:09:22.367+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T21:09:22.367+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T21:09:22.367+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T21:09:22.367+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
savely-krasovsky commented 7 months ago

From user's perspective VPN worked like ~15 minutes and suddenly connections breaks.

Another logs example:

time=2024-02-21T20:31:21.832+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="Connected via utun6\n"
time=2024-02-21T20:31:21.833+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="fixed mssfix=1360\n"
time=2024-02-21T20:31:21.833+03:00 level=INFO msg="Event received" openvpn.conn.event_name=CONNECTED openvpn.conn.event_msg="maskeduser@MASKEDIP:1194 (MASKEDIP) via /UDP on utun6/MASKEDIP/ gw=[MASKEDIP/] mtu=(default)"
time=2024-02-21T20:31:21.833+03:00 level=INFO msg="POST /connect? HTTP/1.1" status_code=200 bytes=0 elapsed=1.513732875s
time=2024-02-21T20:31:21.851+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_IFACE en0\n"
time=2024-02-21T20:36:39.775+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:39.793+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:39.794+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:39.794+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:39.794+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"
time=2024-02-21T20:36:39.795+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: No buffer space available\n"

In those cases user uses the latest Sonoma 14.2.1.

dsommers commented 7 months ago

What else happens in on the host around those timestamps where this issue occurs? That is, out side of the Connect app?

savely-krasovsky commented 7 months ago

@dsommers user that persistently has this bug (around 15-20 minutes after connection) does his usual job -- coding and using VPN to discover internal resources. Tunnelblick and any other openvpn2-based solutions work perfectly in his case.

But I will to get more information. Relatively rare other users also get this issue, but like one time in a month.

dsommers commented 7 months ago

But that does not help us understand what happens ... we have quite some OpenVPN Connect users out there, and this is, afaik, the only report on such behaviour.

But OpenVPN Connect issues will also be better handled via the proper OpenVPN support channel ... https://openvpn.net/support/

OpenVPN 3 Core library (this project) is just the underlying protocol library which OpenVPN Connect implements.

savely-krasovsky commented 7 months ago

@dsommers I understand! I will try to obtain more information, I just shared with what I have on the hands for now.

In our case it is not OpenVPN Connect, we are using our own solution based on OpenVPN3 and currently deploying it for thousands of employees. So I created issue here.

schwabe commented 7 months ago

@L11R It is hard for us to guess what your own solution does. Is the source code of that solution available?

savely-krasovsky commented 7 months ago

Currently it's not available, but we use it as a high level library. Our code is calling Connect() which blocks a thread until subsequent Disconnect() call or some error returns and releases the thread. We don't reinvent the wheel and just following the docs I hope.

Logs from OpenVPN3 are not truncated, we log everyone it sends us.

I guess the main difference from OpenVPN Connect is that we are calling it from Go using SWIG.

To be clear: I don't wait any magic solution, especially because realistically we are using blackbox from yours perspective. I am just sharing my current observations, because it could be useful for you and someone else.

savely-krasovsky commented 7 months ago

Also getting this one, macOS Sonoma 14.2.1.

time=2024-03-06T16:19:52.368+03:00 level=INFO msg="Event received" openvpn.conn.event_name=CONNECTED openvpn.conn.event_msg="username@IP:1194 (IP) via /UDP on utun6/IP/ gw=[IP/]mtu=(default)"
time=2024-03-06T16:19:52.381+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_IFACE en0\n"
time=2024-03-06T16:21:04.545+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_IFACE en0\n"
time=2024-03-06T16:21:04.690+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_IFACE \n"
time=2024-03-06T16:21:04.826+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_STATE 0 status=NotReachable flags=-- -------\n"
time=2024-03-06T16:21:05.629+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.630+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.630+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.630+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.631+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.631+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.631+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.631+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.631+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.632+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.632+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.836+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle ACTION pause=0 state=[net_up=0 iface= sleep=0] prev=[net_up=1 iface=en0 sleep=0]\n"
time=2024-03-06T16:21:05.837+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="UDP send exception: send: Can't assign requested address\n"
time=2024-03-06T16:21:05.955+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="SetupClient: transmitting tun destroy request to /var/run/netzoneagent.sock\nGET unix://[/var/run/netzoneagent.sock]/tun-destroy : 200 OK\nREMOVED\nMacDNSAction: FLAGS=F\n"
time=2024-03-06T16:21:09.275+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_IFACE en0\n"
time=2024-03-06T16:21:09.388+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle NET_STATE 1 status=ReachableViaWiFi flags=-R -------\n"
time=2024-03-06T16:21:10.389+03:00 level=INFO msg="OpenVPN3 library log" openvpn.msg="MacLifeCycle ACTION pause=1 state=[net_up=1 iface=en0 sleep=0] prev=[net_up=0 iface= sleep=0]\n"
savely-krasovsky commented 7 months ago

@schwabe @dsommers I can confirm that we are able to reproduce it. You need to use UDP server, allocate as much memory as you can (e.g. using command like this sudo memory_pressure -S -l critical -p 1 -s 600) and uploading big file (like 100MB+). Your log will fill with tons of UDP send exception: send: No buffer space available.

I believe it's because BSD sendto() (which asio::send_to() is using underneath) is NON blocking and by spec could return ENOBUFS if buffer is exhausted. I don't know how to properly fix it.

schwabe commented 7 months ago

The question is if apart from the log message and the log message being shown too often, anything else is broken. If there are coming packets faster in from the tun interface than OpenVPN can send out via UDP, at some point it needs to drop packets.

savely-krasovsky commented 7 months ago

@schwabe it breaks the connection at some point. But doesn't reproduce stably, we are working it currently.