SIGUSR1[soft,ping-restart] received, process restarting

vladob

Dear all

I have a question related to my openVPN connection from Windows machine (laptop). Connection is restarting quite often, every 2-5 minutes and I do not understand why.

This is listing from Verb4 client connection:

Sat Jan 04 12:19:09 2020 Register_dns request sent to the service
Sat Jan 04 12:19:09 2020 MANAGEMENT: >STATE:1578136749,CONNECTED,SUCCESS,10.0.1.4,87.236.195.236,1194,,
Sat Jan 04 12:22:00 2020 [ovpn.chubbable.com] Inactivity timeout (--ping-restart), restarting
Sat Jan 04 12:22:00 2020 TCP/UDP: Closing socket
Sat Jan 04 12:22:00 2020 SIGUSR1[soft,ping-restart] received, process restarting
Sat Jan 04 12:22:00 2020 MANAGEMENT: >STATE:1578136920,RECONNECTING,ping-restart,,,,,
Sat Jan 04 12:22:00 2020 Restart pause, 5 second(s)
Sat Jan 04 12:22:05 2020 Re-using SSL/TLS context
Sat Jan 04 12:22:05 2020 LZO compression initializing
Sat Jan 04 12:22:05 2020 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Sat Jan 04 12:22:05 2020 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Sat Jan 04 12:22:05 2020 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Sat Jan 04 12:22:05 2020 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-server'
Sat Jan 04 12:22:05 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]87.236.195.236:1194
Sat Jan 04 12:22:05 2020 Socket Buffers: R=[65536->65536] S=[65536->65536]
Sat Jan 04 12:22:05 2020 UDP link local (bound): [AF_INET][undef]:1194
Sat Jan 04 12:22:05 2020 UDP link remote: [AF_INET]87.236.195.236:1194
Sat Jan 04 12:22:05 2020 MANAGEMENT: >STATE:1578136925,WAIT,,,,,,
Sat Jan 04 12:22:05 2020 MANAGEMENT: >STATE:1578136925,AUTH,,,,,,
Sat Jan 04 12:22:05 2020 TLS: Initial packet from [AF_INET]87.236.195.236:1194, sid=33b79800 c3c68b30
Sat Jan 04 12:22:05 2020 VERIFY OK: depth=1, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=internal-ca
Sat Jan 04 12:22:05 2020 VERIFY KU OK
Sat Jan 04 12:22:05 2020 Validating certificate extended key usage
Sat Jan 04 12:22:05 2020 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Sat Jan 04 12:22:05 2020 VERIFY EKU OK
Sat Jan 04 12:22:05 2020 VERIFY X509NAME OK: C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=ovpn.chubbable.com
Sat Jan 04 12:22:05 2020 VERIFY OK: depth=0, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=ovpn.chubbable.com
Sat Jan 04 12:22:05 2020 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Jan 04 12:22:05 2020 [ovpn.chubbable.com] Peer Connection Initiated with [AF_INET]87.236.195.236:1194
Sat Jan 04 12:22:06 2020 MANAGEMENT: >STATE:1578136926,GET_CONFIG,,,,,,
Sat Jan 04 12:22:06 2020 SENT CONTROL [ovpn.chubbable.com]: 'PUSH_REQUEST' (status=1)
Sat Jan 04 12:22:06 2020 PUSH: Received control message: 'PUSH_REPLY,route 192.168.0.0 255.255.255.0,dhcp-option DOMAIN buzalka.local,dhcp-option DNS 192.168.0.13,register-dns,route-gateway 10.0.1.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.0.1.4 255.255.255.0'
Sat Jan 04 12:22:06 2020 OPTIONS IMPORT: timers and/or timeouts modified
Sat Jan 04 12:22:06 2020 OPTIONS IMPORT: --ifconfig/up options modified
Sat Jan 04 12:22:06 2020 OPTIONS IMPORT: route options modified
Sat Jan 04 12:22:06 2020 OPTIONS IMPORT: route-related options modified
Sat Jan 04 12:22:06 2020 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Jan 04 12:22:06 2020 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:406 ET:0 EL:3 ]
Sat Jan 04 12:22:06 2020 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Sat Jan 04 12:22:06 2020 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Sat Jan 04 12:22:06 2020 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Sat Jan 04 12:22:06 2020 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Sat Jan 04 12:22:06 2020 Preserving previous TUN/TAP instance: Ethernet 2
Sat Jan 04 12:22:06 2020 Initialization Sequence Completed
Sat Jan 04 12:22:06 2020 Register_dns request sent to the service
Sat Jan 04 12:22:06 2020 MANAGEMENT: >STATE:1578136926,CONNECTED,SUCCESS,10.0.1.4,87.236.195.236,1194,,
Sat Jan 04 12:25:02 2020 [ovpn.chubbable.com] Inactivity timeout (--ping-restart), restarting
Sat Jan 04 12:25:02 2020 TCP/UDP: Closing socket

