i had a case where [i]openvpn[/i] went into a 100% CPU loop (according to [i]top[/i]). it got my attention because the laptop fan came on and stayed on. so i looked at [i]top[/i], first, and it showed [i]openvp[/i] at 100% i decided to dig into this one so i looked around. we have been having issues with our DSL so i have been monitoring connectivity and the next thing i did was look at that. the internet service dropped out right then (it stayed down for 3.5 hours). i used strace to see if it would tell me anything. i didn't look very deep in that but saved the output. i had [i]openvpn[/i] running in a screen session so i attached that since strace was showing stdout activity. it was repeating this, with increasing timestamps. here is a [i]two[/i] cycle slice of the file i saved: my server IP is replaced with XXX.XX.XX.XXX. only one such IP is involved. [quote]Wed Jan 11 00:38:03 2017 us=617438 TUN READ [1500] Wed Jan 11 00:38:03 2017 us=617464 UDPv4 WRITE [1540] to [AF_INET]XXX.XX.XX.XXX:2304: DATA len=1540 Wed Jan 11 00:38:03 2017 us=617472 TUN READ [1500] Wed Jan 11 00:38:03 2017 us=617492 UDPv4 WRITE [1540] to [AF_INET]XXX.XX.XX.XXX:2304: DATA len=1540[/quote] then i had a look at tcpdump (tcpdump -lln -i any): here is a [i]two[/i] cycle slice: [quote]00:43:26.981851 IP 10.120.40.184 > XXX.XX.XX.XXX: ip-proto-17 00:43:26.981906 IP 10.120.40.184.2304 > XXX.XX.XX.XXX.2304: UDP, bad length 1540 > 1472 00:43:26.981908 IP 10.120.40.184 > XXX.XX.XX.XXX: ip-proto-17 00:43:26.981944 IP 10.120.40.184.2304 > XXX.XX.XX.XXX.2304: UDP, bad length 1540 > 1472 [/quote] this appears to be showing the problem, so i went back to the strace output i had saved (strace -s 256 -p 2392): here is a [i]one[/i] cycle slice: [quote]poll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}, {fd=4, events=0}], 2, 589274044) = 1 ([{fd=3, revents=POLLOUT}]) stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3545, ...}) = 0 write(1, "Wed Jan 11 00:39:28 2017 us=41251 UDPv4 WRITE [1540] to [AF_INET]XXX.XX.XX.XXX:2304: DATA len=1540\n", 100) = 100 sendto(3, "4|mD\375U\232pa\274\344?\201.\363\307\256PKP\362\350\2341\254\364\311\221\205Z1\256\37\256\344\347h\257]\362\377\22\32j\310\352E\370R\32\t\266\270Bs\265\222\352T\235\206\376$\242\213\350\231\340\333QC# \310Z\342VI\367\224\230\213\367\221n5\5\16\2\321\205h\370\16\322\230\245(\t\35(\314O\236\370O-\0\373\21\201\262\276\305\331$v\377\211!\374n =\336\246)&\247\223K\323\252B\324\33\7\2564\345\211\343q\377\266+3\243\201\361\231\360GT\2571\202!i\24\n{\353\360\310CY\357\267Y\206-x\367\216\221h \320@\216m\221\224\313N\376\3276\177\244:\272X\252$1\247L\300xAhE)a\3712\375u\237\264c#\336\16\3\334\10\325\341T\303`\n's\22]\254L\236\206\256(e\2704\335\302\325\257\26c}d\200r/\16\32\244V\305\201\225"..., 1540, 0, {sa_family=AF_INET, sin_port=htons(2304), sin_addr=inet_addr("XXX.XX.XX.XXX")}, 16) = 1540 poll([{fd=3, events=POLLIN|POLLPRI}, {fd=4, events=POLLIN|POLLPRI}], 2, 589274044) = 1 ([{fd=4, revents=POLLIN}]) read(4, "E\0\5\334\305| \0@\21L\335\nx(\270\262\22]u\t\0\t\0\6\f\255\263\214\16kS\27\36%\245\2468\234\246\372;\224\201\345J\2557a7d]>\252W\3457y\326z\"\212y\212\320\306:\363\2653\320|\242\271\\\0230\332/(Y\342U\337\f\10\237\n\22\256+?\301\300\267\252\225\217\344R\353\335\310@W\341(\276\347\206\20

