Is this normal? "SIGUSR1[soft,connection-reset] received, client-instance restarting" every second or two

t.fraser

Connections appear to be stable when looking at them from the client side, however my logs are filling up the lines as listed below ..

It doesn't seem right that it should be re-establishing a connection every few seconds. Note the time stamps. The below logs are for just 2 openVPN clients.

Full logs ( 4 seconds worth) below.. Can provide more, but it is as below just repeated.

Mon Apr  8 04:47:02 2019 us=338706 Control Channel MTU parms [ L:1656 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Mon Apr  8 04:47:02 2019 us=338727 Data Channel MTU parms [ L:1656 D:1450 EF:124 EB:412 ET:32 EL:3 ]
Mon Apr  8 04:47:02 2019 us=338751 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Apr  8 04:47:02 2019 us=338756 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Apr  8 04:47:02 2019 us=338774 TCP connection established with [AF_INET]172.16.88.176:64764
Mon Apr  8 04:47:02 2019 us=338779 TCPv4_SERVER link local: (not bound)
Mon Apr  8 04:47:02 2019 us=338784 TCPv4_SERVER link remote: [AF_INET]172.16.88.176:64764
Mon Apr  8 04:47:02 2019 us=338822 172.16.88.176:64764 Connection reset, restarting [0]
Mon Apr  8 04:47:02 2019 us=338828 172.16.88.176:64764 SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Apr  8 04:47:02 2019 us=338851 TCP/UDP: Closing socket
Mon Apr  8 04:47:02 2019 us=659556 MULTI: multi_create_instance called
Mon Apr  8 04:47:02 2019 us=659616 Re-using SSL/TLS context
Mon Apr  8 04:47:02 2019 us=659630 LZ4v2 compression initializing
Mon Apr  8 04:47:02 2019 us=659686 Control Channel MTU parms [ L:1656 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Mon Apr  8 04:47:02 2019 us=659701 Data Channel MTU parms [ L:1656 D:1450 EF:124 EB:412 ET:32 EL:3 ]
Mon Apr  8 04:47:02 2019 us=659737 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Apr  8 04:47:02 2019 us=659753 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Apr  8 04:47:02 2019 us=659776 TCP connection established with [AF_INET]172.16.88.176:18130
Mon Apr  8 04:47:02 2019 us=659788 TCPv4_SERVER link local: (not bound)
Mon Apr  8 04:47:02 2019 us=659796 TCPv4_SERVER link remote: [AF_INET]172.16.88.176:18130
Mon Apr  8 04:47:02 2019 us=659851 172.16.88.176:18130 Connection reset, restarting [0]
Mon Apr  8 04:47:02 2019 us=659864 172.16.88.176:18130 SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Apr  8 04:47:02 2019 us=659894 TCP/UDP: Closing socket
Mon Apr  8 04:47:03 2019 us=511203 MULTI: multi_create_instance called
Mon Apr  8 04:47:03 2019 us=511243 Re-using SSL/TLS context
Mon Apr  8 04:47:03 2019 us=511254 LZ4v2 compression initializing
Mon Apr  8 04:47:03 2019 us=511311 Control Channel MTU parms [ L:1656 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Mon Apr  8 04:47:03 2019 us=511334 Data Channel MTU parms [ L:1656 D:1450 EF:124 EB:412 ET:32 EL:3 ]
Mon Apr  8 04:47:03 2019 us=511369 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Apr  8 04:47:03 2019 us=511378 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Apr  8 04:47:03 2019 us=511404 TCP connection established with [AF_INET]172.16.88.176:40105
Mon Apr  8 04:47:03 2019 us=511417 TCPv4_SERVER link local: (not bound)
Mon Apr  8 04:47:03 2019 us=511425 TCPv4_SERVER link remote: [AF_INET]172.16.88.176:40105
Mon Apr  8 04:47:03 2019 us=511478 172.16.88.176:40105 Connection reset, restarting [0]
Mon Apr  8 04:47:03 2019 us=511493 172.16.88.176:40105 SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Apr  8 04:47:03 2019 us=511522 TCP/UDP: Closing socket
Mon Apr  8 04:47:05 2019 us=244649 MULTI: multi_create_instance called
Mon Apr  8 04:47:05 2019 us=244685 Re-using SSL/TLS context
Mon Apr  8 04:47:05 2019 us=244697 LZ4v2 compression initializing
Mon Apr  8 04:47:05 2019 us=244753 Control Channel MTU parms [ L:1656 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Mon Apr  8 04:47:05 2019 us=244773 Data Channel MTU parms [ L:1656 D:1450 EF:124 EB:412 ET:32 EL:3 ]
Mon Apr  8 04:47:05 2019 us=244818 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Apr  8 04:47:05 2019 us=244857 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Apr  8 04:47:05 2019 us=244879 TCP connection established with [AF_INET]172.16.88.176:35086
Mon Apr  8 04:47:05 2019 us=244887 TCPv4_SERVER link local: (not bound)
Mon Apr  8 04:47:05 2019 us=244899 TCPv4_SERVER link remote: [AF_INET]172.16.88.176:35086
Mon Apr  8 04:47:05 2019 us=244952 172.16.88.176:35086 Connection reset, restarting [0]
Mon Apr  8 04:47:05 2019 us=244967 172.16.88.176:35086 SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Apr  8 04:47:05 2019 us=244995 TCP/UDP: Closing socket
Mon Apr  8 04:47:05 2019 us=774904 MULTI: multi_create_instance called
Mon Apr  8 04:47:05 2019 us=774959 Re-using SSL/TLS context
Mon Apr  8 04:47:05 2019 us=774988 LZ4v2 compression initializing
Mon Apr  8 04:47:05 2019 us=775051 Control Channel MTU parms [ L:1656 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Mon Apr  8 04:47:05 2019 us=775066 Data Channel MTU parms [ L:1656 D:1450 EF:124 EB:412 ET:32 EL:3 ]
Mon Apr  8 04:47:05 2019 us=775098 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Apr  8 04:47:05 2019 us=775119 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Apr  8 04:47:05 2019 us=775139 TCP connection established with [AF_INET]172.16.88.176:41446
Mon Apr  8 04:47:05 2019 us=775147 TCPv4_SERVER link local: (not bound)
Mon Apr  8 04:47:05 2019 us=775155 TCPv4_SERVER link remote: [AF_INET]172.16.88.176:41446
Mon Apr  8 04:47:05 2019 us=775207 172.16.88.176:41446 Connection reset, restarting [0]
Mon Apr  8 04:47:05 2019 us=775219 172.16.88.176:41446 SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Apr  8 04:47:05 2019 us=775247 TCP/UDP: Closing socket
Mon Apr  8 04:47:06 2019 us=35448 MULTI: multi_create_instance called
Mon Apr  8 04:47:06 2019 us=35500 Re-using SSL/TLS context
Mon Apr  8 04:47:06 2019 us=35512 LZ4v2 compression initializing
Mon Apr  8 04:47:06 2019 us=35563 Control Channel MTU parms [ L:1656 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Mon Apr  8 04:47:06 2019 us=35576 Data Channel MTU parms [ L:1656 D:1450 EF:124 EB:412 ET:32 EL:3 ]
Mon Apr  8 04:47:06 2019 us=35606 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mon Apr  8 04:47:06 2019 us=35612 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1592,tun-mtu 1532,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mon Apr  8 04:47:06 2019 us=35630 TCP connection established with [AF_INET]172.16.88.176:42164
Mon Apr  8 04:47:06 2019 us=35636 TCPv4_SERVER link local: (not bound)
Mon Apr  8 04:47:06 2019 us=35641 TCPv4_SERVER link remote: [AF_INET]172.16.88.176:42164
Mon Apr  8 04:47:06 2019 us=35676 172.16.88.176:42164 Connection reset, restarting [0]
Mon Apr  8 04:47:06 2019 us=35682 172.16.88.176:42164 SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Apr  8 04:47:06 2019 us=35704 TCP/UDP: Closing socket

server.conf

port 11941
proto tcp
dev tun
tun-mtu 1500
tun-mtu-extra 32
mssfix 1450
topology subnet
server 10.8.0.0 255.255.255.0
push "route 172.16.0.0 255.255.0.0"
ca ca.crt
cert server.crt
key server.key
dh dh.pem
cipher AES-256-CBC
compress lz4-v2
push "compress lz4-v2"
status /var/log/openvpn-status.log 2
log /var/log/openvpn.log
log-append /var/log/openvpn.log
verb 4

What do these specific lines mean?

Mon Apr  8 04:47:02 2019 us=659851 172.16.88.176:18130 Connection reset, restarting [0]
Mon Apr  8 04:47:02 2019 us=659864 172.16.88.176:18130 SIGUSR1[soft,connection-reset] received, client-instance restarting

Any help greatly appreciated.

TinCanTech

t.fraser wrote The below logs are for just 2 openVPN clients.

Do the clients share the same certificate ?

t.fraser

No. independent certs ..

Every 2.0s: cat /var/log/openvpn-stat*                                                                                                                                                                             Tue Apr  9 00:34:43 2019

OpenVPN CLIENT LIST
Updated,Tue Apr  9 00:34:42 2019
Common Name,Real Address,Bytes Received,Bytes Sent,Connected Since
OMC-AWS-currawong-jh-00,120.x.x.x:12345,477630,10188,Mon Apr  8 23:20:47 2019
OMC-AWS-Pioneer-tf-00,239.x.x.x:31744,30652,5160,Tue Apr  9 00:33:40 2019
ROUTING TABLE
Virtual Address,Common Name,Real Address,Last Ref
10.8.0.3,OMC-AWS-currawong-jh-00,120.x.x.x:12345,Tue Apr  9 00:34:41 2019
10.8.0.2,OMC-AWS-Pioneer-tf-00,239.x.x.x:31744,Tue Apr  9 00:33:41 2019
GLOBAL STATS
Max bcast/mcast queue length,3
END

Even with just a single user, the log output is the same ..

Tue Apr  9 00:38:18 2019 us=667495 MULTI: multi_create_instance called
Tue Apr  9 00:38:18 2019 us=667558 Re-using SSL/TLS context
Tue Apr  9 00:38:18 2019 us=667571 LZ4v2 compression initializing
Tue Apr  9 00:38:18 2019 us=667629 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:18 2019 us=667656 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:18 2019 us=667692 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:18 2019 us=667701 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:18 2019 us=667729 TCP connection established with [AF_INET]172.16.93.23:23281
Tue Apr  9 00:38:18 2019 us=667742 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:18 2019 us=667750 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:23281
Tue Apr  9 00:38:18 2019 us=667805 172.16.93.23:23281 Connection reset, restarting [0]
Tue Apr  9 00:38:18 2019 us=667818 172.16.93.23:23281 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:18 2019 us=667854 TCP/UDP: Closing socket
Tue Apr  9 00:38:18 2019 us=747285 MULTI: multi_create_instance called
Tue Apr  9 00:38:18 2019 us=747338 Re-using SSL/TLS context
Tue Apr  9 00:38:18 2019 us=747350 LZ4v2 compression initializing
Tue Apr  9 00:38:18 2019 us=747412 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:18 2019 us=747435 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:18 2019 us=747465 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:18 2019 us=747490 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:18 2019 us=747507 TCP connection established with [AF_INET]172.16.93.23:31718
Tue Apr  9 00:38:18 2019 us=747513 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:18 2019 us=747518 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:31718
Tue Apr  9 00:38:18 2019 us=747551 172.16.93.23:31718 Connection reset, restarting [0]
Tue Apr  9 00:38:18 2019 us=747557 172.16.93.23:31718 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:18 2019 us=747579 TCP/UDP: Closing socket
Tue Apr  9 00:38:19 2019 us=339739 MULTI: multi_create_instance called
Tue Apr  9 00:38:19 2019 us=339828 Re-using SSL/TLS context
Tue Apr  9 00:38:19 2019 us=339840 LZ4v2 compression initializing
Tue Apr  9 00:38:19 2019 us=339894 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:19 2019 us=339918 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:19 2019 us=339945 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:19 2019 us=339951 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:19 2019 us=339969 TCP connection established with [AF_INET]172.16.93.23:43374
Tue Apr  9 00:38:19 2019 us=339975 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:19 2019 us=339980 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:43374
Tue Apr  9 00:38:19 2019 us=340017 172.16.93.23:43374 Connection reset, restarting [0]
Tue Apr  9 00:38:19 2019 us=340024 172.16.93.23:43374 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:19 2019 us=340046 TCP/UDP: Closing socket
Tue Apr  9 00:38:19 2019 us=551156 MULTI: multi_create_instance called
Tue Apr  9 00:38:19 2019 us=551219 Re-using SSL/TLS context
Tue Apr  9 00:38:19 2019 us=551232 LZ4v2 compression initializing
Tue Apr  9 00:38:19 2019 us=551288 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:19 2019 us=551312 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:19 2019 us=551338 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:19 2019 us=551344 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:19 2019 us=551361 TCP connection established with [AF_INET]172.16.93.23:45451
Tue Apr  9 00:38:19 2019 us=551367 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:19 2019 us=551372 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:45451
Tue Apr  9 00:38:19 2019 us=551408 172.16.93.23:45451 Connection reset, restarting [0]
Tue Apr  9 00:38:19 2019 us=551414 172.16.93.23:45451 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:19 2019 us=551436 TCP/UDP: Closing socket
Tue Apr  9 00:38:19 2019 us=871156 MULTI: multi_create_instance called
Tue Apr  9 00:38:19 2019 us=871219 Re-using SSL/TLS context
Tue Apr  9 00:38:19 2019 us=871230 LZ4v2 compression initializing
Tue Apr  9 00:38:19 2019 us=871288 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:19 2019 us=871313 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:19 2019 us=871341 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:19 2019 us=871356 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:19 2019 us=871374 TCP connection established with [AF_INET]172.16.93.23:58120
Tue Apr  9 00:38:19 2019 us=871380 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:19 2019 us=871385 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:58120
Tue Apr  9 00:38:19 2019 us=871420 172.16.93.23:58120 Connection reset, restarting [0]
Tue Apr  9 00:38:19 2019 us=871426 172.16.93.23:58120 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:19 2019 us=871449 TCP/UDP: Closing socket
Tue Apr  9 00:38:21 2019 us=207010 MULTI: multi_create_instance called
Tue Apr  9 00:38:21 2019 us=207072 Re-using SSL/TLS context
Tue Apr  9 00:38:21 2019 us=207084 LZ4v2 compression initializing
Tue Apr  9 00:38:21 2019 us=207163 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:21 2019 us=207180 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:21 2019 us=207220 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:21 2019 us=207229 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:21 2019 us=207255 TCP connection established with [AF_INET]172.16.93.23:47591
Tue Apr  9 00:38:21 2019 us=207264 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:21 2019 us=207276 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:47591
Tue Apr  9 00:38:21 2019 us=207331 172.16.93.23:47591 Connection reset, restarting [0]
Tue Apr  9 00:38:21 2019 us=207345 172.16.93.23:47591 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:21 2019 us=207374 TCP/UDP: Closing socket
Tue Apr  9 00:38:21 2019 us=757241 MULTI: multi_create_instance called
Tue Apr  9 00:38:21 2019 us=757302 Re-using SSL/TLS context
Tue Apr  9 00:38:21 2019 us=757314 LZ4v2 compression initializing
Tue Apr  9 00:38:21 2019 us=757373 Control Channel MTU parms [ L:1624 D:1210 EF:40 EB:0 ET:0 EL:3 ]
Tue Apr  9 00:38:21 2019 us=757400 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Tue Apr  9 00:38:21 2019 us=757436 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Apr  9 00:38:21 2019 us=757445 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Tue Apr  9 00:38:21 2019 us=757471 TCP connection established with [AF_INET]172.16.93.23:54034
Tue Apr  9 00:38:21 2019 us=757480 TCPv4_SERVER link local: (not bound)
Tue Apr  9 00:38:21 2019 us=757492 TCPv4_SERVER link remote: [AF_INET]172.16.93.23:54034
Tue Apr  9 00:38:21 2019 us=757549 172.16.93.23:54034 Connection reset, restarting [0]
Tue Apr  9 00:38:21 2019 us=757561 172.16.93.23:54034 SIGUSR1[soft,connection-reset] received, client-instance restarting
Tue Apr  9 00:38:21 2019 us=757593 TCP/UDP: Closing socket

Every 2.0s: cat /var/log/openvpn-stat*                                                                                                                                                                                                                 Tue Apr  9 00:39:05 2019

OpenVPN CLIENT LIST
Updated,Tue Apr  9 00:39:04 2019
Common Name,Real Address,Bytes Received,Bytes Sent,Connected Since
OMC-AWS-currawong-jh-00,x.x.x.x:12345,505278,10188,Mon Apr  8 23:20:47 2019
ROUTING TABLE
Virtual Address,Common Name,Real Address,Last Ref
10.8.0.3,OMC-AWS-currawong-jh-00,x.x.x.x:12345,Tue Apr  9 00:39:03 2019
GLOBAL STATS
Max bcast/mcast queue length,3
END

TinCanTech

What about the client log ?

t.fraser

as mentioned above, from the client side it looks stable ..

Wed Apr 10 11:20:32 2019 OpenVPN 2.4.7 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Feb 21 2019
Wed Apr 10 11:20:32 2019 Windows version 6.2 (Windows 8 or greater) 64bit
Wed Apr 10 11:20:32 2019 library versions: OpenSSL 1.1.0j  20 Nov 2018, LZO 2.10
Enter Management Password:
Wed Apr 10 11:20:32 2019 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25341
Wed Apr 10 11:20:32 2019 Need hold release from management interface, waiting...
Wed Apr 10 11:20:32 2019 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25341
Wed Apr 10 11:20:33 2019 MANAGEMENT: CMD 'state on'
Wed Apr 10 11:20:33 2019 MANAGEMENT: CMD 'log all on'
Wed Apr 10 11:20:33 2019 MANAGEMENT: CMD 'echo all on'
Wed Apr 10 11:20:33 2019 MANAGEMENT: CMD 'bytecount 5'
Wed Apr 10 11:20:33 2019 MANAGEMENT: CMD 'hold off'
Wed Apr 10 11:20:33 2019 MANAGEMENT: CMD 'hold release'
Wed Apr 10 11:20:33 2019 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Wed Apr 10 11:20:33 2019 MANAGEMENT: >STATE:1554859233,RESOLVE,,,,,,
Wed Apr 10 11:20:33 2019 TCP/UDP: Preserving recently used remote address: [AF_INET]x.x.x.x:11941
Wed Apr 10 11:20:33 2019 Socket Buffers: R=[65536->65536] S=[64512->64512]
Wed Apr 10 11:20:33 2019 Attempting to establish TCP connection with [AF_INET]x.x.x.x:11941 [nonblock]
Wed Apr 10 11:20:33 2019 MANAGEMENT: >STATE:1554859233,TCP_CONNECT,,,,,,
Wed Apr 10 11:20:34 2019 TCP connection established with [AF_INET]x.x.x.x:11941
Wed Apr 10 11:20:34 2019 TCP_CLIENT link local: (not bound)
Wed Apr 10 11:20:34 2019 TCP_CLIENT link remote: [AF_INET]x.x.x.x:11941
Wed Apr 10 11:20:34 2019 MANAGEMENT: >STATE:1554859234,WAIT,,,,,,
Wed Apr 10 11:20:34 2019 MANAGEMENT: >STATE:1554859234,AUTH,,,,,,
Wed Apr 10 11:20:34 2019 TLS: Initial packet from [AF_INET]x.x.x.x:11941, sid=f160b1f6 02669692
Wed Apr 10 11:20:34 2019 VERIFY OK: depth=1, C=AU, ST=VIC, L=Abbotsford, O=OMC International, emailAddress=it@omcinternational.com, CN=OMC-AWS-OPENVPN-CA
Wed Apr 10 11:20:34 2019 VERIFY OK: depth=0, C=AU, ST=VIC, L=Abbotsford, O=OMC International, emailAddress=it@omcinternational.com, CN=OMC-AWS-OpenVPN-GW-02
Wed Apr 10 11:20:34 2019 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 4096 bit RSA
Wed Apr 10 11:20:34 2019 [OMC-AWS-OpenVPN-GW-02] Peer Connection Initiated with [AF_INET]x.x.x.x:11941
Wed Apr 10 11:20:35 2019 MANAGEMENT: >STATE:1554859235,GET_CONFIG,,,,,,
Wed Apr 10 11:20:35 2019 SENT CONTROL [OMC-AWS-OpenVPN-GW-02]: 'PUSH_REQUEST' (status=1)
Wed Apr 10 11:20:35 2019 PUSH: Received control message: 'PUSH_REPLY,route 172.16.0.0 255.255.0.0,compress lz4-v2,route-gateway 10.8.0.1,topology subnet,ifconfig 10.8.0.4 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: compression parms modified
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: --ifconfig/up options modified
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: route options modified
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: route-related options modified
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: peer-id set
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: adjusting link_mtu to 1659
Wed Apr 10 11:20:35 2019 OPTIONS IMPORT: data channel crypto options modified
Wed Apr 10 11:20:35 2019 Data Channel: using negotiated cipher 'AES-256-GCM'
Wed Apr 10 11:20:35 2019 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Wed Apr 10 11:20:35 2019 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Wed Apr 10 11:20:35 2019 interactive service msg_channel=800
Wed Apr 10 11:20:35 2019 ROUTE_GATEWAY 192.168.0.13/255.255.255.0 I=8 HWADDR=18:66:da:42:b8:85
Wed Apr 10 11:20:35 2019 open_tun
Wed Apr 10 11:20:35 2019 TAP-WIN32 device [Ethernet 5] opened: \\.\Global\{5CA33472-54EF-490C-910D-051BAE37588B}.tap
Wed Apr 10 11:20:35 2019 TAP-Windows Driver Version 9.21 
Wed Apr 10 11:20:35 2019 Set TAP-Windows TUN subnet mode network/local/netmask = 10.8.0.0/10.8.0.4/255.255.255.0 [SUCCEEDED]
Wed Apr 10 11:20:35 2019 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.8.0.4/255.255.255.0 on interface {5CA33472-54EF-490C-910D-051BAE37588B} [DHCP-serv: 10.8.0.254, lease-time: 31536000]
Wed Apr 10 11:20:35 2019 Successful ARP Flush on interface [9] {5CA33472-54EF-490C-910D-051BAE37588B}
Wed Apr 10 11:20:35 2019 MANAGEMENT: >STATE:1554859235,ASSIGN_IP,,10.8.0.4,,,,
Wed Apr 10 11:20:37 2019 TEST ROUTES: 1/1 succeeded len=1 ret=1 a=0 u/d=up
Wed Apr 10 11:20:37 2019 MANAGEMENT: >STATE:1554859237,ADD_ROUTES,,,,,,
Wed Apr 10 11:20:37 2019 C:\WINDOWS\system32\route.exe ADD 172.16.0.0 MASK 255.255.0.0 10.8.0.1
Wed Apr 10 11:20:37 2019 Route addition via service succeeded
Wed Apr 10 11:20:37 2019 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Wed Apr 10 11:20:37 2019 Initialization Sequence Completed
Wed Apr 10 11:20:37 2019 MANAGEMENT: >STATE:1554859237,CONNECTED,SUCCESS,10.8.0.4,x.x.x.x,11941,192.168.0.159,54921

So, it sounds like the behaviour I am seeing is not normal, but I am at a loss for where else to look for the cause.

Thanks

TinCanTech

According to your client log, openvpn is working perfectly.

t.fraser

TinCanTech wrote According to your client log, openvpn is working perfectly.

I agree, but the big question is why are my server side logs looking so unstable ?

Cheers

TinCanTech

You probably have a network problem but your server config also needs --keepalive

t.fraser

TinCanTech wrote You probably have a network problem but your server config also needs --keepalive

The server is located in AWS, so I don't think networking will be the issue, however you raise a good point. I wonder if the loadbalancer in between my workstation and the server could have anything to do with it.

I have no problem with the link dropping out due to lack of activity. My current connection has been up for 3 days.

Cheers