Problem connecting from Windows 10 to OpenVPN on CentOS 7

pdavie

---------------- SERVER CONFIG ----------------------------
[oconf=]
local 192.168.0.12
port 1194
proto udp4
dev tap0
ca keys/ca.crt
cert keys/server.crt
key keys/server.key
dh keys/dh2048.pem
topology subnet
mode server
ifconfig-pool-persist /var/lib/openvpn/ipp.txt
server-bridge 192.168.0.12 255.255.255.0 192.168.0.200 192.168.0.229
keepalive 10 120
tls-auth ta.key 0
cipher AES-256-CBC
compress lz4-v2
push "compress lz4-v2"
max-clients 30
user nobody
group nobody
persist-key
persist-tun
status /var/log/openvpn-status.log
log-append /var/log/openvpn.log
verb 9
explicit-exit-notify 1
[/oconf]

---------------- CLIENT CONFIG ----------------------------
[oconf=]
client
dev tap0
proto udp
remote SERVER_ADDRESS 1194
resolv-retry infinite
nobind
persist-key
persist-tun
mute-replay-warnings
ca gmb-keys/ca.crt
cert gmb-keys/pdavie.crt
key gmb-keys/pdavie.key
remote-cert-tls server
tls-auth gmb-ta.key 1
cipher AES-256-CBC
verb 7
[/oconf]

The Windows 10 client is unable to connect to the OpenVPN server. The
following error is continually displayed by the client:
UDP READ [0] from [AF_UNSPEC]: DATA UNDEF len=-1

us=863911 UDP WRITE [42] to [AF_INET]122.99.82.90:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
us=863911 UDP READ [0] from [AF_UNSPEC]: DATA UNDEF len=-1
us=903757 UDP WRITE [42] to [AF_INET]122.99.82.90:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #2 ] [ ] pid=0 DATA len=0
us=966813 UDP WRITE [42] to [AF_INET]122.99.82.90:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #3 ] [ ] pid=0 DATA len=0
us=452331 UDP WRITE [42] to [AF_INET]122.99.82.90:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #4 ] [ ] pid=0 DATA len=0
us=110993 UDP WRITE [42] to [AF_INET]122.99.82.90:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #5 ] [ ] pid=0 DATA len=0
us=553480 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
us=553480 TLS Error: TLS handshake failed

The client version is:
OpenVPN 2.5_git x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Oct 14 2017
Windows version 6.2 (Windows 8 or greater) 64bit
library versions: OpenSSL 1.0.2l 25 May 2017, LZO 2.10