Can you advice what I should investigate?

Many thanks

V

TinCanTech

What does your server log say ?

vladob

Jan  4 12:19:14 pfSense openvpn[7881]: OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_3f5e1d8ea60fdbe9306c450655c482c6.tmp
Jan  4 12:19:14 pfSense openvpn[7881]: MULTI: Learn: 10.0.1.4 -> notebookvb/89.203.223.6:1113
Jan  4 12:19:14 pfSense openvpn[7881]: MULTI: primary virtual IP for notebookvb/89.203.223.6:1113: 10.0.1.4
Jan  4 12:19:15 pfSense openvpn[7881]: notebookvb/89.203.223.6:1113 PUSH: Received control message: 'PUSH_REQUEST'
Jan  4 12:19:15 pfSense openvpn[7881]: notebookvb/89.203.223.6:1113 send_push_reply(): safe_cap=940
Jan  4 12:19:15 pfSense openvpn[7881]: notebookvb/89.203.223.6:1113 SENT CONTROL [notebookvb]: 'PUSH_REPLY,route 192.168.0.0 255.255.255.0,dhcp-option DOMAIN buzalka.local,dhcp-option DNS 192.168.0.13,register-dns,route-gateway 10.0.1.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.0.1.4 255.255.255.0' (status=1)
Jan  4 12:19:53 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:19:53 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:19:54 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:19:54 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:20:55 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:20:55 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:20:55 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:20:55 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:21:57 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:21:57 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:21:57 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:21:57 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:22:11 pfSense openvpn[7881]: MULTI: multi_create_instance called
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Re-using SSL/TLS context
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 LZO compression initialized
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Control Channel MTU parms [ L:1558 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:143 ET:0 EL:3 AF:3/1 ]
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-server'
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Local Options hash (VER=V4): '162b04de'
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Expected Remote Options hash (VER=V4): '9e7066d2'
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 TLS: Initial packet from [AF_INET]89.203.223.6:1114, sid=fbdac6f4 134ae7ea
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 VERIFY SCRIPT OK: depth=1, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=internal-ca
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 VERIFY OK: depth=1, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=internal-ca
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 VERIFY SCRIPT OK: depth=0, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=notebookvbcert
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 VERIFY OK: depth=0, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=notebookvbcert
Jan  4 12:22:11 pfSense openvpn: user 'notebookvb' authenticated
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 TLS: Username/Password authentication succeeded for username 'notebookvb' [CN SET]
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Jan  4 12:22:11 pfSense openvpn[7881]: 89.203.223.6:1114 [notebookvb] Peer Connection Initiated with [AF_INET]89.203.223.6:1114
Jan  4 12:22:12 pfSense openvpn[7881]: MULTI: new connection by client 'notebookvb' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
Jan  4 12:22:12 pfSense openvpn[7881]: MULTI_sva: pool returned IPv4=10.0.1.4, IPv6=(Not enabled)
Jan  4 12:22:12 pfSense openvpn[7881]: OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_07ac16f06a3e24d8fb68f80f15021fd2.tmp
Jan  4 12:22:12 pfSense openvpn[7881]: MULTI: Learn: 10.0.1.4 -> notebookvb/89.203.223.6:1114
Jan  4 12:22:12 pfSense openvpn[7881]: MULTI: primary virtual IP for notebookvb/89.203.223.6:1114: 10.0.1.4
Jan  4 12:22:13 pfSense openvpn[7881]: notebookvb/89.203.223.6:1114 PUSH: Received control message: 'PUSH_REQUEST'
Jan  4 12:22:13 pfSense openvpn[7881]: notebookvb/89.203.223.6:1114 send_push_reply(): safe_cap=940
Jan  4 12:22:13 pfSense openvpn[7881]: notebookvb/89.203.223.6:1114 SENT CONTROL [notebookvb]: 'PUSH_REPLY,route 192.168.0.0 255.255.255.0,dhcp-option DOMAIN buzalka.local,dhcp-option DNS 192.168.0.13,register-dns,route-gateway 10.0.1.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.0.1.4 255.255.255.0' (status=1)
Jan  4 12:22:58 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:22:58 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:22:59 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:22:59 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:24:00 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:24:00 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:24:00 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:24:00 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:25:02 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:25:02 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:25:02 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:25:02 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:25:13 pfSense openvpn[7881]: MULTI: multi_create_instance called
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Re-using SSL/TLS context
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 LZO compression initialized
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Control Channel MTU parms [ L:1558 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:143 ET:0 EL:3 AF:3/1 ]
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-server'
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA1,keysize 256,tls-auth,key-method 2,tls-client'
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Local Options hash (VER=V4): '162b04de'
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Expected Remote Options hash (VER=V4): '9e7066d2'
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 TLS: Initial packet from [AF_INET]89.203.223.6:1194, sid=3b4553d6 80f38a1f
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 VERIFY SCRIPT OK: depth=1, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=internal-ca
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 VERIFY OK: depth=1, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=internal-ca
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 VERIFY SCRIPT OK: depth=0, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=notebookvbcert
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 VERIFY OK: depth=0, C=US, ST=asd, L=asd, O=asd, emailAddress=vladimir.buzalka@buzalka.cz, CN=notebookvbcert
Jan  4 12:25:13 pfSense openvpn: user 'notebookvb' authenticated
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 TLS: Username/Password authentication succeeded for username 'notebookvb' [CN SET]
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Jan  4 12:25:13 pfSense openvpn[7881]: 89.203.223.6:1194 [notebookvb] Peer Connection Initiated with [AF_INET]89.203.223.6:1194
Jan  4 12:25:13 pfSense openvpn[7881]: MULTI: new connection by client 'notebookvb' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
Jan  4 12:25:13 pfSense openvpn[7881]: MULTI_sva: pool returned IPv4=10.0.1.4, IPv6=(Not enabled)
Jan  4 12:25:13 pfSense openvpn[7881]: OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_f7e1a584ef0c7460d1608dc014f56ea5.tmp
Jan  4 12:25:13 pfSense openvpn[7881]: MULTI: Learn: 10.0.1.4 -> notebookvb/89.203.223.6:1194
Jan  4 12:25:13 pfSense openvpn[7881]: MULTI: primary virtual IP for notebookvb/89.203.223.6:1194: 10.0.1.4
Jan  4 12:25:14 pfSense openvpn[7881]: notebookvb/89.203.223.6:1194 PUSH: Received control message: 'PUSH_REQUEST'
Jan  4 12:25:14 pfSense openvpn[7881]: notebookvb/89.203.223.6:1194 send_push_reply(): safe_cap=940
Jan  4 12:25:14 pfSense openvpn[7881]: notebookvb/89.203.223.6:1194 SENT CONTROL [notebookvb]: 'PUSH_REPLY,route 192.168.0.0 255.255.255.0,dhcp-option DOMAIN buzalka.local,dhcp-option DNS 192.168.0.13,register-dns,route-gateway 10.0.1.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.0.1.4 255.255.255.0' (status=1)
Jan  4 12:26:03 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:26:03 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:26:04 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:26:04 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:27:05 pfSense openvpn[7881]: MANAGEMENT: Client connected from /var/etc/openvpn/server1.sock
Jan  4 12:27:05 pfSense openvpn[7881]: MANAGEMENT: CMD 'status 2'
Jan  4 12:27:05 pfSense openvpn[7881]: MANAGEMENT: CMD 'quit'
Jan  4 12:27:05 pfSense openvpn[7881]: MANAGEMENT: Client disconnected
Jan  4 12:27:30 pfSense openvpn[7881]: MULTI: multi_create_instance called
Jan  4 12:27:30 pfSense openvpn[7881]: 89.203.223.6:1114 Re-using SSL/TLS context
Jan  4 12:27:30 pfSense openvpn[7881]: 89.203.223.6:1114 LZO compression initialized
Jan  4 12:27:30 pfSense openvpn[7881]: 89.203.223.6:1114 Control Channel MTU parms [ L:1558 D:1184 EF:66 EB:0 ET:0 EL:3 ]

TinCanTech

Your server is pfSense which we don't support here.

As for openvpn, the timeout looks like some sort of network issue because it happens at a random time.

I would setup a TCP based VPN and see if that has the same problem.

vladob

Hi there, thanks for advice, I will try TCP based VPN. I have laptop with SIM card inside, when I close WIFI and switch to mobile operator internet connection, my connection works all the time without interruption. Same is true for ´wired connection to my computer, i.e. my computer in home network with cable has very stable VPN connection, breaking once per 24 hours maybe.

But when I am in wifi, it looks like you see on logs above.

Have a nice day

V

TinCanTech

Strongly suggesting there is something wrong with your wifi