[quote="Skaperen"]--ifconfig 192.0.2.1 192.0.2.2[/quote]You understand, this is not a [i]private[/i] IP address ?

openvpn goes into a loop - 100% CPU

Skaperen

i had a case where openvpn went into a 100% CPU loop (according to top). it got my attention because the laptop fan came on and stayed on. so i looked at top, first, and it showed openvp at 100% i decided to dig into this one so i looked around. we have been having issues with our DSL so i have been monitoring connectivity and the next thing i did was look at that. the internet service dropped out right then (it stayed down for 3.5 hours). i used strace to see if it would tell me anything. i didn't look very deep in that but saved the output. i had openvpn running in a screen session so i attached that since strace was showing stdout activity. it was repeating this, with increasing timestamps.

here is a two cycle slice of the file i saved:
my server IP is replaced with XXX.XX.XX.XXX. only one such IP is involved.

Wed Jan 11 00:38:03 2017 us=617438 TUN READ [1500]
Wed Jan 11 00:38:03 2017 us=617464 UDPv4 WRITE [1540] to [AF_INET]XXX.XX.XX.XXX:2304: DATA len=1540
Wed Jan 11 00:38:03 2017 us=617472 TUN READ [1500]
Wed Jan 11 00:38:03 2017 us=617492 UDPv4 WRITE [1540] to [AF_INET]XXX.XX.XX.XXX:2304: DATA len=1540

then i had a look at tcpdump (tcpdump -lln -i any):

here is a two cycle slice:

00:43:26.981851 IP 10.120.40.184 > XXX.XX.XX.XXX: ip-proto-17
00:43:26.981906 IP 10.120.40.184.2304 > XXX.XX.XX.XXX.2304: UDP, bad length 1540 > 1472
00:43:26.981908 IP 10.120.40.184 > XXX.XX.XX.XXX: ip-proto-17
00:43:26.981944 IP 10.120.40.184.2304 > XXX.XX.XX.XXX.2304: UDP, bad length 1540 > 1472

this appears to be showing the problem, so i went back to the strace output i had saved (strace -s 256 -p 2392):

here is a one cycle slice:

poll([{fd=3, events=POLLIN|POLLPRI|POLLOUT}, {fd=4, events=0}], 2, 589274044) = 1 ([{fd=3, revents=POLLOUT}])
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3545, ...}) = 0
write(1, "Wed Jan 11 00:39:28 2017 us=41251 UDPv4 WRITE [1540] to [AF_INET]XXX.XX.XX.XXX:2304: DATA len=1540\n", 100) = 100
sendto(3, "4|mD\375U\232pa\274\344?\201.\363\307\256PKP\362\350\2341\254\364\311\221\205Z1\256\37\256\344\347h\257]\362\377\22\32j\310\352E\370R\32\t\266\270Bs\265\222\352T\235\206\376$\242\213\350\231\340\333QC# \310Z\342VI\367\224\230\213\367\221n5\5\16\2\321\205h\370\16\322\230\245(\t\35(\314O\236\370O-\0\373\21\201\262\276\305\331$v\377\211!\374n =\336\246)&\247\223K\323\252B\324\33\7\2564\345\211\343q\377\266+3\243\201\361\231\360GT\2571\202!i\24\n{\353\360\310CY\357\267Y\206-x\367\216\221h \320@\216m\221\224\313N\376\3276\177\244:\272X\252$1\247L\300xAhE)a\3712\375u\237\264c#\336\16\3\334\10\325\341T\303`\n's\22]\254L\236\206\256(e\2704\335\302\325\257\26c}d\200r/\16\32\244V\305\201\225"..., 1540, 0, {sa_family=AF_INET, sin_port=htons(2304), sin_addr=inet_addr("XXX.XX.XX.XXX")}, 16) = 1540
poll([{fd=3, events=POLLIN|POLLPRI}, {fd=4, events=POLLIN|POLLPRI}], 2, 589274044) = 1 ([{fd=4, revents=POLLIN}])
read(4, "E\0\5\334\305| \0@\21L\335\nx(\270\262\22]u\t\0\t\0\6\f\255\263\214\16kS\27\36%\245\2468\234\246\372;\224\201\345J\2557a7d]>\252W\3457y\326z\"\212y\212\320\306:\363\2653\320|\242\271\\\0230\332/(Y\342U\337\f\10\237\n\22\256+?\301\300\267\252\225\217\344R\353\335\310@W\341(\276\347\206\20<\24/?<\2224\213\214$\265\0224\357D\4\332#,\255?\317I\340S\3106\372\213\177\7H\347J\254\271\203\263R\271\2\2}UAI\210\321\260\4/\24\212\261\35K4L4\345s\254v\24\370)\0i\262\36b\301\\\313\352\305\325\247+*\223c\215Z\320K)_b\260\321\231\35J\265c>\334\347\220:wP\301o\211\225\3268\260\2u\20+Y\335\276\"\20\372\243io/\371A_y.\260\352\224\271\317S\336\226l\330~\365\317\213F\224"..., 1500) = 1500
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3545, ...}) = 0
write(1, "Wed Jan 11 00:39:28 2017 us=41336 TUN READ [1500]\n", 50) = 50

