[OpenVPN home] [Date Prev] [Date Index] [Date Next]
[OpenVPN mailing lists] [Thread Prev] [Thread Index] [Thread Next]
Google
 
Web openvpn.net

[Openvpn-users] reverts to port 1024 and then doesn't process replies


  • Subject: [Openvpn-users] reverts to port 1024 and then doesn't process replies
  • From: "Brian J. Murrell" <brian@xxxxxxxxxxxxxxx>
  • Date: Sun, 26 Aug 2007 20:54:03 -0400

I have an openvpn connection between my OpenWRT White Russian 0.9 which
has openvpn 2.0.8 in it.  On the other end I have a Ubuntu Feisty
machine with openvpn 2.0.9 on it.

The connection between the two will come up successfully, with in most
cases, the 2.0.9 version side originating the connection and
communication will commence.

I have been having problems however, wherein the 2.0.8 side of the
connection will at some point revert to using port 1024 as it's source
address.  The 2.0.9 side will happily receive those packets (1024->1194)
and send replies back to the 2.0.8 side on port 1024.  The openvpn
instance on the 2.0.8 side will receive these replies and process them
but the result is that the encapsulated packet will not be put onto the
tap0 interface.

To illustrate, while a connection is up and has reverted to using port
1024 on the 2.0.8 side I will ping the 2.0.9 side from a machine within
the 2.0.8 side's subnet.  On the openvpn machine the packets look like
this:

20:41:58.014852 IP d38-139-100.home1.cgocable.net.1024 > CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194: UDP, length 124
20:41:58.034701 IP CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194 > d38-139-100.home1.cgocable.net.1024: UDP, length 124
20:41:59.014829 IP d38-139-100.home1.cgocable.net.1024 > CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194: UDP, length 124
20:41:59.034577 IP CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194 > d38-139-100.home1.cgocable.net.1024: UDP, length 124
20:42:00.014986 IP d38-139-100.home1.cgocable.net.1024 > CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194: UDP, length 124
20:42:00.040245 IP CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194 > d38-139-100.home1.cgocable.net.1024: UDP, length 124
20:42:01.014837 IP d38-139-100.home1.cgocable.net.1024 > CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194: UDP, length 124
20:42:01.035685 IP CPE00a0c98cb9ff-CM000a73a15345.cpe.net.cable.rogers.com.1194 > d38-139-100.home1.cgocable.net.1024: UDP, length 124

and on the 2.0.9's tun0 interface I see:

20:41:58.900650 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13229, length 64
20:41:58.900910 IP 10.75.23.254 > 10.75.22.1: ICMP echo reply, id 54036, seq 13229, length 64
20:41:59.894650 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13230, length 64
20:41:59.894813 IP 10.75.23.254 > 10.75.22.1: ICMP echo reply, id 54036, seq 13230, length 64
20:42:00.894707 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13231, length 64
20:42:00.894869 IP 10.75.23.254 > 10.75.22.1: ICMP echo reply, id 54036, seq 13231, length 64
20:42:01.895839 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13232, length 64
20:42:01.895974 IP 10.75.23.254 > 10.75.22.1: ICMP echo reply, id 54036, seq 13232, length 64

And the openvpn process on the 2.0.8 side processes as such:

poll([{fd=4, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI, revents=POLLIN}], 2, 591374245) = 1
time(NULL)                              = 1188175517
read(5, "E\0\0T\0\0@\0?\1\371\24\nK\26\1\nK\27\376\10\0w\361\323"..., 1500) = 84
poll([{fd=4, events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=5, events=0}], 2, 591373245) = 1
time(NULL)                              = 1188175517
sendto(4, "P\33\t^1%\204\320+\325\267\267K\276F\220\273q\217\f\r\22"..., 124, 0, {sa_family=AF_INET, sin_port=htons(1194), sin_addr=inet_addr("99.245.25.89")}, 16) = 124
poll([{fd=4, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI, revents=POLLIN}], 2, 591373245) = 1
time(NULL)                              = 1188175518
read(5, "E\0\0T\0\0@\0?\1\371\24\nK\26\1\nK\27\376\10\0w\360\323"..., 1500) = 84
poll([{fd=4, events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=5, events=0}], 2, 591372245) = 1
time(NULL)                              = 1188175518
sendto(4, "h\361\304%=/\320i3\332x\357b\3\242g`\237\r\373\333\253"..., 124, 0, {sa_family=AF_INET, sin_port=htons(1194), sin_addr=inet_addr("99.245.25.89")}, 16) = 124
poll([{fd=4, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI, revents=POLLIN}], 2, 591372245) = 1
time(NULL)                              = 1188175518
read(5, "E\0\0T\0\0@\0?\1\371\24\nK\26\1\nK\27\376\10\0w\360\323"..., 1500) = 84
poll([{fd=4, events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=5, events=0}], 2, 591372245) = 1
time(NULL)                              = 1188175518
sendto(4, "h\361\304%=/\320i3\332x\357b\3\242g`\237\r\373\333\253"..., 124, 0, {sa_family=AF_INET, sin_port=htons(1194), sin_addr=inet_addr("99.245.25.89")}, 16) = 124
poll([{fd=4, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI, revents=POLLIN}], 2, 591372245) = 1
time(NULL)                              = 1188175519
read(5, "E\0\0T\0\0@\0?\1\371\24\nK\26\1\nK\27\376\10\0\252\356"..., 1500) = 84
poll([{fd=4, events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=5, events=0}], 2, 591371245) = 1
time(NULL)                              = 1188175519
sendto(4, "t\316t\324\16dk\277x\260\25\273\227\336\255\324.\201\332"..., 124, 0, {sa_family=AF_INET, sin_port=htons(1194), sin_addr=inet_addr("99.245.25.89")}, 16) = 124
poll([{fd=4, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI, revents=POLLIN}], 2, 591371245) = 1
time(NULL)                              = 1188175520
read(5, "E\0\0T\0\0@\0?\1\371\24\nK\26\1\nK\27\376\10\0v\356\323"..., 1500) = 84
poll([{fd=4, events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=5, events=0}], 2, 591370245) = 1
time(NULL)                              = 1188175520
sendto(4, "%T_\257V\377\275\303\255\241\324\324\320\37\234\301\327"..., 124, 0, {sa_family=AF_INET, sin_port=htons(1194), sin_addr=inet_addr("99.245.25.89")}, 16) = 124
poll([{fd=4, events=POLLIN|POLLPRI}, {fd=5, events=POLLIN|POLLPRI, revents=POLLIN}], 2, 591370245) = 1
time(NULL)                              = 1188175521
read(5, "E\0\0T\0\0@\0?\1\371\24\nK\26\1\nK\27\376\10\0[\355\323"..., 1500) = 84
poll([{fd=4, events=POLLIN|POLLPRI|POLLOUT, revents=POLLOUT}, {fd=5, events=0}], 2, 591369245) = 1

So the openvpn on the 2.0.8 side is actually receiving the packets that
are coming back to it on port 1024, it is just not putting them back on
to tun0 interface as it only sees the echo requests being made from it's
own client subnet:

20:41:58.113956 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13229, length 64
20:41:59.113957 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13230, length 64
20:42:00.120592 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13231, length 64
20:42:01.130171 IP 10.75.22.1 > 10.75.23.254: ICMP echo request, id 54036, seq 13232, length 64

Sometime later, traffic will resume going from 1194->1194 from the 20.8
to the 2.0.9 side and then all will be good again; the ping sender will
see his replies and of course, they will be seen on the 2.0.8's tun0
interface again.

This situation seems to come and go periodically, all within the
lifespan of a single openvpn process on the 2.0.8 side, so it's not the
restarting of an openvpn process on the 2.0.8 side that is curing the
ill.  It will self-heal.

I have even added:

port 1194
lport 1194

to the reciprocating profiles on both machines in an effort to work
around whatever is going on and it seems to persist

Any ideas as to what is going wrong?  Or any ideas how to initiate some
debugging to see what is going wrong?

Thanx,
b.

-- 
A day in the yard with my son is just like a day at work.  He goes
hunting around for stuff and brings it back to me and says: "Hey Dad,
look what I found.  The money is for me and the screw is for you."

Attachment: signature.asc
Description: This is a digitally signed message part