The server version is:
OpenVPN 2.4.3 x86_64-redhat-linux-gnu [Fedora EPEL patched] [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jun 21 2017
library versions: OpenSSL 1.0.1e-fips 11 Feb 2013, LZO 2.06

The OpenVPN UDP traffic is being port forwarded from the router to the
OpenVPN server and I can see the client UDP packets being received by
the server using tcpdump.

The OpenVPN server is the host for a KVM virtual machine (and as such
has an existing bridge). I have configured a separate bridge (on a
second ethernet adapter) for OpenVPN (using the
openvpn-startup/shutdown scripts from the distribution). The server
runs firewalld and I have tried turning off firewalld and using
iptables instead but the error still occurs. I have also tried
creating a new tap interface (tap1) and connecting this tap interface
to the bridge used by KVM and changing the OpenVPN server
configuration to use the new tap interface and the IP address for the
KVM bridge. This also has not been successful. I have been able to
successfully configure OpenVPN on another CentOS 7 server with two
bridges (one for VMs and the other for OpenVPN) and can successfully
connect an OpenVPN client to this server. The major differences
between the two servers are that the working server uses Xen for
virtualisation and iptables for the firewall, the non-working server is
using KVM for virtualisation and firewalld for the firewall.

I hope I have provided everything needed. Any suggestions would be
greatfully received.

TinCanTech

And what does the server log show ? (You need to use --verb 4 only)

pdavie

The following is the server log. I don't have direct access to the server and so I am providing this output which I grabbed from the last run (verbosity 7, unfortunately).

Wed Oct 25 21:59:48 2017 us=595517 OpenVPN 2.4.3 x86_64-redhat-linux-gnu [Fedora EPEL patched] [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jun 21 2017
Wed Oct 25 21:59:48 2017 us=595540 library versions: OpenSSL 1.0.1e-fips 11 Feb 2013, LZO 2.06
Wed Oct 25 21:59:48 2017 us=596930 PKCS#11: pkcs11_initialize - entered
Wed Oct 25 21:59:48 2017 us=597200 PKCS#11: pkcs11_initialize - return 0-'CKR_OK'
Wed Oct 25 21:59:48 2017 us=597270 NOTE: when bridging your LAN adapter with the TAP adapter, note that the new bridge adapter will often take on its own IP address that is different from what the LAN adapter was previously set to
Wed Oct 25 21:59:48 2017 us=599922 Diffie-Hellman initialized with 2048 bit key
Wed Oct 25 21:59:48 2017 us=600786 Extracting ECDH curve from private key
Wed Oct 25 21:59:48 2017 us=600906 Failed to extract curve from certificate (UNDEF), using secp384r1 instead.
Wed Oct 25 21:59:48 2017 us=600939 ECDH curve secp384r1 added
Wed Oct 25 21:59:48 2017 us=601113 PRNG init md=SHA1 size=36
Wed Oct 25 21:59:48 2017 us=601259 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Oct 25 21:59:48 2017 us=601286 Outgoing Control Channel Authentication: HMAC KEY: bcdd3a67 45e169f5 26e452d9 93e40da9 4b31e5e0
Wed Oct 25 21:59:48 2017 us=601302 Outgoing Control Channel Authentication: HMAC size=20 block_size=20
Wed Oct 25 21:59:48 2017 us=601320 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Oct 25 21:59:48 2017 us=601340 Incoming Control Channel Authentication: HMAC KEY: 10140a16 a09989b7 c2dc6225 a1ac4e90 101e664a
Wed Oct 25 21:59:48 2017 us=601355 Incoming Control Channel Authentication: HMAC size=20 block_size=20
Wed Oct 25 21:59:48 2017 us=601374 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 28 bytes
Wed Oct 25 21:59:48 2017 us=601400 TLS-Auth MTU parms [ L:1654 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Wed Oct 25 21:59:48 2017 us=601416 MTU DYNAMIC mtu=1450, flags=2, 1654 -> 1450
Wed Oct 25 21:59:48 2017 us=602468 TUN/TAP device tap0 opened
Wed Oct 25 21:59:48 2017 us=602847 TUN/TAP TX queue length set to 100
Wed Oct 25 21:59:48 2017 us=602917 Data Channel MTU parms [ L:1654 D:1450 EF:122 EB:411 ET:32 EL:3 ]
Wed Oct 25 21:59:48 2017 us=604233 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Oct 25 21:59:48 2017 us=604409 UDPv4 link local (bound): [AF_INET]192.168.0.12:1194
Wed Oct 25 21:59:48 2017 us=604433 UDPv4 link remote: [AF_UNSPEC]
Wed Oct 25 21:59:48 2017 us=604453 GID set to nobody
Wed Oct 25 21:59:48 2017 us=604473 UID set to nobody
Wed Oct 25 21:59:48 2017 us=604498 MULTI: multi_init called, r=256 v=256
Wed Oct 25 21:59:48 2017 us=604544 IFCONFIG POOL: base=192.168.0.200 size=30, ipv6=0
Wed Oct 25 21:59:48 2017 us=604574 ifconfig_pool_read(), in='pdavie,192.168.0.200', TODO: IPv6
Wed Oct 25 21:59:48 2017 us=604596 succeeded -> ifconfig_pool_set()
Wed Oct 25 21:59:48 2017 us=604613 IFCONFIG POOL LIST
Wed Oct 25 21:59:48 2017 us=604630 pdavie,192.168.0.200
Wed Oct 25 21:59:48 2017 us=604664 PO_INIT maxevents=4 flags=0x00000002
Wed Oct 25 21:59:48 2017 us=604695 Initialization Sequence Completed
Wed Oct 25 21:59:48 2017 us=604712 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=604732 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=604747 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=604766 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=604786 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=604804 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=604818 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=622141 read from TUN/TAP returned 90
Wed Oct 25 21:59:48 2017 us=622199 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=622220 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=622236 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=622255 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=673041 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=673122 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=673142 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=673162 read from TUN/TAP returned 160
Wed Oct 25 21:59:48 2017 us=673181 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=673213 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=673229 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=673248 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=710844 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=710888 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=710907 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=710925 read from TUN/TAP returned 197
Wed Oct 25 21:59:48 2017 us=710942 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=710957 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=710971 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=710989 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=726187 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=726229 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=726246 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=726264 read from TUN/TAP returned 54
Wed Oct 25 21:59:48 2017 us=726280 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=726295 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=726309 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=726327 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=774163 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=774206 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=774224 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=774241 read from TUN/TAP returned 90
Wed Oct 25 21:59:48 2017 us=774258 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=774273 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=774287 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=774305 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=783425 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=783473 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=783495 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=783513 read from TUN/TAP returned 60
Wed Oct 25 21:59:48 2017 us=783529 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=783545 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=783559 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=783577 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=817824 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=817874 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=817897 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=817915 read from TUN/TAP returned 240
Wed Oct 25 21:59:48 2017 us=817932 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=817947 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=817962 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=817979 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:48 2017 us=866122 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=866168 event_wait returned 1
Wed Oct 25 21:59:48 2017 us=866191 I/O WAIT status=0x0004
Wed Oct 25 21:59:48 2017 us=866209 read from TUN/TAP returned 154
Wed Oct 25 21:59:48 2017 us=866226 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:48 2017 us=866241 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:48 2017 us=866256 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:48 2017 us=866274 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=6155 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=6247 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=6268 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=6284 MULTI: REAP range 0 -> 16
Wed Oct 25 21:59:49 2017 us=6305 read from TUN/TAP returned 90
Wed Oct 25 21:59:49 2017 us=6339 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=6357 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=6372 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=6390 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=67994 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=68088 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=68109 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=68129 read from TUN/TAP returned 240
Wed Oct 25 21:59:49 2017 us=68148 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=68164 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=68179 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=68198 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=272931 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=273025 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=273046 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=273065 read from TUN/TAP returned 60
Wed Oct 25 21:59:49 2017 us=273084 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=273100 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=273114 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=273133 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=283211 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=283257 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=283287 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=283305 read from TUN/TAP returned 78
Wed Oct 25 21:59:49 2017 us=283322 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=283337 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=283351 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=283368 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=318858 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=318911 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=318931 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=318949 read from TUN/TAP returned 240
Wed Oct 25 21:59:49 2017 us=318966 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=318981 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=318996 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=319098 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=443239 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=443289 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=443312 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=443331 read from TUN/TAP returned 78
Wed Oct 25 21:59:49 2017 us=443347 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=443362 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=443376 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=443394 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=519134 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=519184 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=519214 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=519232 read from TUN/TAP returned 222
Wed Oct 25 21:59:49 2017 us=519249 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=519264 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=519278 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=519296 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=623689 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=623778 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=623800 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=623819 read from TUN/TAP returned 60
Wed Oct 25 21:59:49 2017 us=623838 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=623869 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=623885 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=623903 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=654215 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=654297 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=654317 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=654336 read from TUN/TAP returned 60
Wed Oct 25 21:59:49 2017 us=654355 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=654372 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=654386 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=654405 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=658698 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=658743 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=658763 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=658781 read from TUN/TAP returned 60
Wed Oct 25 21:59:49 2017 us=658797 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=658812 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=658827 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=658844 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:49 2017 us=673800 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=673853 event_wait returned 1
Wed Oct 25 21:59:49 2017 us=673877 I/O WAIT status=0x0004
Wed Oct 25 21:59:49 2017 us=673894 read from TUN/TAP returned 160
Wed Oct 25 21:59:49 2017 us=673911 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:49 2017 us=673927 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:49 2017 us=673941 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:49 2017 us=673959 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=38427 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=38470 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=38488 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=38503 MULTI: REAP range 16 -> 32
Wed Oct 25 21:59:50 2017 us=38522 read from TUN/TAP returned 60
Wed Oct 25 21:59:50 2017 us=38538 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=38553 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=38567 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=38584 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=60919 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=60965 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=60995 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=61030 read from TUN/TAP returned 209
Wed Oct 25 21:59:50 2017 us=61048 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=61063 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=61077 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=61095 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=129400 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=129439 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=129457 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=129474 read from TUN/TAP returned 151
Wed Oct 25 21:59:50 2017 us=129490 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=129505 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=129519 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=129537 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=285289 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=285390 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=285411 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=285431 read from TUN/TAP returned 90
Wed Oct 25 21:59:50 2017 us=285451 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=286130 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=286175 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=286200 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=286221 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=286236 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=286250 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=286267 read from TUN/TAP returned 70
Wed Oct 25 21:59:50 2017 us=286284 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=286299 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=286313 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=286329 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=445318 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=445374 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=445730 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=445760 read from TUN/TAP returned 90
Wed Oct 25 21:59:50 2017 us=445778 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=445794 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=445808 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=445826 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=445845 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=445860 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=445874 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=445890 read from TUN/TAP returned 70
Wed Oct 25 21:59:50 2017 us=445906 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=445921 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=445935 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=445952 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=447334 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=447373 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=447390 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=447408 read from TUN/TAP returned 60
Wed Oct 25 21:59:50 2017 us=447427 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=447442 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=447457 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=447474 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=449382 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=449417 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=449435 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=449452 read from TUN/TAP returned 60
Wed Oct 25 21:59:50 2017 us=449467 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=449482 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=449496 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=449513 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=521116 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=521158 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=521176 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=521194 read from TUN/TAP returned 60
Wed Oct 25 21:59:50 2017 us=521211 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=521226 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=521240 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=521258 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=531028 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=531079 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=531099 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=531116 read from TUN/TAP returned 191
Wed Oct 25 21:59:50 2017 us=531134 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=531157 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=531173 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=531190 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=654144 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=654194 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=654217 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=654235 read from TUN/TAP returned 60
Wed Oct 25 21:59:50 2017 us=654252 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=654266 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=654281 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=654298 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=693786 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=693836 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=693859 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=693877 read from TUN/TAP returned 215
Wed Oct 25 21:59:50 2017 us=693894 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=693908 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=693923 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=693940 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=713883 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=713928 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=713951 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=713969 read from TUN/TAP returned 222
Wed Oct 25 21:59:50 2017 us=713986 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=714001 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=714031 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=714049 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=781381 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=781426 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=781449 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=781467 read from TUN/TAP returned 191
Wed Oct 25 21:59:50 2017 us=781484 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=781499 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=781514 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=781531 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:50 2017 us=825217 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=825300 event_wait returned 1
Wed Oct 25 21:59:50 2017 us=825320 I/O WAIT status=0x0004
Wed Oct 25 21:59:50 2017 us=825340 read from TUN/TAP returned 90
Wed Oct 25 21:59:50 2017 us=825359 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:50 2017 us=825374 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:50 2017 us=825389 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:50 2017 us=825407 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=32310 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=32403 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=32422 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=32438 MULTI: REAP range 32 -> 48
Wed Oct 25 21:59:51 2017 us=32459 read from TUN/TAP returned 191
Wed Oct 25 21:59:51 2017 us=32478 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=32494 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=32508 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=32527 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=129462 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=129501 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=129519 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=129536 read from TUN/TAP returned 151
Wed Oct 25 21:59:51 2017 us=129552 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=129581 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=129597 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=129614 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=153588 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=153631 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=153649 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=153666 read from TUN/TAP returned 60
Wed Oct 25 21:59:51 2017 us=153683 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=153698 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=153712 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=153730 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=233204 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=233261 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=233284 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=233302 read from TUN/TAP returned 179
Wed Oct 25 21:59:51 2017 us=233319 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=233334 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=233348 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=233365 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=411121 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=411206 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=411225 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=411246 read from TUN/TAP returned 90
Wed Oct 25 21:59:51 2017 us=411264 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=411280 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=411294 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=411313 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=638624 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=638694 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=638713 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=638735 read from TUN/TAP returned 60
Wed Oct 25 21:59:51 2017 us=638754 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=638770 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=638784 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=638803 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=674680 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=674735 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=674758 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=674776 read from TUN/TAP returned 160
Wed Oct 25 21:59:51 2017 us=674793 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=674808 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=674822 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=674840 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=720201 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=720285 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=720305 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=720326 read from TUN/TAP returned 197
Wed Oct 25 21:59:51 2017 us=720345 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=720361 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=720376 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=720395 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:51 2017 us=744043 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=744122 event_wait returned 1
Wed Oct 25 21:59:51 2017 us=744141 I/O WAIT status=0x0004
Wed Oct 25 21:59:51 2017 us=744160 read from TUN/TAP returned 60
Wed Oct 25 21:59:51 2017 us=744179 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:51 2017 us=744195 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:51 2017 us=744224 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:51 2017 us=744244 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=130530 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=130615 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=130635 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=130650 MULTI: REAP range 48 -> 64
Wed Oct 25 21:59:52 2017 us=130671 read from TUN/TAP returned 151
Wed Oct 25 21:59:52 2017 us=130689 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=130705 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=130720 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=130739 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=153588 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=153649 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=153669 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=153688 read from TUN/TAP returned 60
Wed Oct 25 21:59:52 2017 us=153705 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=153721 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=153735 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=153753 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=256071 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=256121 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=256144 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=256163 read from TUN/TAP returned 237
Wed Oct 25 21:59:52 2017 us=256180 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=256195 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=256209 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=256227 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=428298 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=428347 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=428370 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=428389 read from TUN/TAP returned 151
Wed Oct 25 21:59:52 2017 us=428405 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=428420 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=428435 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=428452 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=449604 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=449652 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=449673 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=449691 read from TUN/TAP returned 60
Wed Oct 25 21:59:52 2017 us=449707 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=449722 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=449736 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=449754 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=907536 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=907619 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=907638 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=907657 read from TUN/TAP returned 89
Wed Oct 25 21:59:52 2017 us=907676 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=907693 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=907707 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=907726 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=909233 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=909275 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=909304 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=909340 read from TUN/TAP returned 250
Wed Oct 25 21:59:52 2017 us=909367 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=909407 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=909423 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=909441 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=910385 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=910421 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=910437 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=910454 read from TUN/TAP returned 69
Wed Oct 25 21:59:52 2017 us=910470 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=910485 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=910500 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=910517 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=912517 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=912558 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=912577 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=912594 read from TUN/TAP returned 89
Wed Oct 25 21:59:52 2017 us=912610 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=912659 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=912687 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=912714 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:52 2017 us=914440 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=914482 event_wait returned 1
Wed Oct 25 21:59:52 2017 us=914502 I/O WAIT status=0x0004
Wed Oct 25 21:59:52 2017 us=914519 read from TUN/TAP returned 69
Wed Oct 25 21:59:52 2017 us=914535 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:52 2017 us=914551 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:52 2017 us=914580 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:52 2017 us=914600 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:53 2017 us=753891 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:53 2017 us=753972 event_wait returned 1
Wed Oct 25 21:59:53 2017 us=754019 I/O WAIT status=0x0004
Wed Oct 25 21:59:53 2017 us=754043 MULTI: REAP range 64 -> 80
Wed Oct 25 21:59:53 2017 us=754068 read from TUN/TAP returned 215
Wed Oct 25 21:59:53 2017 us=754091 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:53 2017 us=754109 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:53 2017 us=754124 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:53 2017 us=754143 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:54 2017 us=131422 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=131598 event_wait returned 1
Wed Oct 25 21:59:54 2017 us=131619 I/O WAIT status=0x0004
Wed Oct 25 21:59:54 2017 us=131635 MULTI: REAP range 80 -> 96
Wed Oct 25 21:59:54 2017 us=131655 read from TUN/TAP returned 151
Wed Oct 25 21:59:54 2017 us=131680 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:54 2017 us=131697 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:54 2017 us=131711 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=131730 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:54 2017 us=219140 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=219233 event_wait returned 1
Wed Oct 25 21:59:54 2017 us=219252 I/O WAIT status=0x0004
Wed Oct 25 21:59:54 2017 us=219273 read from TUN/TAP returned 60
Wed Oct 25 21:59:54 2017 us=219292 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:54 2017 us=219308 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:54 2017 us=219323 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=219342 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:54 2017 us=291089 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=291186 event_wait returned 1
Wed Oct 25 21:59:54 2017 us=291207 I/O WAIT status=0x0004
Wed Oct 25 21:59:54 2017 us=291225 read from TUN/TAP returned 70
Wed Oct 25 21:59:54 2017 us=291261 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:54 2017 us=291276 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:54 2017 us=291292 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=291311 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:54 2017 us=449805 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=449890 event_wait returned 1
Wed Oct 25 21:59:54 2017 us=449910 I/O WAIT status=0x0004
Wed Oct 25 21:59:54 2017 us=449930 read from TUN/TAP returned 60
Wed Oct 25 21:59:54 2017 us=449949 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:54 2017 us=450078 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:54 2017 us=450109 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=450130 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:54 2017 us=451155 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=451198 event_wait returned 1
Wed Oct 25 21:59:54 2017 us=451216 I/O WAIT status=0x0004
Wed Oct 25 21:59:54 2017 us=451234 read from TUN/TAP returned 70
Wed Oct 25 21:59:54 2017 us=451251 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:54 2017 us=451267 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:54 2017 us=451293 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=451313 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:54 2017 us=624681 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=624767 event_wait returned 1
Wed Oct 25 21:59:54 2017 us=624789 I/O WAIT status=0x0004
Wed Oct 25 21:59:54 2017 us=624810 read from TUN/TAP returned 179
Wed Oct 25 21:59:54 2017 us=624829 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:54 2017 us=624853 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:54 2017 us=624869 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:54 2017 us=624888 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:55 2017 us=555600 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=555685 event_wait returned 1
Wed Oct 25 21:59:55 2017 us=555706 I/O WAIT status=0x0004
Wed Oct 25 21:59:55 2017 us=555723 MULTI: REAP range 96 -> 112
Wed Oct 25 21:59:55 2017 us=555758 read from TUN/TAP returned 208
Wed Oct 25 21:59:55 2017 us=555779 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:55 2017 us=555795 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:55 2017 us=555810 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=555829 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:55 2017 us=576516 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=576601 event_wait returned 1
Wed Oct 25 21:59:55 2017 us=576620 I/O WAIT status=0x0004
Wed Oct 25 21:59:55 2017 us=576657 read from TUN/TAP returned 60
Wed Oct 25 21:59:55 2017 us=576678 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:55 2017 us=576695 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:55 2017 us=576710 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=576729 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:55 2017 us=676245 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=676339 event_wait returned 1
Wed Oct 25 21:59:55 2017 us=676402 I/O WAIT status=0x0004
Wed Oct 25 21:59:55 2017 us=676464 read from TUN/TAP returned 160
Wed Oct 25 21:59:55 2017 us=676492 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:55 2017 us=676512 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:55 2017 us=676527 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=676547 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:55 2017 us=723742 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=723847 event_wait returned 1
Wed Oct 25 21:59:55 2017 us=723869 I/O WAIT status=0x0004
Wed Oct 25 21:59:55 2017 us=723907 read from TUN/TAP returned 197
Wed Oct 25 21:59:55 2017 us=723928 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:55 2017 us=723951 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:55 2017 us=723967 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=723986 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:55 2017 us=790139 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=790228 event_wait returned 1
Wed Oct 25 21:59:55 2017 us=790248 I/O WAIT status=0x0004
Wed Oct 25 21:59:55 2017 us=790268 read from TUN/TAP returned 60
Wed Oct 25 21:59:55 2017 us=790287 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:55 2017 us=790304 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:55 2017 us=790319 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:55 2017 us=790338 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:56 2017 us=449981 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=450077 event_wait returned 1
Wed Oct 25 21:59:56 2017 us=450097 I/O WAIT status=0x0004
Wed Oct 25 21:59:56 2017 us=450113 MULTI: REAP range 112 -> 128
Wed Oct 25 21:59:56 2017 us=450134 read from TUN/TAP returned 60
Wed Oct 25 21:59:56 2017 us=450153 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:56 2017 us=450169 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:56 2017 us=450183 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=450203 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:56 2017 us=501278 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=501368 event_wait returned 1
Wed Oct 25 21:59:56 2017 us=501386 I/O WAIT status=0x0004
Wed Oct 25 21:59:56 2017 us=501406 read from TUN/TAP returned 110
Wed Oct 25 21:59:56 2017 us=501426 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:56 2017 us=501480 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:56 2017 us=501525 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=501556 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:56 2017 us=653908 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=654011 event_wait returned 1
Wed Oct 25 21:59:56 2017 us=654057 I/O WAIT status=0x0004
Wed Oct 25 21:59:56 2017 us=654081 read from TUN/TAP returned 60
Wed Oct 25 21:59:56 2017 us=654106 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:56 2017 us=654126 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:56 2017 us=654142 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=654162 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:56 2017 us=777423 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=777514 event_wait returned 1
Wed Oct 25 21:59:56 2017 us=777539 I/O WAIT status=0x0004
Wed Oct 25 21:59:56 2017 us=777560 read from TUN/TAP returned 60
Wed Oct 25 21:59:56 2017 us=777579 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:56 2017 us=777595 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:56 2017 us=777609 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=777628 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:56 2017 us=813827 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=813916 event_wait returned 1
Wed Oct 25 21:59:56 2017 us=813943 I/O WAIT status=0x0004
Wed Oct 25 21:59:56 2017 us=813963 read from TUN/TAP returned 215
Wed Oct 25 21:59:56 2017 us=813983 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:56 2017 us=813999 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:56 2017 us=814092 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=814113 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:56 2017 us=935533 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=935619 event_wait returned 1
Wed Oct 25 21:59:56 2017 us=935644 I/O WAIT status=0x0004
Wed Oct 25 21:59:56 2017 us=935683 read from TUN/TAP returned 98
Wed Oct 25 21:59:56 2017 us=935704 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:56 2017 us=935720 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:56 2017 us=935734 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:56 2017 us=935753 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:57 2017 us=653863 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:57 2017 us=653951 event_wait returned 1
Wed Oct 25 21:59:57 2017 us=653987 I/O WAIT status=0x0004
Wed Oct 25 21:59:57 2017 us=654014 MULTI: REAP range 128 -> 144
Wed Oct 25 21:59:57 2017 us=654037 read from TUN/TAP returned 60
Wed Oct 25 21:59:57 2017 us=654062 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:57 2017 us=654079 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:57 2017 us=654093 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:57 2017 us=654118 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:57 2017 us=776657 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:57 2017 us=776743 event_wait returned 1
Wed Oct 25 21:59:57 2017 us=776769 I/O WAIT status=0x0004
Wed Oct 25 21:59:57 2017 us=776789 read from TUN/TAP returned 98
Wed Oct 25 21:59:57 2017 us=776808 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:57 2017 us=776825 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:57 2017 us=776840 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:57 2017 us=776859 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:57 2017 us=780978 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:57 2017 us=781095 event_wait returned 1
Wed Oct 25 21:59:57 2017 us=781130 I/O WAIT status=0x0004
Wed Oct 25 21:59:57 2017 us=781151 read from TUN/TAP returned 60
Wed Oct 25 21:59:57 2017 us=781168 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:57 2017 us=781194 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:57 2017 us=781210 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:57 2017 us=781229 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:58 2017 us=132292 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=132386 event_wait returned 1
Wed Oct 25 21:59:58 2017 us=132408 I/O WAIT status=0x0004
Wed Oct 25 21:59:58 2017 us=132424 MULTI: REAP range 144 -> 160
Wed Oct 25 21:59:58 2017 us=132445 read from TUN/TAP returned 151
Wed Oct 25 21:59:58 2017 us=132464 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:58 2017 us=132495 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:58 2017 us=132517 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=132537 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:58 2017 us=299263 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=299345 event_wait returned 1
Wed Oct 25 21:59:58 2017 us=299365 I/O WAIT status=0x0004
Wed Oct 25 21:59:58 2017 us=299386 read from TUN/TAP returned 70
Wed Oct 25 21:59:58 2017 us=299416 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:58 2017 us=299434 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:58 2017 us=299449 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=299468 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:58 2017 us=450191 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=450276 event_wait returned 1
Wed Oct 25 21:59:58 2017 us=450296 I/O WAIT status=0x0004
Wed Oct 25 21:59:58 2017 us=450316 read from TUN/TAP returned 60
Wed Oct 25 21:59:58 2017 us=450335 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:58 2017 us=450376 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:58 2017 us=450395 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=450421 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:58 2017 us=459157 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=459215 event_wait returned 1
Wed Oct 25 21:59:58 2017 us=459235 I/O WAIT status=0x0004
Wed Oct 25 21:59:58 2017 us=459254 read from TUN/TAP returned 70
Wed Oct 25 21:59:58 2017 us=459271 SCHEDULE: schedule_find_least NULL
Wed Oct 25 21:59:58 2017 us=459302 PO_CTL rwflags=0x0001 ev=6 arg=0x55ac519a9150
Wed Oct 25 21:59:58 2017 us=459319 PO_CTL rwflags=0x0001 ev=5 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=459337 I/O WAIT TR|Tw|SR|Sw [10/0]
Wed Oct 25 21:59:58 2017 us=617883 PO_WAIT[1,0] fd=5 rev=0x00000001 rwflags=0x0001 arg=0x55ac519a9068
Wed Oct 25 21:59:58 2017 us=617973 event_wait returned 1
Wed Oct 25 21:59:58 2017 us=617995 I/O WAIT status=0x0004

TinCanTech

Your server log shows that the client packets never arrive at the server process.

pdavie

I spent a few hours last night looking again at the issue. I can see the OpenVPN traffic coming through to the Ethernet interface but the traffic is not coming through to the OpenVPN server (via the tap0 interface). I cannot see anything with tcpdump on the tap0 interface. I have tried using both firewalld and iptables to verify if it is a firewall issue so it seems not to be a problem with the firewall (I configured logging of rejected packets and cannot see any OpenVPN - UDP/1194 - packets being logged). I have also tried connecting the tap interface to the existing bridge used for the virtual machine which is also hosted on the server, again, still no traffic being identified by OpenVPN server.

To eliminate the bridge as an issue, I tried a configuration with the tun interface ("routed" setup) and found that this configuration also does not respond to the client traffic (TCP or UDP). Is there any way that I can determine what is happening to the traffic?

Initially, I considered that it would be simpler to run OpenVPN on the (VM) host server as I wasn't sure about running a bridge on a VM, while I thought it should work theoretically, I decided it would probably end up being more complex. In an effort to make at least a little progress, I tried running the existing configuration on the "virtual" mail server. While the bridged configuration does not work, the routed configuration does work on the VM.

The clients need to access windows servers on the network and therefore I need to get the bridged configuration working, but I have no idea what to try from here. Note that I have the required configuration working on a lab at home (except it is running on CentOS 6 rather than CentOS 7) and therefore I am virtually clueless as to why I cannot get the OpenVPN server to receive the traffic at all (either routed or bridged).

Any suggestions as to how to proceed are very welcome.

TinCanTech

pdavie wrote The OpenVPN server is the host for a KVM virtual machine (and as such
has an existing bridge). I have configured a separate bridge (on a
second ethernet adapter) for OpenVPN (using the
openvpn-startup/shutdown scripts from the distribution).

Get rid of this ..

pdavie wrote To eliminate the bridge as an issue, I tried a configuration with the tun interface ("routed" setup) and found that this configuration also does not respond to the client traffic (TCP or UDP).

Probably because of all your other network bridges interfering ..

Get rid of all bridges and setup a simple tunnel and make sure it works.

Then do what ever you want .. you may break it all again but at least you know it is not openvpn at fault.

pdavie

thanks for the advice. I will give it a go at the next opportunity.