there was the same console output and the sendto() that was failing, in each loop cycle. it was trying to send a packet of size 1540 against an MTU of 1500.

there is NO configuration file; it is configured on the command line because it is built dynamically by a Python script (that runs it in a screen session). here is the command line running on my laptop:

openvpn --writepid /var/run/openvpn_kepler --nice -1 --port 2304 --proto udp --verb 6 --dev tun2kepler --local 10.120.40.184 --remote XXX.XX.XX.XXX --ifconfig 192.0.2.2 192.0.2.1 --secret kepler.key

here is the command line running on the server:

openvpn --writepid /var/run/openvpn_kepler --nice -1 --port 2304 --proto udp --verb 6 --dev tun2home --local XXX.XX.XX.XXX --ifconfig 192.0.2.1 192.0.2.2 --secret kepler.key

the MTU is 1500 on all interfaces. i am studying what to change it to for each end of the tunnel.

so ... any idea what is going wrong? it seems something is trying to send an oversize packet and the error from it is not being handled right. maybe i should have a smaller MTU. but 1540 is still going be a problem. this is the first and only time this has happened in about 15 months of running this dual-stack dual-masqueraded tunnel. when internet connectivity came back, the VPN restarted OK. i chose to kill the looping process, but the server side was up waiting for me (auto-restarted every 20 minutes by crontab).

edit 2:

the laptop is running OpenVPN version 2.3.10 on Ubuntu 16.04.1 LTS.
the server is running OpenVPN version 2.3.13 on Ubuntu 14.04.5 LTS.

TinCanTech

Skaperen wrote--ifconfig 192.0.2.1 192.0.2.2

You understand, this is not a private IP address ?

Skaperen

TinCanTech wrote
Skaperen wrote--ifconfig 192.0.2.1 192.0.2.2
You understand, this is not a private IP address ?

yes, i understand that

the intent was to number the tunnel in a way that would allow communicating from any private address to any public address via the masquerading on the server. that rules out using any public address and it rules out using any private (rfc1918) address as the tunnel address. to select the tunnel address i chose what i believed to be the most benign alternative addresses, considering that these numbers would not leak onto the internet (masquerading in effect, which addresses the requirement in rfc3330 sect 2. para 12) when this host becomes a gateway (and now is for a few VMs and 2 more transient tunnels to cloud regions). using any rfc1918 address would expose the potential to cause problems.

since you posted this i assume it attracted your attention for some reason. is this reason a possible cause to the construct of a 1540 byte packet or the lack of handling the error from such a packet? if it is some other reason, i am willing to deal with it, but not in this thread. if so, please start another thread for it, where appropriate, and let me know where. otherwise, if it relates to the incident i asked about, i am curious what that is.