openvpn - from command line works OK but from service not

belamy · Post by **belamy** » Wed Apr 04, 2018 12:49 pm

I've stuck with this problem. I've checked all but without result. There is somthing stupid or bug.

System: Ubuntu 17.10
Instalation: OpenVPN 2.4.3 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jul 3 2017
library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08

and

when I start openvpn server from command line:
$ /usr/sbin/openvpn /etc/openvpn/server.conf
server starts and works correctly, users can login.

but

when I start openvpn server as service:
service openvpn start
server starts but doesn't authorize users.

I've checed if the same config is loaded:
$ ps waux |grep openvpn

nobody 3247 0.0 0.0 56916 7124 ? Ss 14:42 0:00 /usr/sbin/openvpn --daemon ovpn-server --status /run/openvpn/server.status 10 --cd /etc/openvpn --script-security 2 --config /etc/openvpn/server.conf --writepid /run/openvpn/server.pid
root 3248 0.0 0.0 56648 3884 ? S 14:42 0:00 /usr/sbin/openvpn --daemon ovpn-server --status /run/openvpn/server.status 10 --cd /etc/openvpn --script-security 2 --config /etc/openvpn/server.conf --writepid /run/openvpn/server.pid

but loaded config is the same like from command line.

Below log from openvpn:
Apr 4 14:45:31 mp1 ovpn-server[3247]: MULTI: multi_create_instance called
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 Re-using SSL/TLS context
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 LZO compression initializing
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 Control Channel MTU parms [ L:1622 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 TLS: Initial packet from [AF_INET]10.103.53.67:61320, sid=8087d83a 32132196
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 VERIFY OK: depth=1, C=US, ST=CA, L=SanFrancisco, O=Fort-Funston, OU=T4, CN=Fort-Funston CA, name=mp1, emailAddress=it@xxxxx.pl
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 VERIFY OK: depth=0, C=US, ST=CA, L=SanFrancisco, O=Fort-Funston, OU=T4, CN=rafal, name=mp1, emailAddress=it@xxxx.pl
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_VER=2.4.4
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_PLAT=mac
Apr 4 14:45:31 mp1 openvpn[3247]: AUTH-PAM: BACKGROUND: received command code: 0
Apr 4 14:45:31 mp1 openvpn[3247]: AUTH-PAM: BACKGROUND: USER: rafal
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_PROTO=2
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_NCP=2
Apr 4 14:45:31 mp1 openvpn[3247]: AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_LZ4=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_LZ4v2=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_LZO=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_COMP_STUB=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_COMP_STUBv2=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_TCPNL=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 peer info: IV_GUI_VER="net.tunnelblick.tunnelblick_5011_3.7.5a__build_5011)"
Apr 4 14:45:31 mp1 openvpn[3247]: AUTH-PAM: BACKGROUND: user 'rafal' failed to authenticate: System error
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 PLUGIN_CALL: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=1
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 PLUGIN_CALL: plugin function PLUGIN_AUTH_USER_PASS_VERIFY failed with status 1: /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 TLS Auth Error: Auth Username/Password verification failed for peer
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Apr 4 14:45:31 mp1 ovpn-server[3247]: 10.103.53.67:61320 [rafal] Peer Connection Initiated with [AF_INET]10.103.53.67:61320
Apr 4 14:45:32 mp1 ovpn-server[3247]: 10.103.53.67:61320 PUSH: Received control message: 'PUSH_REQUEST'
Apr 4 14:45:32 mp1 ovpn-server[3247]: 10.103.53.67:61320 Delayed exit in 5 seconds
Apr 4 14:45:32 mp1 ovpn-server[3247]: 10.103.53.67:61320 SENT CONTROL [rafal]: 'AUTH_FAILED' (status=1)
Apr 4 14:45:37 mp1 ovpn-server[3247]: 10.103.53.67:61320 SIGTERM[soft,delayed-exit] received, client-instance exiting

What's going on ?

TinCanTech · Post by **TinCanTech** » Wed Apr 04, 2018 12:59 pm

Server config and log at verb 4 .. also, try to be clear about which logs belong to which instance ..

markoweb · Post by **markoweb** » Wed Apr 04, 2018 9:06 pm

try to count number of openvpn process running in both. I think openvpn is not loading the plugin properly due to which you are getting authentication failed.

ps aux | grep -c openvpn

belamy · Post by **belamy** » Thu Apr 05, 2018 10:20 am

Below my config file and two logs:
-run from command line (with successful user login)
-run as service (with failed user login, not authorized)

This is server.conf:

port 1194
proto udp
dev tun

ca /etc/openvpn/ca.crt
cert /etc/openvpn/server.crt
key /etc/openvpn/server.key # This file should be kept secret
dh /etc/openvpn/dh2048.pem

server 10.8.0.0 255.255.255.0

ifconfig-pool-persist ipp.txt

push "route 192.168.50.0 255.255.255.0"
push "redirect-gateway def1 bypass-dhcp"

push "dhcp-option DNS 8.8.8.8"
push "dhcp-option DNS 208.67.222.222"
push "dhcp-option DNS 208.67.220.220"

keepalive 10 120
comp-lzo

user nobody
group nogroup

persist-key
persist-tun
plugin /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so login
status openvpn-status.log
verb 4
explicit-exit-notify 1
log-append /var/log/openvpn.log

Here is my log when I start openvpn from command line and succesfull user login:

Thu Apr 5 12:07:42 2018 us=99044 Current Parameter Settings:
Thu Apr 5 12:07:42 2018 us=99167 config = '/etc/openvpn/server.conf'
Thu Apr 5 12:07:42 2018 us=99194 mode = 1
Thu Apr 5 12:07:42 2018 us=99220 persist_config = DISABLED
Thu Apr 5 12:07:42 2018 us=99245 persist_mode = 1
Thu Apr 5 12:07:42 2018 us=99270 show_ciphers = DISABLED
Thu Apr 5 12:07:42 2018 us=99295 show_digests = DISABLED
Thu Apr 5 12:07:42 2018 us=99320 show_engines = DISABLED
Thu Apr 5 12:07:42 2018 us=99345 genkey = DISABLED
Thu Apr 5 12:07:42 2018 us=99370 key_pass_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=99395 show_tls_ciphers = DISABLED
Thu Apr 5 12:07:42 2018 us=99420 connect_retry_max = 0
Thu Apr 5 12:07:42 2018 us=99445 Connection profiles [0]:
Thu Apr 5 12:07:42 2018 us=99470 proto = udp
Thu Apr 5 12:07:42 2018 us=99495 local = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=99520 local_port = '1194'
Thu Apr 5 12:07:42 2018 us=99545 remote = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=99569 remote_port = '1194'
Thu Apr 5 12:07:42 2018 us=99594 remote_float = DISABLED
Thu Apr 5 12:07:42 2018 us=99619 bind_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=99644 bind_local = ENABLED
Thu Apr 5 12:07:42 2018 us=99669 bind_ipv6_only = DISABLED
Thu Apr 5 12:07:42 2018 us=99694 connect_retry_seconds = 5
Thu Apr 5 12:07:42 2018 us=99719 connect_timeout = 120
Thu Apr 5 12:07:42 2018 us=99743 socks_proxy_server = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=99768 socks_proxy_port = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=99793 tun_mtu = 1500
Thu Apr 5 12:07:42 2018 us=99818 tun_mtu_defined = ENABLED
Thu Apr 5 12:07:42 2018 us=99843 link_mtu = 1500
Thu Apr 5 12:07:42 2018 us=99868 link_mtu_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=99893 tun_mtu_extra = 0
Thu Apr 5 12:07:42 2018 us=99918 tun_mtu_extra_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=99943 mtu_discover_type = -1
Thu Apr 5 12:07:42 2018 us=99968 fragment = 0
Thu Apr 5 12:07:42 2018 us=99993 mssfix = 1450
Thu Apr 5 12:07:42 2018 us=100018 explicit_exit_notification = 1
Thu Apr 5 12:07:42 2018 us=100042 Connection profiles END
Thu Apr 5 12:07:42 2018 us=100067 remote_random = DISABLED
Thu Apr 5 12:07:42 2018 us=100092 ipchange = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100117 dev = 'tun'
Thu Apr 5 12:07:42 2018 us=100141 dev_type = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100166 dev_node = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100191 lladdr = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100216 topology = 1
Thu Apr 5 12:07:42 2018 us=100240 ifconfig_local = '10.8.0.1'
Thu Apr 5 12:07:42 2018 us=100265 ifconfig_remote_netmask = '10.8.0.2'
Thu Apr 5 12:07:42 2018 us=100290 ifconfig_noexec = DISABLED
Thu Apr 5 12:07:42 2018 us=100315 ifconfig_nowarn = DISABLED
Thu Apr 5 12:07:42 2018 us=100340 ifconfig_ipv6_local = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100365 ifconfig_ipv6_netbits = 0
Thu Apr 5 12:07:42 2018 us=100389 ifconfig_ipv6_remote = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100414 shaper = 0
Thu Apr 5 12:07:42 2018 us=100439 mtu_test = 0
Thu Apr 5 12:07:42 2018 us=100464 mlock = DISABLED
Thu Apr 5 12:07:42 2018 us=100489 keepalive_ping = 10
Thu Apr 5 12:07:42 2018 us=100513 keepalive_timeout = 120
Thu Apr 5 12:07:42 2018 us=100538 inactivity_timeout = 0
Thu Apr 5 12:07:42 2018 us=100563 ping_send_timeout = 10
Thu Apr 5 12:07:42 2018 us=100588 ping_rec_timeout = 240
Thu Apr 5 12:07:42 2018 us=100613 ping_rec_timeout_action = 2
Thu Apr 5 12:07:42 2018 us=100637 ping_timer_remote = DISABLED
Thu Apr 5 12:07:42 2018 us=100662 remap_sigusr1 = 0
Thu Apr 5 12:07:42 2018 us=100687 persist_tun = ENABLED
Thu Apr 5 12:07:42 2018 us=100712 persist_local_ip = DISABLED
Thu Apr 5 12:07:42 2018 us=100736 persist_remote_ip = DISABLED
Thu Apr 5 12:07:42 2018 us=100761 persist_key = ENABLED
Thu Apr 5 12:07:42 2018 us=100785 passtos = DISABLED
Thu Apr 5 12:07:42 2018 us=100810 resolve_retry_seconds = 1000000000
Thu Apr 5 12:07:42 2018 us=100835 resolve_in_advance = DISABLED
Thu Apr 5 12:07:42 2018 us=100873 username = 'nobody'
Thu Apr 5 12:07:42 2018 us=100898 groupname = 'nogroup'
Thu Apr 5 12:07:42 2018 us=100923 chroot_dir = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100947 cd_dir = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100972 writepid = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=100997 up_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101022 down_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101046 down_pre = DISABLED
Thu Apr 5 12:07:42 2018 us=101071 up_restart = DISABLED
Thu Apr 5 12:07:42 2018 us=101096 up_delay = DISABLED
Thu Apr 5 12:07:42 2018 us=101120 daemon = DISABLED
Thu Apr 5 12:07:42 2018 us=101145 inetd = 0
Thu Apr 5 12:07:42 2018 us=101170 log = ENABLED
Thu Apr 5 12:07:42 2018 us=101195 suppress_timestamps = DISABLED
Thu Apr 5 12:07:42 2018 us=101220 machine_readable_output = DISABLED
Thu Apr 5 12:07:42 2018 us=101245 nice = 0
Thu Apr 5 12:07:42 2018 us=101270 verbosity = 4
Thu Apr 5 12:07:42 2018 us=101294 mute = 0
Thu Apr 5 12:07:42 2018 us=101319 gremlin = 0
Thu Apr 5 12:07:42 2018 us=101344 status_file = 'openvpn-status.log'
Thu Apr 5 12:07:42 2018 us=101369 status_file_version = 1
Thu Apr 5 12:07:42 2018 us=101394 status_file_update_freq = 60
Thu Apr 5 12:07:42 2018 us=101419 occ = ENABLED
Thu Apr 5 12:07:42 2018 us=101443 rcvbuf = 0
Thu Apr 5 12:07:42 2018 us=101468 sndbuf = 0
Thu Apr 5 12:07:42 2018 us=101493 mark = 0
Thu Apr 5 12:07:42 2018 us=101518 sockflags = 0
Thu Apr 5 12:07:42 2018 us=101543 fast_io = DISABLED
Thu Apr 5 12:07:42 2018 us=101568 comp.alg = 2
Thu Apr 5 12:07:42 2018 us=101592 comp.flags = 1
Thu Apr 5 12:07:42 2018 us=101617 route_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101642 route_default_gateway = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101667 route_default_metric = 0
Thu Apr 5 12:07:42 2018 us=101692 route_noexec = DISABLED
Thu Apr 5 12:07:42 2018 us=101718 route_delay = 0
Thu Apr 5 12:07:42 2018 us=101743 route_delay_window = 30
Thu Apr 5 12:07:42 2018 us=101769 route_delay_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=101794 route_nopull = DISABLED
Thu Apr 5 12:07:42 2018 us=101819 route_gateway_via_dhcp = DISABLED
Thu Apr 5 12:07:42 2018 us=101844 allow_pull_fqdn = DISABLED
Thu Apr 5 12:07:42 2018 us=101870 route 10.8.0.0/255.255.255.0/default (not set)/default (not set)
Thu Apr 5 12:07:42 2018 us=101895 management_addr = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101920 management_port = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101945 management_user_pass = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=101970 management_log_history_cache = 250
Thu Apr 5 12:07:42 2018 us=101996 management_echo_buffer_size = 100
Thu Apr 5 12:07:42 2018 us=102020 management_write_peer_info_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102046 management_client_user = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102072 management_client_group = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102097 management_flags = 0
Thu Apr 5 12:07:42 2018 us=102132 plugin[0] /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so '[/usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so] [login]'
Thu Apr 5 12:07:42 2018 us=102158 shared_secret_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102184 key_direction = 0
Thu Apr 5 12:07:42 2018 us=102209 ciphername = 'BF-CBC'
Thu Apr 5 12:07:42 2018 us=102234 ncp_enabled = ENABLED
Thu Apr 5 12:07:42 2018 us=102259 ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Thu Apr 5 12:07:42 2018 us=102284 authname = 'SHA1'
Thu Apr 5 12:07:42 2018 us=102309 prng_hash = 'SHA1'
Thu Apr 5 12:07:42 2018 us=102334 prng_nonce_secret_len = 16
Thu Apr 5 12:07:42 2018 us=102359 keysize = 0
Thu Apr 5 12:07:42 2018 us=102384 engine = DISABLED
Thu Apr 5 12:07:42 2018 us=102409 replay = ENABLED
Thu Apr 5 12:07:42 2018 us=102434 mute_replay_warnings = DISABLED
Thu Apr 5 12:07:42 2018 us=102459 replay_window = 64
Thu Apr 5 12:07:42 2018 us=102484 replay_time = 15
Thu Apr 5 12:07:42 2018 us=102510 packet_id_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102544 use_iv = ENABLED
Thu Apr 5 12:07:42 2018 us=102569 test_crypto = DISABLED
Thu Apr 5 12:07:42 2018 us=102594 tls_server = ENABLED
Thu Apr 5 12:07:42 2018 us=102619 tls_client = DISABLED
Thu Apr 5 12:07:42 2018 us=102644 key_method = 2
Thu Apr 5 12:07:42 2018 us=102669 ca_file = '/etc/openvpn/ca.crt'
Thu Apr 5 12:07:42 2018 us=102724 ca_path = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102750 dh_file = '/etc/openvpn/dh2048.pem'
Thu Apr 5 12:07:42 2018 us=102775 cert_file = '/etc/openvpn/server.crt'
Thu Apr 5 12:07:42 2018 us=102800 extra_certs_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102825 priv_key_file = '/etc/openvpn/server.key'
Thu Apr 5 12:07:42 2018 us=102850 pkcs12_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102875 cipher_list = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102899 tls_verify = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102924 tls_export_cert = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102950 verify_x509_type = 0
Thu Apr 5 12:07:42 2018 us=102975 verify_x509_name = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=102999 crl_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=103025 ns_cert_type = 0
Thu Apr 5 12:07:42 2018 us=103050 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103075 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103100 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103125 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103150 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103175 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103200 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103226 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103250 remote_cert_ku = 0
Thu Apr 5 12:07:42 2018 us=103276 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103301 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103326 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103351 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103376 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103401 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103426 remote_cert_ku[i] = 0
Thu Apr 5 12:07:42 2018 us=103451 remote_cert_eku = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=103477 ssl_flags = 0
Thu Apr 5 12:07:42 2018 us=103502 tls_timeout = 2
Thu Apr 5 12:07:42 2018 us=103527 renegotiate_bytes = -1
Thu Apr 5 12:07:42 2018 us=103552 renegotiate_packets = 0
Thu Apr 5 12:07:42 2018 us=103577 renegotiate_seconds = 3600
Thu Apr 5 12:07:42 2018 us=103603 handshake_window = 60
Thu Apr 5 12:07:42 2018 us=103628 transition_window = 3600
Thu Apr 5 12:07:42 2018 us=103653 single_session = DISABLED
Thu Apr 5 12:07:42 2018 us=103678 push_peer_info = DISABLED
Thu Apr 5 12:07:42 2018 us=103703 tls_exit = DISABLED
Thu Apr 5 12:07:42 2018 us=103728 tls_auth_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=103753 tls_crypt_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=103778 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103803 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103829 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103854 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103879 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103904 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103929 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103955 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=103980 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104005 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104030 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104055 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104080 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104105 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104130 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104164 pkcs11_protected_authentication = DISABLED
Thu Apr 5 12:07:42 2018 us=104191 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104216 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104242 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104267 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104292 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104318 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104343 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104369 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104394 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104419 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104445 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104470 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104495 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104520 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104545 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104570 pkcs11_private_mode = 00000000
Thu Apr 5 12:07:42 2018 us=104595 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104620 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104645 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104669 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104695 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104719 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104744 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104769 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104793 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104818 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104843 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104868 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104893 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104917 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104943 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104968 pkcs11_cert_private = DISABLED
Thu Apr 5 12:07:42 2018 us=104993 pkcs11_pin_cache_period = -1
Thu Apr 5 12:07:42 2018 us=105018 pkcs11_id = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=105042 pkcs11_id_management = DISABLED
Thu Apr 5 12:07:42 2018 us=105069 server_network = 10.8.0.0
Thu Apr 5 12:07:42 2018 us=105096 server_netmask = 255.255.255.0
Thu Apr 5 12:07:42 2018 us=105125 server_network_ipv6 = ::
Thu Apr 5 12:07:42 2018 us=105150 server_netbits_ipv6 = 0
Thu Apr 5 12:07:42 2018 us=105177 server_bridge_ip = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=105204 server_bridge_netmask = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=105231 server_bridge_pool_start = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=105258 server_bridge_pool_end = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=105284 push_entry = 'route 192.168.50.0 255.255.255.0'
Thu Apr 5 12:07:42 2018 us=105309 push_entry = 'redirect-gateway def1 bypass-dhcp'
Thu Apr 5 12:07:42 2018 us=105334 push_entry = 'dhcp-option DNS 8.8.8.8'
Thu Apr 5 12:07:42 2018 us=105359 push_entry = 'dhcp-option DNS 208.67.222.222'
Thu Apr 5 12:07:42 2018 us=105385 push_entry = 'dhcp-option DNS 208.67.220.220'
Thu Apr 5 12:07:42 2018 us=105410 push_entry = 'route 10.8.0.1'
Thu Apr 5 12:07:42 2018 us=105434 push_entry = 'topology net30'
Thu Apr 5 12:07:42 2018 us=105459 push_entry = 'ping 10'
Thu Apr 5 12:07:42 2018 us=105484 push_entry = 'ping-restart 120'
Thu Apr 5 12:07:42 2018 us=105509 ifconfig_pool_defined = ENABLED
Thu Apr 5 12:07:42 2018 us=105536 ifconfig_pool_start = 10.8.0.4
Thu Apr 5 12:07:42 2018 us=105563 ifconfig_pool_end = 10.8.0.251
Thu Apr 5 12:07:42 2018 us=105590 ifconfig_pool_netmask = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=105615 ifconfig_pool_persist_filename = 'ipp.txt'
Thu Apr 5 12:07:42 2018 us=105641 ifconfig_pool_persist_refresh_freq = 600
Thu Apr 5 12:07:42 2018 us=105674 ifconfig_ipv6_pool_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=105701 ifconfig_ipv6_pool_base = ::
Thu Apr 5 12:07:42 2018 us=105726 ifconfig_ipv6_pool_netbits = 0
Thu Apr 5 12:07:42 2018 us=105751 n_bcast_buf = 256
Thu Apr 5 12:07:42 2018 us=105776 tcp_queue_limit = 64
Thu Apr 5 12:07:42 2018 us=105801 real_hash_size = 256
Thu Apr 5 12:07:42 2018 us=105826 virtual_hash_size = 256
Thu Apr 5 12:07:42 2018 us=105852 client_connect_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=105876 learn_address_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=105901 client_disconnect_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=105926 client_config_dir = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=105951 ccd_exclusive = DISABLED
Thu Apr 5 12:07:42 2018 us=105976 tmp_dir = '/tmp'
Thu Apr 5 12:07:42 2018 us=106001 push_ifconfig_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=106027 push_ifconfig_local = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=106054 push_ifconfig_remote_netmask = 0.0.0.0
Thu Apr 5 12:07:42 2018 us=106079 push_ifconfig_ipv6_defined = DISABLED
Thu Apr 5 12:07:42 2018 us=106111 push_ifconfig_ipv6_local = ::/0
Thu Apr 5 12:07:42 2018 us=106138 push_ifconfig_ipv6_remote = ::
Thu Apr 5 12:07:42 2018 us=106162 enable_c2c = DISABLED
Thu Apr 5 12:07:42 2018 us=106188 duplicate_cn = DISABLED
Thu Apr 5 12:07:42 2018 us=106212 cf_max = 0
Thu Apr 5 12:07:42 2018 us=106238 cf_per = 0
Thu Apr 5 12:07:42 2018 us=106263 max_clients = 1024
Thu Apr 5 12:07:42 2018 us=106288 max_routes_per_client = 256
Thu Apr 5 12:07:42 2018 us=106313 auth_user_pass_verify_script = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=106338 auth_user_pass_verify_script_via_file = DISABLED
Thu Apr 5 12:07:42 2018 us=106363 auth_token_generate = DISABLED
Thu Apr 5 12:07:42 2018 us=106388 auth_token_lifetime = 0
Thu Apr 5 12:07:42 2018 us=106413 port_share_host = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=106438 port_share_port = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=106463 client = DISABLED
Thu Apr 5 12:07:42 2018 us=106488 pull = DISABLED
Thu Apr 5 12:07:42 2018 us=106513 auth_user_pass_file = '[UNDEF]'
Thu Apr 5 12:07:42 2018 us=106540 OpenVPN 2.4.3 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jul 3 2017
Thu Apr 5 12:07:42 2018 us=106573 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
AUTH-PAM: BACKGROUND: INIT service='login'
Thu Apr 5 12:07:42 2018 us=107943 PLUGIN_INIT: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so '[/usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so] [login]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY
Thu Apr 5 12:07:42 2018 us=108519 Diffie-Hellman initialized with 2048 bit key
Thu Apr 5 12:07:42 2018 us=109248 TLS-Auth MTU parms [ L:1622 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Apr 5 12:07:42 2018 us=109621 ROUTE_GATEWAY 192.168.50.1/255.255.255.0 IFACE=enp2s0 HWADDR=d0:50:99:a4:e8:96
Thu Apr 5 12:07:42 2018 us=111133 TUN/TAP device tun0 opened
Thu Apr 5 12:07:42 2018 us=111220 TUN/TAP TX queue length set to 100
Thu Apr 5 12:07:42 2018 us=111264 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu Apr 5 12:07:42 2018 us=111304 /sbin/ip link set dev tun0 up mtu 1500
Thu Apr 5 12:07:42 2018 us=121213 /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Thu Apr 5 12:07:42 2018 us=124545 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
Thu Apr 5 12:07:42 2018 us=126925 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Thu Apr 5 12:07:42 2018 us=128236 Could not determine IPv4/IPv6 protocol. Using AF_INET
Thu Apr 5 12:07:42 2018 us=128311 Socket Buffers: R=[212992->212992] S=[212992->212992]
Thu Apr 5 12:07:42 2018 us=128353 UDPv4 link local (bound): [AF_INET][undef]:1194
Thu Apr 5 12:07:42 2018 us=128379 UDPv4 link remote: [AF_UNSPEC]
Thu Apr 5 12:07:42 2018 us=128416 GID set to nogroup
Thu Apr 5 12:07:42 2018 us=128451 UID set to nobody
Thu Apr 5 12:07:42 2018 us=128498 MULTI: multi_init called, r=256 v=256
Thu Apr 5 12:07:42 2018 us=128599 IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Thu Apr 5 12:07:42 2018 us=142408 ifconfig_pool_read(), in='rafal,10.8.0.4', TODO: IPv6
Thu Apr 5 12:07:42 2018 us=142489 succeeded -> ifconfig_pool_set()
Thu Apr 5 12:07:42 2018 us=142522 IFCONFIG POOL LIST
Thu Apr 5 12:07:42 2018 us=142549 rafal,10.8.0.4
Thu Apr 5 12:07:42 2018 us=142641 Initialization Sequence Completed
Thu Apr 5 12:07:50 2018 us=70278 MULTI: multi_create_instance called
Thu Apr 5 12:07:50 2018 us=70466 31.0.35.83:17222 Re-using SSL/TLS context
Thu Apr 5 12:07:50 2018 us=70536 31.0.35.83:17222 LZO compression initializing
Thu Apr 5 12:07:50 2018 us=70844 31.0.35.83:17222 Control Channel MTU parms [ L:1622 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Apr 5 12:07:50 2018 us=70897 31.0.35.83:17222 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Thu Apr 5 12:07:50 2018 us=70999 31.0.35.83:17222 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Thu Apr 5 12:07:50 2018 us=71045 31.0.35.83:17222 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Thu Apr 5 12:07:50 2018 us=71135 31.0.35.83:17222 TLS: Initial packet from [AF_INET]31.0.35.83:17222, sid=f105e3a0 ed3fd849
Thu Apr 5 12:07:50 2018 us=322773 31.0.35.83:17222 VERIFY OK: depth=1, C=US, ST=CA, L=SanFrancisco, O=Fort-Funston, OU=T4, CN=Fort-Funston CA, name=mp1, emailAddress=it@xxxx.pl
Thu Apr 5 12:07:50 2018 us=323568 31.0.35.83:17222 VERIFY OK: depth=0, C=US, ST=CA, L=SanFrancisco, O=Fort-Funston, OU=T4, CN=rafal, name=mp1, emailAddress=it@xxxx.pl
Thu Apr 5 12:07:50 2018 us=412274 31.0.35.83:17222 peer info: IV_VER=2.4.4
Thu Apr 5 12:07:50 2018 us=412372 31.0.35.83:17222 peer info: IV_PLAT=mac
Thu Apr 5 12:07:50 2018 us=412421 31.0.35.83:17222 peer info: IV_PROTO=2
Thu Apr 5 12:07:50 2018 us=412468 31.0.35.83:17222 peer info: IV_NCP=2
Thu Apr 5 12:07:50 2018 us=412515 31.0.35.83:17222 peer info: IV_LZ4=1
Thu Apr 5 12:07:50 2018 us=412562 31.0.35.83:17222 peer info: IV_LZ4v2=1
Thu Apr 5 12:07:50 2018 us=412608 31.0.35.83:17222 peer info: IV_LZO=1
Thu Apr 5 12:07:50 2018 us=412655 31.0.35.83:17222 peer info: IV_COMP_STUB=1
Thu Apr 5 12:07:50 2018 us=412701 31.0.35.83:17222 peer info: IV_COMP_STUBv2=1
Thu Apr 5 12:07:50 2018 us=412748 31.0.35.83:17222 peer info: IV_TCPNL=1
Thu Apr 5 12:07:50 2018 us=412797 31.0.35.83:17222 peer info: IV_GUI_VER="net.tunnelblick.tunnelblick_5011_3.7.5a__build_5011)"
AUTH-PAM: BACKGROUND: received command code: 0
AUTH-PAM: BACKGROUND: USER: rafal
AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
Thu Apr 5 12:07:50 2018 us=450448 31.0.35.83:17222 PLUGIN_CALL: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
Thu Apr 5 12:07:50 2018 us=450554 31.0.35.83:17222 TLS: Username/Password authentication succeeded for username 'rafal'
Thu Apr 5 12:07:50 2018 us=537950 31.0.35.83:17222 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Thu Apr 5 12:07:50 2018 us=538085 31.0.35.83:17222 [rafal] Peer Connection Initiated with [AF_INET]31.0.35.83:17222
Thu Apr 5 12:07:50 2018 us=538176 rafal/31.0.35.83:17222 MULTI_sva: pool returned IPv4=10.8.0.6, IPv6=(Not enabled)
Thu Apr 5 12:07:50 2018 us=538325 rafal/31.0.35.83:17222 MULTI: Learn: 10.8.0.6 -> rafal/31.0.35.83:17222
Thu Apr 5 12:07:50 2018 us=538377 rafal/31.0.35.83:17222 MULTI: primary virtual IP for rafal/31.0.35.83:17222: 10.8.0.6
Thu Apr 5 12:07:51 2018 us=870201 rafal/31.0.35.83:17222 PUSH: Received control message: 'PUSH_REQUEST'
Thu Apr 5 12:07:51 2018 us=870373 rafal/31.0.35.83:17222 SENT CONTROL [rafal]: 'PUSH_REPLY,route 192.168.50.0 255.255.255.0,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 8.8.8.8,dhcp-option DNS 208.67.222.222,dhcp-option DNS 208.67.220.220,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.6 10.8.0.5,peer-id 0,cipher AES-256-GCM' (status=1)
Thu Apr 5 12:07:51 2018 us=870455 rafal/31.0.35.83:17222 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Apr 5 12:07:51 2018 us=870519 rafal/31.0.35.83:17222 Data Channel MTU parms [ L:1550 D:1450 EF:50 EB:406 ET:0 EL:3 ]
Thu Apr 5 12:07:51 2018 us=870804 rafal/31.0.35.83:17222 Data Channel Encrypt: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Apr 5 12:07:51 2018 us=870861 rafal/31.0.35.83:17222 Data Channel Decrypt: Cipher 'AES-256-GCM' initialized with 256 bit key

and here is log when I start openvpn as service:

Thu Apr 5 14:23:26 2018 OpenVPN 2.4.3 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jul 3 2017
Thu Apr 5 14:23:26 2018 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Thu Apr 5 14:23:26 2018 PLUGIN_INIT: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so '[/usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so] [login]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY
Thu Apr 5 14:23:26 2018 Diffie-Hellman initialized with 2048 bit key
Thu Apr 5 14:23:26 2018 ROUTE_GATEWAY 192.168.50.1/255.255.255.0 IFACE=enp2s0 HWADDR=d0:50:99:a4:e8:96
Thu Apr 5 14:23:26 2018 us=170445 Current Parameter Settings:
Thu Apr 5 14:23:26 2018 us=170555 config = '/etc/openvpn/server.conf'
Thu Apr 5 14:23:26 2018 us=170588 mode = 1
Thu Apr 5 14:23:26 2018 us=170619 persist_config = DISABLED
Thu Apr 5 14:23:26 2018 us=170650 persist_mode = 1
Thu Apr 5 14:23:26 2018 us=170704 show_ciphers = DISABLED
Thu Apr 5 14:23:26 2018 us=170737 show_digests = DISABLED
Thu Apr 5 14:23:26 2018 us=170767 show_engines = DISABLED
Thu Apr 5 14:23:26 2018 us=170798 genkey = DISABLED
Thu Apr 5 14:23:26 2018 us=170829 key_pass_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=170863 show_tls_ciphers = DISABLED
Thu Apr 5 14:23:26 2018 us=170888 connect_retry_max = 0
Thu Apr 5 14:23:26 2018 us=170914 Connection profiles [0]:
Thu Apr 5 14:23:26 2018 us=170940 proto = udp
Thu Apr 5 14:23:26 2018 us=170965 local = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=170990 local_port = '1194'
Thu Apr 5 14:23:26 2018 us=171015 remote = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171040 remote_port = '1194'
Thu Apr 5 14:23:26 2018 us=171065 remote_float = DISABLED
Thu Apr 5 14:23:26 2018 us=171090 bind_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=171115 bind_local = ENABLED
Thu Apr 5 14:23:26 2018 us=171140 bind_ipv6_only = DISABLED
Thu Apr 5 14:23:26 2018 us=171165 connect_retry_seconds = 5
Thu Apr 5 14:23:26 2018 us=171190 connect_timeout = 120
Thu Apr 5 14:23:26 2018 us=171215 socks_proxy_server = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171240 socks_proxy_port = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171265 tun_mtu = 1500
Thu Apr 5 14:23:26 2018 us=171290 tun_mtu_defined = ENABLED
Thu Apr 5 14:23:26 2018 us=171316 link_mtu = 1500
Thu Apr 5 14:23:26 2018 us=171341 link_mtu_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=171366 tun_mtu_extra = 0
Thu Apr 5 14:23:26 2018 us=171391 tun_mtu_extra_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=171416 mtu_discover_type = -1
Thu Apr 5 14:23:26 2018 us=171441 fragment = 0
Thu Apr 5 14:23:26 2018 us=171466 mssfix = 1450
Thu Apr 5 14:23:26 2018 us=171491 explicit_exit_notification = 1
Thu Apr 5 14:23:26 2018 us=171517 Connection profiles END
Thu Apr 5 14:23:26 2018 us=171542 remote_random = DISABLED
Thu Apr 5 14:23:26 2018 us=171566 ipchange = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171592 dev = 'tun'
Thu Apr 5 14:23:26 2018 us=171616 dev_type = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171642 dev_node = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171667 lladdr = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171692 topology = 1
Thu Apr 5 14:23:26 2018 us=171717 ifconfig_local = '10.8.0.1'
Thu Apr 5 14:23:26 2018 us=171743 ifconfig_remote_netmask = '10.8.0.2'
Thu Apr 5 14:23:26 2018 us=171768 ifconfig_noexec = DISABLED
Thu Apr 5 14:23:26 2018 us=171793 ifconfig_nowarn = DISABLED
Thu Apr 5 14:23:26 2018 us=171818 ifconfig_ipv6_local = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171843 ifconfig_ipv6_netbits = 0
Thu Apr 5 14:23:26 2018 us=171867 ifconfig_ipv6_remote = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=171892 shaper = 0
Thu Apr 5 14:23:26 2018 us=171917 mtu_test = 0
Thu Apr 5 14:23:26 2018 us=171942 mlock = DISABLED
Thu Apr 5 14:23:26 2018 us=171967 keepalive_ping = 10
Thu Apr 5 14:23:26 2018 us=171992 keepalive_timeout = 120
Thu Apr 5 14:23:26 2018 us=172018 inactivity_timeout = 0
Thu Apr 5 14:23:26 2018 us=172043 ping_send_timeout = 10
Thu Apr 5 14:23:26 2018 us=172068 ping_rec_timeout = 240
Thu Apr 5 14:23:26 2018 us=172111 ping_rec_timeout_action = 2
Thu Apr 5 14:23:26 2018 us=172137 ping_timer_remote = DISABLED
Thu Apr 5 14:23:26 2018 us=172162 remap_sigusr1 = 0
Thu Apr 5 14:23:26 2018 us=172187 persist_tun = ENABLED
Thu Apr 5 14:23:26 2018 us=172212 persist_local_ip = DISABLED
Thu Apr 5 14:23:26 2018 us=172237 persist_remote_ip = DISABLED
Thu Apr 5 14:23:26 2018 us=172262 persist_key = ENABLED
Thu Apr 5 14:23:26 2018 us=172286 passtos = DISABLED
Thu Apr 5 14:23:26 2018 us=172312 resolve_retry_seconds = 1000000000
Thu Apr 5 14:23:26 2018 us=172337 resolve_in_advance = DISABLED
Thu Apr 5 14:23:26 2018 us=172362 username = 'nobody'
Thu Apr 5 14:23:26 2018 us=172386 groupname = 'nogroup'
Thu Apr 5 14:23:26 2018 us=172411 chroot_dir = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=172436 cd_dir = '/etc/openvpn'
Thu Apr 5 14:23:26 2018 us=172461 writepid = '/run/openvpn/server.pid'
Thu Apr 5 14:23:26 2018 us=172486 up_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=172511 down_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=172536 down_pre = DISABLED
Thu Apr 5 14:23:26 2018 us=172560 up_restart = DISABLED
Thu Apr 5 14:23:26 2018 us=172585 up_delay = DISABLED
Thu Apr 5 14:23:26 2018 us=172610 daemon = ENABLED
Thu Apr 5 14:23:26 2018 us=172636 inetd = 0
Thu Apr 5 14:23:26 2018 us=172661 log = ENABLED
Thu Apr 5 14:23:26 2018 us=172686 suppress_timestamps = DISABLED
Thu Apr 5 14:23:26 2018 us=172710 machine_readable_output = DISABLED
Thu Apr 5 14:23:26 2018 us=172735 nice = 0
Thu Apr 5 14:23:26 2018 us=172760 verbosity = 4
Thu Apr 5 14:23:26 2018 us=172785 mute = 0
Thu Apr 5 14:23:26 2018 us=172810 gremlin = 0
Thu Apr 5 14:23:26 2018 us=172835 status_file = 'openvpn-status.log'
Thu Apr 5 14:23:26 2018 us=172860 status_file_version = 1
Thu Apr 5 14:23:26 2018 us=172886 status_file_update_freq = 10
Thu Apr 5 14:23:26 2018 us=172911 occ = ENABLED
Thu Apr 5 14:23:26 2018 us=172936 rcvbuf = 0
Thu Apr 5 14:23:26 2018 us=172961 sndbuf = 0
Thu Apr 5 14:23:26 2018 us=172986 mark = 0
Thu Apr 5 14:23:26 2018 us=173011 sockflags = 0
Thu Apr 5 14:23:26 2018 us=173036 fast_io = DISABLED
Thu Apr 5 14:23:26 2018 us=173060 comp.alg = 2
Thu Apr 5 14:23:26 2018 us=173086 comp.flags = 1
Thu Apr 5 14:23:26 2018 us=173110 route_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173136 route_default_gateway = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173161 route_default_metric = 0
Thu Apr 5 14:23:26 2018 us=173186 route_noexec = DISABLED
Thu Apr 5 14:23:26 2018 us=173212 route_delay = 0
Thu Apr 5 14:23:26 2018 us=173238 route_delay_window = 30
Thu Apr 5 14:23:26 2018 us=173263 route_delay_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=173288 route_nopull = DISABLED
Thu Apr 5 14:23:26 2018 us=173313 route_gateway_via_dhcp = DISABLED
Thu Apr 5 14:23:26 2018 us=173338 allow_pull_fqdn = DISABLED
Thu Apr 5 14:23:26 2018 us=173365 route 10.8.0.0/255.255.255.0/default (not set)/default (not set)
Thu Apr 5 14:23:26 2018 us=173390 management_addr = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173416 management_port = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173441 management_user_pass = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173466 management_log_history_cache = 250
Thu Apr 5 14:23:26 2018 us=173492 management_echo_buffer_size = 100
Thu Apr 5 14:23:26 2018 us=173517 management_write_peer_info_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173543 management_client_user = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173570 management_client_group = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173596 management_flags = 0
Thu Apr 5 14:23:26 2018 us=173633 plugin[0] /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so '[/usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so] [login]'
Thu Apr 5 14:23:26 2018 us=173660 shared_secret_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=173686 key_direction = 0
Thu Apr 5 14:23:26 2018 us=173711 ciphername = 'BF-CBC'
Thu Apr 5 14:23:26 2018 us=173749 ncp_enabled = ENABLED
Thu Apr 5 14:23:26 2018 us=173775 ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Thu Apr 5 14:23:26 2018 us=173801 authname = 'SHA1'
Thu Apr 5 14:23:26 2018 us=173826 prng_hash = 'SHA1'
Thu Apr 5 14:23:26 2018 us=173852 prng_nonce_secret_len = 16
Thu Apr 5 14:23:26 2018 us=173877 keysize = 0
Thu Apr 5 14:23:26 2018 us=173903 engine = DISABLED
Thu Apr 5 14:23:26 2018 us=173928 replay = ENABLED
Thu Apr 5 14:23:26 2018 us=173955 mute_replay_warnings = DISABLED
Thu Apr 5 14:23:26 2018 us=173980 replay_window = 64
Thu Apr 5 14:23:26 2018 us=174006 replay_time = 15
Thu Apr 5 14:23:26 2018 us=174032 packet_id_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174058 use_iv = ENABLED
Thu Apr 5 14:23:26 2018 us=174084 test_crypto = DISABLED
Thu Apr 5 14:23:26 2018 us=174110 tls_server = ENABLED
Thu Apr 5 14:23:26 2018 us=174136 tls_client = DISABLED
Thu Apr 5 14:23:26 2018 us=174162 key_method = 2
Thu Apr 5 14:23:26 2018 us=174187 ca_file = '/etc/openvpn/ca.crt'
Thu Apr 5 14:23:26 2018 us=174213 ca_path = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174238 dh_file = '/etc/openvpn/dh2048.pem'
Thu Apr 5 14:23:26 2018 us=174264 cert_file = '/etc/openvpn/server.crt'
Thu Apr 5 14:23:26 2018 us=174290 extra_certs_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174315 priv_key_file = '/etc/openvpn/server.key'
Thu Apr 5 14:23:26 2018 us=174341 pkcs12_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174366 cipher_list = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174392 tls_verify = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174417 tls_export_cert = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174443 verify_x509_type = 0
Thu Apr 5 14:23:26 2018 us=174469 verify_x509_name = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174494 crl_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=174520 ns_cert_type = 0
Thu Apr 5 14:23:26 2018 us=174545 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=174571 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=174596 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=174622 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=174647 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 TUN/TAP device tun0 opened
Thu Apr 5 14:23:26 2018 TUN/TAP TX queue length set to 100
Thu Apr 5 14:23:26 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu Apr 5 14:23:26 2018 /sbin/ip link set dev tun0 up mtu 1500
Thu Apr 5 14:23:26 2018 us=176503 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176584 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176613 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176639 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176665 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176691 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176717 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176743 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176769 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176794 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176820 remote_cert_ku[i] = 0
Thu Apr 5 14:23:26 2018 us=176847 remote_cert_eku = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=176873 ssl_flags = 0
Thu Apr 5 14:23:26 2018 us=176899 tls_timeout = 2
Thu Apr 5 14:23:26 2018 us=176925 renegotiate_bytes = -1
Thu Apr 5 14:23:26 2018 us=176950 renegotiate_packets = 0
Thu Apr 5 14:23:26 2018 us=176977 renegotiate_seconds = 3600
Thu Apr 5 14:23:26 2018 us=177002 handshake_window = 60
Thu Apr 5 14:23:26 2018 us=177028 transition_window = 3600
Thu Apr 5 14:23:26 2018 us=177053 single_session = DISABLED
Thu Apr 5 14:23:26 2018 us=177079 push_peer_info = DISABLED
Thu Apr 5 14:23:26 2018 us=177105 tls_exit = DISABLED
Thu Apr 5 14:23:26 2018 us=177130 tls_auth_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=177156 tls_crypt_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=177182 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177208 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177234 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177280 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177306 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177332 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177358 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177384 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177409 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177435 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177460 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177487 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177514 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177540 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177565 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177591 pkcs11_protected_authentication = DISABLED
Thu Apr 5 14:23:26 2018 us=177617 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177643 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177669 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177695 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177721 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177746 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177772 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177798 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177824 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177850 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177876 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177901 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177927 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177952 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=177978 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=178003 pkcs11_private_mode = 00000000
Thu Apr 5 14:23:26 2018 us=178029 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178054 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178080 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178105 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178130 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178156 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178182 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178207 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178232 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178258 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178283 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178308 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178333 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178359 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178384 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178410 pkcs11_cert_private = DISABLED
Thu Apr 5 14:23:26 2018 us=178436 pkcs11_pin_cache_period = -1
Thu Apr 5 14:23:26 2018 us=178461 pkcs11_id = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=178486 pkcs11_id_management = DISABLED
Thu Apr 5 14:23:26 2018 us=178514 server_network = 10.8.0.0
Thu Apr 5 14:23:26 2018 us=178541 server_netmask = 255.255.255.0
Thu Apr 5 14:23:26 2018 us=178570 server_network_ipv6 = ::
Thu Apr 5 14:23:26 2018 us=178596 server_netbits_ipv6 = 0
Thu Apr 5 14:23:26 2018 us=178624 server_bridge_ip = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=178652 server_bridge_netmask = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=178713 server_bridge_pool_start = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=178743 server_bridge_pool_end = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=178769 push_entry = 'route 192.168.50.0 255.255.255.0'
Thu Apr 5 14:23:26 2018 us=178795 push_entry = 'redirect-gateway def1 bypass-dhcp'
Thu Apr 5 14:23:26 2018 us=178840 push_entry = 'dhcp-option DNS 8.8.8.8'
Thu Apr 5 14:23:26 2018 us=178866 push_entry = 'dhcp-option DNS 208.67.222.222'
Thu Apr 5 14:23:26 2018 us=178892 push_entry = 'dhcp-option DNS 208.67.220.220'
Thu Apr 5 14:23:26 2018 us=178918 push_entry = 'route 10.8.0.1'
Thu Apr 5 14:23:26 2018 us=178943 push_entry = 'topology net30'
Thu Apr 5 14:23:26 2018 us=178968 push_entry = 'ping 10'
Thu Apr 5 14:23:26 2018 us=178994 push_entry = 'ping-restart 120'
Thu Apr 5 14:23:26 2018 us=179019 ifconfig_pool_defined = ENABLED
Thu Apr 5 14:23:26 2018 /sbin/ip addr add dev tun0 local 10.8.0.1 peer 10.8.0.2
Thu Apr 5 14:23:26 2018 us=179047 ifconfig_pool_start = 10.8.0.4
Thu Apr 5 14:23:26 2018 us=179097 ifconfig_pool_end = 10.8.0.251
Thu Apr 5 14:23:26 2018 us=179125 ifconfig_pool_netmask = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=179151 ifconfig_pool_persist_filename = 'ipp.txt'
Thu Apr 5 14:23:26 2018 us=179177 ifconfig_pool_persist_refresh_freq = 600
Thu Apr 5 14:23:26 2018 us=179203 ifconfig_ipv6_pool_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=179231 ifconfig_ipv6_pool_base = ::
Thu Apr 5 14:23:26 2018 us=179256 ifconfig_ipv6_pool_netbits = 0
Thu Apr 5 14:23:26 2018 us=179282 n_bcast_buf = 256
Thu Apr 5 14:23:26 2018 us=179308 tcp_queue_limit = 64
Thu Apr 5 14:23:26 2018 us=179334 real_hash_size = 256
Thu Apr 5 14:23:26 2018 us=179359 virtual_hash_size = 256
Thu Apr 5 14:23:26 2018 us=179385 client_connect_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=179410 learn_address_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=179436 client_disconnect_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=179462 client_config_dir = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=179487 ccd_exclusive = DISABLED
Thu Apr 5 14:23:26 2018 us=179513 tmp_dir = '/tmp'
Thu Apr 5 14:23:26 2018 us=179538 push_ifconfig_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=179565 push_ifconfig_local = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=179593 push_ifconfig_remote_netmask = 0.0.0.0
Thu Apr 5 14:23:26 2018 us=179619 push_ifconfig_ipv6_defined = DISABLED
Thu Apr 5 14:23:26 2018 us=179660 push_ifconfig_ipv6_local = ::/0
Thu Apr 5 14:23:26 2018 us=179688 push_ifconfig_ipv6_remote = ::
Thu Apr 5 14:23:26 2018 us=179714 enable_c2c = DISABLED
Thu Apr 5 14:23:26 2018 us=179740 duplicate_cn = DISABLED
Thu Apr 5 14:23:26 2018 us=179765 cf_max = 0
Thu Apr 5 14:23:26 2018 us=179791 cf_per = 0
Thu Apr 5 14:23:26 2018 us=179817 max_clients = 1024
Thu Apr 5 14:23:26 2018 us=179842 max_routes_per_client = 256
Thu Apr 5 14:23:26 2018 us=179868 auth_user_pass_verify_script = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=179893 auth_user_pass_verify_script_via_file = DISABLED
Thu Apr 5 14:23:26 2018 us=179919 auth_token_generate = DISABLED
Thu Apr 5 14:23:26 2018 us=179944 auth_token_lifetime = 0
Thu Apr 5 14:23:26 2018 us=179970 port_share_host = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=179995 port_share_port = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=180021 client = DISABLED
Thu Apr 5 14:23:26 2018 us=180046 pull = DISABLED
Thu Apr 5 14:23:26 2018 us=180072 auth_user_pass_file = '[UNDEF]'
Thu Apr 5 14:23:26 2018 us=180099 OpenVPN 2.4.3 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jul 3 2017
Thu Apr 5 14:23:26 2018 us=180138 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Thu Apr 5 14:23:26 2018 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
AUTH-PAM: BACKGROUND: INIT service='login'
Thu Apr 5 14:23:26 2018 us=184181 PLUGIN_INIT: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so '[/usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so] [login]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY
Thu Apr 5 14:23:26 2018 us=184804 Diffie-Hellman initialized with 2048 bit key
Thu Apr 5 14:23:26 2018 us=185622 TLS-Auth MTU parms [ L:1622 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Apr 5 14:23:26 2018 us=187128 ROUTE_GATEWAY 192.168.50.1/255.255.255.0 IFACE=enp2s0 HWADDR=d0:50:99:a4:e8:96
Thu Apr 5 14:23:26 2018 Could not determine IPv4/IPv6 protocol. Using AF_INET
Thu Apr 5 14:23:26 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Thu Apr 5 14:23:26 2018 UDPv4 link local (bound): [AF_INET][undef]:1194
Thu Apr 5 14:23:26 2018 UDPv4 link remote: [AF_UNSPEC]
Thu Apr 5 14:23:26 2018 GID set to nogroup
Thu Apr 5 14:23:26 2018 us=187569 TUN/TAP device tun1 opened
Thu Apr 5 14:23:26 2018 us=187616 TUN/TAP TX queue length set to 100
Thu Apr 5 14:23:26 2018 us=187658 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu Apr 5 14:23:26 2018 us=187697 /sbin/ip link set dev tun1 up mtu 1500
Thu Apr 5 14:23:26 2018 us=190253 /sbin/ip addr add dev tun1 local 10.8.0.1 peer 10.8.0.2
Thu Apr 5 14:23:26 2018 UID set to nobody
Thu Apr 5 14:23:26 2018 MULTI: multi_init called, r=256 v=256
Thu Apr 5 14:23:26 2018 IFCONFIG POOL: base=10.8.0.4 size=62, ipv6=0
Thu Apr 5 14:23:26 2018 ifconfig_pool_read(), in='rafal,10.8.0.4', TODO: IPv6
Thu Apr 5 14:23:26 2018 succeeded -> ifconfig_pool_set()
Thu Apr 5 14:23:26 2018 IFCONFIG POOL LIST
Thu Apr 5 14:23:26 2018 rafal,10.8.0.4
Thu Apr 5 14:23:26 2018 Initialization Sequence Completed
Thu Apr 5 14:23:26 2018 us=195031 /sbin/ip route add 10.8.0.0/24 via 10.8.0.2
RTNETLINK answers: File exists
Thu Apr 5 14:23:26 2018 us=197055 ERROR: Linux route add command failed: external program exited with error status: 2
Thu Apr 5 14:23:26 2018 us=197153 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Thu Apr 5 14:23:26 2018 us=198158 Could not determine IPv4/IPv6 protocol. Using AF_INET
Thu Apr 5 14:23:26 2018 us=198230 Socket Buffers: R=[212992->212992] S=[212992->212992]
Thu Apr 5 14:23:26 2018 us=198277 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use
Thu Apr 5 14:23:26 2018 us=198310 Exiting due to fatal error
Thu Apr 5 14:23:26 2018 us=198358 Closing TUN/TAP interface
Thu Apr 5 14:23:26 2018 us=198395 /sbin/ip addr del dev tun1 local 10.8.0.1 peer 10.8.0.2
AUTH-PAM: BACKGROUND: received command code: 1
AUTH-PAM: BACKGROUND: EXIT
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 TLS: Initial packet from [AF_INET]22.33.44.55:63147, sid=8cd7c0ca 76473b90
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 VERIFY OK: depth=1, C=US, ST=CA, L=SanFrancisco, O=Fort-Funston, OU=T4, CN=Fort-Funston CA, name=mp1, emailAddress=
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 VERIFY OK: depth=0, C=US, ST=CA, L=SanFrancisco, O=Fort-Funston, OU=T4, CN=rafal, name=mp1, emailAddress=
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_VER=2.4.4
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_PLAT=mac
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_PROTO=2
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_NCP=2
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_LZ4=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_LZ4v2=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_LZO=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_COMP_STUB=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_COMP_STUBv2=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_TCPNL=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 peer info: IV_GUI_VER="net.tunnelblick.tunnelblick_5011_3.7.5a__build_5011)"
AUTH-PAM: BACKGROUND: user 'rafal' failed to authenticate: System error
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 PLUGIN_CALL: POST /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=1
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 PLUGIN_CALL: plugin function PLUGIN_AUTH_USER_PASS_VERIFY failed with status 1: /usr/lib/x86_64-linux-gnu/openvpn/plugins/openvpn-plugin-auth-pam.so
Thu Apr 5 14:23:39 2018 22.33.44.55:63147 TLS Auth Error: Auth Username/Password verification failed for peer
Thu Apr 5 14:23:40 2018 22.33.44.55:63147 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Thu Apr 5 14:23:40 2018 22.33.44.55:63147 [rafal] Peer Connection Initiated with [AF_INET]22.33.44.55:63147
Thu Apr 5 14:23:41 2018 22.33.44.55:63147 PUSH: Received control message: 'PUSH_REQUEST'
Thu Apr 5 14:23:41 2018 22.33.44.55:63147 Delayed exit in 5 seconds
Thu Apr 5 14:23:41 2018 22.33.44.55:63147 SENT CONTROL [rafal]: 'AUTH_FAILED' (status=1)

belamy · Post by **belamy** » Thu Apr 05, 2018 10:26 am

markoweb wrote: ↑
Wed Apr 04, 2018 9:06 pm
try to count number of openvpn process running in both. I think openvpn is not loading the plugin properly due to which you are getting authentication failed.

ps aux | grep -c openvpn

The same: 3 processes (2 from openvpn and one from grep)

# /usr/sbin/openvpn /etc/openvpn/server.conf
# ps aux | grep -c openvpn
3

# /etc/init.d/openvpn start
# ps aux | grep -c openvpn
3

TinCanTech · Post by **TinCanTech** » Thu Apr 05, 2018 11:54 am

belamy wrote: ↑
Thu Apr 05, 2018 10:26 am
and here is log when I start openvpn as service:

Thu Apr 5 12:13:03 2018 us=479897 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use
Thu Apr 5 12:13:03 2018 us=479962 Exiting due to fatal error

You can only run the same config file once .. so you cannot start the service after starting at the command line until you kill the command line instance.

belamy · Post by **belamy** » Thu Apr 05, 2018 12:37 pm

TinCanTech wrote: ↑
Thu Apr 05, 2018 11:54 am

belamy wrote: ↑
Thu Apr 05, 2018 10:26 am
and here is log when I start openvpn as service:

Thu Apr 5 12:13:03 2018 us=479897 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use
Thu Apr 5 12:13:03 2018 us=479962 Exiting due to fatal error
You can only run the same config file once .. so you cannot start the service after starting at the command line until you kill the command line instance.

It is very strange. I've checked this again

Sccenario:
# ps aux | grep -c openvpn
1 (only grep command, no openvpn instance)

# service openvpn start

in log still "in use":

Thu Apr 5 14:23:26 2018 us=197153 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Thu Apr 5 14:23:26 2018 us=198158 Could not determine IPv4/IPv6 protocol. Using AF_INET
Thu Apr 5 14:23:26 2018 us=198230 Socket Buffers: R=[212992->212992] S=[212992->212992]
Thu Apr 5 14:23:26 2018 us=198277 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use
Thu Apr 5 14:23:26 2018 us=198310 Exiting due to fatal error
Thu Apr 5 14:23:26 2018 us=198358 Closing TUN/TAP interface

Why?

TinCanTech · Post by **TinCanTech** » Thu Apr 05, 2018 12:52 pm

Your command line instance started ok .. then your service instance did not .. and they both use the same port.

belamy · Post by **belamy** » Mon Apr 09, 2018 8:51 am

TinCanTech wrote: ↑
Thu Apr 05, 2018 12:52 pm
Your command line instance started ok .. then your service instance did not .. and they both use the same port.

No. I tested both of the configurations "comand line" and "service".
After all test I kill all instances of openvpn or service and checked all process for sure.

Even if I start linux, without any openvpn.

# ps waux| grep openvpn
root 1721 0.0 0.0 15892 1052 pts/1 S+ 10:49 0:00 grep --color=auto openvpn
(only my grep process, no openvpn instance)

# service openvpn start

and in log file, again "in use":

Mon Apr 9 10:43:34 2018 us=786745 Socket Buffers: R=[212992->212992] S=[212992->212992]
Mon Apr 9 10:43:34 2018 us=786797 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use
Mon Apr 9 10:43:34 2018 us=786830 Exiting due to fatal error
Mon Apr 9 10:43:34 2018 us=786878 Closing TUN/TAP interface

belamy · Post by **belamy** » Mon Apr 09, 2018 12:32 pm

--- CASE CLOSED ---

I uninstalled OpenVPN 2.4.3 and installed OpenVPN 2.3.10.
All work perfect. The same config, keys, etc..

Maybe there is bug at 2.4.3...

Okini · Post by **Okini** » Thu Jul 19, 2018 12:03 pm

use nobind in client config.

OpenVPN Support Forum

openvpn - from command line works OK but from service not

openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not

Re: openvpn - from command line works OK but from service not