Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Randomly getting this exception on macOS #295

Open
savely-krasovsky opened this issue Feb 21, 2024 · 17 comments
Open

Randomly getting this exception on macOS #295

savely-krasovsky opened this issue Feb 21, 2024 · 17 comments

Comments

@savely-krasovsky
Copy link

savely-krasovsky commented Feb 21, 2024 •
edited
Loading

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
Copy link
Member

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

@savely-krasovsky
Copy link
Author

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

@schwabe
Copy link
Contributor

schwabe commented Feb 21, 2024

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
Copy link
Author

savely-krasovsky commented Feb 21, 2024 •
edited
Loading

@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
Copy link
Contributor

schwabe commented Feb 21, 2024

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
Copy link
Author

savely-krasovsky commented Feb 21, 2024 •
edited
Loading

@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
Copy link
Author

savely-krasovsky commented Feb 21, 2024 •
edited
Loading

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.

@savely-krasovsky savely-krasovsky changed the title Randomly getting this exeption on macOS Randomly getting this exception on macOS Feb 22, 2024
@dsommers
Copy link
Member

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

@savely-krasovsky
Copy link
Author

savely-krasovsky commented Feb 23, 2024 •
edited
Loading

@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
Copy link
Member

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
Copy link
Author

@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
Copy link
Contributor

schwabe commented Feb 24, 2024

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

@savely-krasovsky
Copy link
Author

savely-krasovsky commented Feb 24, 2024 •
edited
Loading

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
Copy link
Author

savely-krasovsky commented Mar 6, 2024 •
edited
Loading

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
Copy link
Author

savely-krasovsky commented Mar 7, 2024 •
edited
Loading

@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
Copy link
Contributor

schwabe commented Mar 7, 2024

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
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@schwabe @dsommers @savely-krasovsky