Hi all,
I'm using openvpn to play lan games with my friends, but occasionally the connection to the server breaks down for all clients. The interface is setup as tap, and while the openvpn connection breaks we still have perfectly good internet connection to the server. Teamspeak 3 (SpeechOverIP) runs on the same host and there are no hickups in the connection, while the openvpn downtime is about 20 seconds.
I'm using OpenVPN 2.4.0 x86_64-pc-linux-gnu on debian linux for the server side with the following configuration:
port 1194
proto udp
server 172.16.17.0 255.255.255.0
ca /etc/openvpn/easy-rsa/keys/ca.crt
cert /etc/openvpn/easy-rsa/keys/server.crt
key /etc/openvpn/easy-rsa/keys/server.key
dh /etc/openvpn/easy-rsa/keys/dh4096.pem
topology subnet
ifconfig-pool-persist ipp.txt
client-to-client
keepalive 10 120
cipher AES-256-CBC
user nobody
group nogroup
persist-key
persist-tun
status ovpn_server1_status.log
log ovpn_server1.log
verb 5
explicit-exit-notify 1
script-security 2
Because I could not spot something suspicious in the logfile with verb=5 other than that there are no more "Wr"s or "Rw"s beeing added to the log,i went ahead and tried again with verb=9. The timeout is apparent from the timestamps in the log (18:33:01-18:33:20).
The timeouts are quiet short and occur in irregular fashion. Apart from the timeouts the vpn connection works as expected.
If you need further information (log with verb=5) or anything else please let me know.
Note: The server is a rootserver from a hosting service, so I have no physical access.
I don't know if this could be related, but in the syslog there is the following error message with a timestamp when the connection is reestablished:
Oct 16 18:33:20 v22017115266956773 kernel: [1605787.721679] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
Oct 16 18:33:20 v22017115266956773 kernel: [1605787.724470] ata3.00: failed command: WRITE DMA EXT
Oct 16 18:33:20 v22017115266956773 kernel: [1605787.726194] ata3.00: cmd 35/00:00:00:0e:5a/00:01:19:00:00/e0 tag 23 dma 131072 out
Oct 16 18:33:20 v22017115266956773 kernel: [1605787.726194] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
Oct 16 18:33:20 v22017115266956773 kernel: [1605787.729369] ata3.00: status: { DRDY }
Oct 16 18:33:20 v22017115266956773 kernel: [1605787.730661] ata3: hard resetting link
Oct 16 18:33:20 v22017115266956773 kernel: [1605788.045346] ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
Oct 16 18:33:20 v22017115266956773 kernel: [1605788.046955] ata3.00: configured for UDMA/33
Oct 16 18:33:20 v22017115266956773 kernel: [1605788.048064] ata3.00: device reported invalid CHS sector 0
Oct 16 18:33:20 v22017115266956773 kernel: [1605788.049152] ata3: EH complete
Log with verb=9, ip addresses slightly altered, copyed only a few entries before and after timeout:
Wed Oct 16 18:33:00 2019 us=994455 GET INST BY VIRT: 00:ff:10:ff:09:46 -> client1/77.199.11.25:50485 via 00:ff:10:ff:09:46
Wed Oct 16 18:33:00 2019 us=994502 client1/77.199.11.25:50485 TUN READ [101]
Wed Oct 16 18:33:00 2019 us=994557 client1/77.199.11.25:50485 TLS: tls_pre_encrypt: key_id=0
Wed Oct 16 18:33:00 2019 us=994586 client1/77.199.11.25:50485 ENCRYPT IV: 00001495 c360d138 bc8aa079
Wed Oct 16 18:33:00 2019 us=994624 client1/77.199.11.25:50485 ENCRYPT FROM: 00ff10f9 06613a6e f157d605 08004500 00570b5f 40004011 b4e3ac10 1101ac1[more...]
Wed Oct 16 18:33:00 2019 us=994653 client1/77.199.11.25:50485 ENCRYPT AD: 00001495
Wed Oct 16 18:33:00 2019 us=994710 client1/77.199.11.25:50485 ENCRYPT TO: 00001495 ab29b015 39c32e75 c8c2f0d9 97522201 f3161a82 c8fc7d73 2a4f15d[more...]
Wed Oct 16 18:33:00 2019 us=994765 client1/77.199.11.25:50485 tls_prepend_opcode_v1
Wed Oct 16 18:33:00 2019 us=994806 PO_CTL rwflags=0x0002 ev=6 arg=0x55f5aef0a180
Wed Oct 16 18:33:00 2019 us=994850 PO_CTL rwflags=0x0000 ev=5 arg=0x55f5aef0a068
Wed Oct 16 18:33:00 2019 us=994886 I/O WAIT Tr|Tw|Sr|SW [7/180817]
Wed Oct 16 18:33:00 2019 us=994924 PO_WAIT[0,0] fd=6 rev=0x00000004 rwflags=0x0002 arg=0x55f5aef0a180
Wed Oct 16 18:33:00 2019 us=994963 event_wait returned 1
Wed Oct 16 18:33:00 2019 us=995000 I/O WAIT status=0x0002
Wed Oct 16 18:33:00 2019 us=995076 client1/77.199.11.25:50485 UDPv4 WRITE [122] to [AF_INET]77.199.11.25:50485: P_DATA_V1 kid=0 DATA 00001495 ab29b015 39c32e75 c8c2f0d9 97522201 f3161a82 c8fc7d73 2a4f15d[more...]
Wed Oct 16 18:33:00 2019 us=995169 client1/77.199.11.25:50485 UDPv4 write returned 122
Wed Oct 16 18:33:00 2019 us=995306 PO_CTL rwflags=0x0001 ev=6 arg=0x55f5aef0a180
Wed Oct 16 18:33:00 2019 us=995348 PO_CTL rwflags=0x0001 ev=5 arg=0x55f5aef0a068
Wed Oct 16 18:33:00 2019 us=995386 I/O WAIT TR|Tw|SR|Sw [7/180817]
Wed Oct 16 18:33:01 2019 us=5242 PO_WAIT[0,0] fd=6 rev=0x00000001 rwflags=0x0001 arg=0x55f5aef0a180
Wed Oct 16 18:33:01 2019 us=5324 event_wait returned 1
Wed Oct 16 18:33:01 2019 us=5341 I/O WAIT status=0x0001
Wed Oct 16 18:33:01 2019 us=5354 MULTI: REAP range 16 -> 32
Wed Oct 16 18:33:20 2019 us=405823 UDPv4 read returned 139
Wed Oct 16 18:33:20 2019 us=405905 GET INST BY REAL: 77.199.11.25:50485 [ok]
Wed Oct 16 18:33:20 2019 us=405985 client1/77.199.11.25:50485 UDPv4 READ [139] from [AF_INET]77.199.11.25:50485: P_DATA_V2 kid=0 DATA 00000300 003579ad 18613a6b 33f9c44c 539a1e9f 294892ad 50505d78 41af82a[more...]
Wed Oct 16 18:33:20 2019 us=406796 client1/77.199.11.25:50485 TLS: tls_pre_decrypt, key_id=0, IP=[AF_INET]77.199.11.25:50485
Wed Oct 16 18:33:20 2019 us=406920 client1/77.199.11.25:50485 DECRYPT FROM: 00003579 ad18613a 6b33f9c4 4c539a1e 9f294892 ad50505d 7841af82 a2f9595[more...]
Wed Oct 16 18:33:20 2019 us=406943 client1/77.199.11.25:50485 DECRYPT IV: 00003579 8e485523 a814a6cd
Wed Oct 16 18:33:20 2019 us=406965 client1/77.199.11.25:50485 DECRYPT MAC: ad18613a 6b33f9c4 4c539a1e 9f294892
Wed Oct 16 18:33:20 2019 us=406986 client1/77.199.11.25:50485 DECRYPT FROM: ad50505d 7841af82 a2f95957 efc86b96 17b3225f 52d934b2 0edb2320 ed98ba95 fb3b5ea1 91b3bd88 f35cd268 a804446f 3197d4ba b0b104a0 4b47f48e 50aa7cf3 8434a769 632f81f1 e7ceb998 7f1ef287 a66393b9 42f27a07 19b768fd ec83de8a ae5993ef 3b3e59b0 6520333c c09f7f27 047b73
Wed Oct 16 18:33:20 2019 us=407000 client1/77.199.11.25:50485 DECRYPT AD: 48000003 00003579
Wed Oct 16 18:33:20 2019 us=407042 client1/77.199.11.25:50485 DECRYPT TO: 3a6ef157 d60500ff 10f90661 08004500 0065609f 00008011 5f95ac10 1132ac1[more...]
Wed Oct 16 18:33:20 2019 us=407068 client1/77.199.11.25:50485 PID_TEST [0] [SSL-0] [1111111111111111111111111111111111111111111111111111222222222222] 0:13688 0:13689 t=1571243581[-19] r=[-22,64,15,0,1] sl=[8,64,64,528]
Wed Oct 16 18:33:20 2019 us=407093 client1/77.199.11.25:50485 GET INST BY VIRT: 3a:6e:f1:57:d6:05 [failed]
Wed Oct 16 18:33:20 2019 us=407146 client1/77.199.11.25:50485 SCHEDULE: schedule_add_modify wakeup=[Wed Oct 16 18:33:28 2019 us=592171] pri=1503760218
Wed Oct 16 18:33:20 2019 us=407159 SCHEDULE: schedule_find_least wakeup=[Wed Oct 16 18:33:08 2019 us=177052] pri=1347921427
Wed Oct 16 18:33:20 2019 us=407167 PO_CTL rwflags=0x0000 ev=6 arg=0x55f5aef0a180
Wed Oct 16 18:33:20 2019 us=407173 PO_CTL rwflags=0x0002 ev=5 arg=0x55f5aef0a068
Wed Oct 16 18:33:20 2019 us=407191 I/O WAIT Tr|TW|Sr|Sw [0/0]
Wed Oct 16 18:33:20 2019 us=407207 PO_WAIT[1,0] fd=5 rev=0x00000004 rwflags=0x0002 arg=0x55f5aef0a068
Wed Oct 16 18:33:20 2019 us=407361 event_wait returned 1
Wed Oct 16 18:33:20 2019 us=407374 I/O WAIT status=0x0008
Wed Oct 16 18:33:20 2019 us=407386 MULTI: REAP range 32 -> 48
Thanks in advanve
Benjamin
