[Solved] learn-address: kill: Operation not permitted

jiriprchal

Hi all,
please, help with this issue.
After upgrade to Debian 9 (OpenVPN 2.4.0) I have problem to run command in script learn-address

kill -HUP $(cat /run/dnsmasq/dnsmasq.pid)

it complies in log
/etc/openvpn/server/learn-address: line 72: kill: (627) - Operation not permitted
In previous Debian 8 it ran.
At command line it runs.
Trying for a while, searching everywhere but no success. Script is executed as root (tested by echoing uid in it), config:

learn-address /etc/openvpn/server/learn-address
script-security 2

If you need complete conf, script or surrounding log, I'll post them.
Thanks in advance.
Jiri

TinCanTech

jiriprchal wrote Script is executed as root (tested by echoing uid in it),

jiriprchal wrote in log
/etc/openvpn/server/learn-address: line 72: kill: (627) - Operation not permitted

The error message means the operation is not permitted .. probably due to not being run with root.

Please post your complete server config and log file at --verb 4

jiriprchal

Here it is:

port 11194
proto udp
dev tun

ca /etc/openvpn/server/ca.crt
cert /etc/openvpn/server/srv_cdu.crt
key /etc/openvpn/server/srv_cdu.key # This file should be kept secret
dh /etc/openvpn/server/dh.pem
tls-auth /etc/openvpn/server/ta.key 0 # This file is secret

topology subnet
mode server
tls-server
ifconfig 172.27.224.1 255.255.0.0
ifconfig-pool 172.27.224.2 172.27.255.254 255.255.224.0
route 172.27.0.0 255.255.0.0
#route-gateway 172.27.224.1

script-security 2
keepalive 55 180
compress lzo
#reneg-sec 10400
#tls-timeout 3
#user nobody
#group nogroup

username-as-common-name
auth-user-pass-verify /etc/openvpn/server/user-pass-verify via-env
push "route 172.27.224.1" #to server
push "route 172.28.0.0 255.255.0.0" #to other vnp with PCs
push "dhcp-option DNS 172.27.224.1"
push "dhcp-option DOMAIN cdu.vpn.aksignal.cz"
push "dhcp-option NTP 172.27.224.1"
;push "redirect-gateway def1 bypass-dhcp"
client-config-dir /etc/openvpn/server/ccd
learn-address /etc/openvpn/server/learn-address
;client-to-client
;duplicate-cn

status /run/openvpn/srv_cdu.status 60
#status-version 2
log /run/openvpn/srv_cdu.log
;--daemon ovpn-srv_cdu
verb 4
#mute 3

Truncated log:

Mon Oct 9 12:32:18 2017 us=437856 Current Parameter Settings:
Mon Oct 9 12:32:18 2017 us=439783 config = '/etc/openvpn/srv_cdu.conf'
Mon Oct 9 12:32:18 2017 us=439891 mode = 1
Mon Oct 9 12:32:18 2017 us=440036 persist_config = DISABLED
Mon Oct 9 12:32:18 2017 us=440117 persist_mode = 1
Mon Oct 9 12:32:18 2017 us=440190 show_ciphers = DISABLED
Mon Oct 9 12:32:18 2017 us=440292 show_digests = DISABLED
Mon Oct 9 12:32:18 2017 us=440367 show_engines = DISABLED
Mon Oct 9 12:32:18 2017 us=440454 genkey = DISABLED
Mon Oct 9 12:32:18 2017 us=440557 key_pass_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=440639 show_tls_ciphers = DISABLED
Mon Oct 9 12:32:18 2017 us=440709 connect_retry_max = 0
Mon Oct 9 12:32:18 2017 us=442972 Connection profiles [0]:
Mon Oct 9 12:32:18 2017 us=443074 proto = udp
Mon Oct 9 12:32:18 2017 us=443165 local = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=443235 local_port = '11194'
Mon Oct 9 12:32:18 2017 us=443328 remote = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=443411 remote_port = '11194'
Mon Oct 9 12:32:18 2017 us=443478 remote_float = DISABLED
Mon Oct 9 12:32:18 2017 us=443551 bind_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=443643 bind_local = ENABLED
Mon Oct 9 12:32:18 2017 us=443724 bind_ipv6_only = DISABLED
Mon Oct 9 12:32:18 2017 us=443807 connect_retry_seconds = 5
Mon Oct 9 12:32:18 2017 us=443887 connect_timeout = 120
Mon Oct 9 12:32:18 2017 us=443963 socks_proxy_server = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=444105 socks_proxy_port = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=444180 tun_mtu = 1500
Mon Oct 9 12:32:18 2017 us=444261 tun_mtu_defined = ENABLED
Mon Oct 9 12:32:18 2017 us=444336 link_mtu = 1500
Mon Oct 9 12:32:18 2017 us=444415 link_mtu_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=444488 tun_mtu_extra = 0
Mon Oct 9 12:32:18 2017 us=444559 tun_mtu_extra_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=444634 mtu_discover_type = -1
Mon Oct 9 12:32:18 2017 us=444715 fragment = 0
Mon Oct 9 12:32:18 2017 us=444799 mssfix = 1450
Mon Oct 9 12:32:18 2017 us=452695 explicit_exit_notification = 0
Mon Oct 9 12:32:18 2017 us=452817 Connection profiles END
Mon Oct 9 12:32:18 2017 us=452856 remote_random = DISABLED
Mon Oct 9 12:32:18 2017 us=452892 ipchange = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=452937 dev = 'tun'
Mon Oct 9 12:32:18 2017 us=452974 dev_type = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=453013 dev_node = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=453049 lladdr = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=453084 topology = 3
Mon Oct 9 12:32:18 2017 us=453119 ifconfig_local = '172.27.224.1'
Mon Oct 9 12:32:18 2017 us=453157 ifconfig_remote_netmask = '255.255.0.0'
Mon Oct 9 12:32:18 2017 us=453219 ifconfig_noexec = DISABLED
Mon Oct 9 12:32:18 2017 us=453255 ifconfig_nowarn = DISABLED
Mon Oct 9 12:32:18 2017 us=453282 ifconfig_ipv6_local = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=453313 ifconfig_ipv6_netbits = 0
Mon Oct 9 12:32:18 2017 us=453344 ifconfig_ipv6_remote = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=453374 shaper = 0
Mon Oct 9 12:32:18 2017 us=453406 mtu_test = 0
Mon Oct 9 12:32:18 2017 us=453436 mlock = DISABLED
Mon Oct 9 12:32:18 2017 us=453464 keepalive_ping = 55
Mon Oct 9 12:32:18 2017 us=453496 keepalive_timeout = 180
Mon Oct 9 12:32:18 2017 us=453528 inactivity_timeout = 0
Mon Oct 9 12:32:18 2017 us=453560 ping_send_timeout = 55
Mon Oct 9 12:32:18 2017 us=453590 ping_rec_timeout = 360
Mon Oct 9 12:32:18 2017 us=453620 ping_rec_timeout_action = 2
Mon Oct 9 12:32:18 2017 us=453650 ping_timer_remote = DISABLED
Mon Oct 9 12:32:18 2017 us=453690 remap_sigusr1 = 0
Mon Oct 9 12:32:18 2017 us=453724 persist_tun = DISABLED
Mon Oct 9 12:32:18 2017 us=453757 persist_local_ip = DISABLED
Mon Oct 9 12:32:18 2017 us=453789 persist_remote_ip = DISABLED
Mon Oct 9 12:32:18 2017 us=453849 persist_key = DISABLED
Mon Oct 9 12:32:18 2017 us=453883 passtos = DISABLED
Mon Oct 9 12:32:18 2017 us=453912 resolve_retry_seconds = 1000000000
Mon Oct 9 12:32:18 2017 us=453937 resolve_in_advance = DISABLED
Mon Oct 9 12:32:18 2017 us=453974 username = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=457950 groupname = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458015 chroot_dir = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458033 cd_dir = '/etc/openvpn'
Mon Oct 9 12:32:18 2017 us=458045 writepid = '/run/openvpn/srv_cdu.pid'
Mon Oct 9 12:32:18 2017 us=458058 up_script = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458070 down_script = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458083 down_pre = DISABLED
Mon Oct 9 12:32:18 2017 us=458096 up_restart = DISABLED
Mon Oct 9 12:32:18 2017 us=458108 up_delay = DISABLED
Mon Oct 9 12:32:18 2017 us=458118 daemon = ENABLED
Mon Oct 9 12:32:18 2017 us=458128 inetd = 0
Mon Oct 9 12:32:18 2017 us=458141 log = ENABLED
Mon Oct 9 12:32:18 2017 us=458152 suppress_timestamps = DISABLED
Mon Oct 9 12:32:18 2017 us=458163 machine_readable_output = DISABLED
Mon Oct 9 12:32:18 2017 us=458175 nice = 0
Mon Oct 9 12:32:18 2017 us=458186 verbosity = 4
Mon Oct 9 12:32:18 2017 us=458198 mute = 0
Mon Oct 9 12:32:18 2017 us=458210 gremlin = 0
Mon Oct 9 12:32:18 2017 us=458222 status_file = '/run/openvpn/srv_cdu.status'
Mon Oct 9 12:32:18 2017 us=458234 status_file_version = 1
Mon Oct 9 12:32:18 2017 us=458246 status_file_update_freq = 60
Mon Oct 9 12:32:18 2017 us=458258 occ = ENABLED
Mon Oct 9 12:32:18 2017 us=458269 rcvbuf = 0
Mon Oct 9 12:32:18 2017 us=458280 sndbuf = 0
Mon Oct 9 12:32:18 2017 us=458292 mark = 0
Mon Oct 9 12:32:18 2017 us=458303 sockflags = 0
Mon Oct 9 12:32:18 2017 us=458313 fast_io = DISABLED
Mon Oct 9 12:32:18 2017 us=458323 comp.alg = 2
Mon Oct 9 12:32:18 2017 us=458334 comp.flags = 0
Mon Oct 9 12:32:18 2017 us=458346 route_script = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458357 route_default_gateway = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458368 route_default_metric = 0
Mon Oct 9 12:32:18 2017 us=458377 route_noexec = DISABLED
Mon Oct 9 12:32:18 2017 us=458386 route_delay = 0
Mon Oct 9 12:32:18 2017 us=458396 route_delay_window = 30
Mon Oct 9 12:32:18 2017 us=458405 route_delay_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=458415 route_nopull = DISABLED
Mon Oct 9 12:32:18 2017 us=458424 route_gateway_via_dhcp = DISABLED
Mon Oct 9 12:32:18 2017 us=458434 allow_pull_fqdn = DISABLED
Mon Oct 9 12:32:18 2017 us=458447 route 172.27.0.0/255.255.0.0/default (not set)/default (not set)
Mon Oct 9 12:32:18 2017 us=458457 management_addr = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458467 management_port = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458477 management_user_pass = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458487 management_log_history_cache = 250
Mon Oct 9 12:32:18 2017 us=458496 management_echo_buffer_size = 100
Mon Oct 9 12:32:18 2017 us=458506 management_write_peer_info_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458514 management_client_user = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458523 management_client_group = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458533 management_flags = 0
Mon Oct 9 12:32:18 2017 us=458544 shared_secret_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458555 key_direction = 1
Mon Oct 9 12:32:18 2017 us=458564 ciphername = 'BF-CBC'
Mon Oct 9 12:32:18 2017 us=458574 ncp_enabled = ENABLED
Mon Oct 9 12:32:18 2017 us=458584 ncp_ciphers = 'AES-256-GCM:AES-128-GCM'
Mon Oct 9 12:32:18 2017 us=458594 authname = 'SHA1'
Mon Oct 9 12:32:18 2017 us=458605 prng_hash = 'SHA1'
Mon Oct 9 12:32:18 2017 us=458617 prng_nonce_secret_len = 16
Mon Oct 9 12:32:18 2017 us=458627 keysize = 0
Mon Oct 9 12:32:18 2017 us=458639 engine = DISABLED
Mon Oct 9 12:32:18 2017 us=458649 replay = ENABLED
Mon Oct 9 12:32:18 2017 us=458661 mute_replay_warnings = DISABLED
Mon Oct 9 12:32:18 2017 us=458673 replay_window = 64
Mon Oct 9 12:32:18 2017 us=458685 replay_time = 15
Mon Oct 9 12:32:18 2017 us=458697 packet_id_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458709 use_iv = ENABLED
Mon Oct 9 12:32:18 2017 us=458718 test_crypto = DISABLED
Mon Oct 9 12:32:18 2017 us=458741 tls_server = ENABLED
Mon Oct 9 12:32:18 2017 us=458754 tls_client = DISABLED
Mon Oct 9 12:32:18 2017 us=458763 key_method = 2
Mon Oct 9 12:32:18 2017 us=458774 ca_file = '/etc/openvpn/server/ca.crt'
Mon Oct 9 12:32:18 2017 us=458784 ca_path = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458793 dh_file = '/etc/openvpn/server/dh.pem'
Mon Oct 9 12:32:18 2017 us=458803 cert_file = '/etc/openvpn/server/srv_cdu.crt'
Mon Oct 9 12:32:18 2017 us=458813 extra_certs_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458824 priv_key_file = '/etc/openvpn/server/srv_cdu.key'
Mon Oct 9 12:32:18 2017 us=458835 pkcs12_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458845 cipher_list = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458856 tls_verify = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458867 tls_export_cert = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458878 verify_x509_type = 0
Mon Oct 9 12:32:18 2017 us=458888 verify_x509_name = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458899 crl_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=458908 ns_cert_type = 0
Mon Oct 9 12:32:18 2017 us=458917 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458926 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458936 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458945 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458953 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458962 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458971 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458980 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458989 remote_cert_ku = 0
Mon Oct 9 12:32:18 2017 us=458998 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459007 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459015 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459025 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459034 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459043 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459052 remote_cert_ku[i] = 0
Mon Oct 9 12:32:18 2017 us=459060 remote_cert_eku = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=459069 ssl_flags = 4
Mon Oct 9 12:32:18 2017 us=459078 tls_timeout = 2
Mon Oct 9 12:32:18 2017 us=459086 renegotiate_bytes = -1
Mon Oct 9 12:32:18 2017 us=459095 renegotiate_packets = 0
Mon Oct 9 12:32:18 2017 us=459104 renegotiate_seconds = 3600
Mon Oct 9 12:32:18 2017 us=459113 handshake_window = 60
Mon Oct 9 12:32:18 2017 us=459121 transition_window = 3600
Mon Oct 9 12:32:18 2017 us=459130 single_session = DISABLED
Mon Oct 9 12:32:18 2017 us=459139 push_peer_info = DISABLED
Mon Oct 9 12:32:18 2017 us=459148 tls_exit = DISABLED
Mon Oct 9 12:32:18 2017 us=459157 tls_auth_file = '/etc/openvpn/server/ta.key'
Mon Oct 9 12:32:18 2017 us=459175 tls_crypt_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=459187 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459196 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459205 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459214 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459222 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459231 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459240 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459249 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459258 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459267 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459276 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459284 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459293 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459302 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459310 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459319 pkcs11_protected_authentication = DISABLED
Mon Oct 9 12:32:18 2017 us=459332 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459342 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459351 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459360 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459369 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459378 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459387 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459396 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459405 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459414 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459423 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459432 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459441 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459450 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459459 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459468 pkcs11_private_mode = 00000000
Mon Oct 9 12:32:18 2017 us=459477 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459485 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459494 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459502 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459511 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459520 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459529 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459538 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459547 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459556 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459565 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459573 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459582 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459591 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459599 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459608 pkcs11_cert_private = DISABLED
Mon Oct 9 12:32:18 2017 us=459617 pkcs11_pin_cache_period = -1
Mon Oct 9 12:32:18 2017 us=459626 pkcs11_id = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=459635 pkcs11_id_management = DISABLED
Mon Oct 9 12:32:18 2017 us=459646 server_network = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=459656 server_netmask = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=459667 server_network_ipv6 = ::
Mon Oct 9 12:32:18 2017 us=459677 server_netbits_ipv6 = 0
Mon Oct 9 12:32:18 2017 us=459687 server_bridge_ip = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=459696 server_bridge_netmask = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=459706 server_bridge_pool_start = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=459716 server_bridge_pool_end = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=459726 push_entry = 'route 172.27.224.1'
Mon Oct 9 12:32:18 2017 us=459735 push_entry = 'route 172.28.0.0 255.255.0.0'
Mon Oct 9 12:32:18 2017 us=459744 push_entry = 'dhcp-option DNS 172.27.224.1'
Mon Oct 9 12:32:18 2017 us=459753 push_entry = 'dhcp-option DOMAIN cdu.vpn.aksignal.cz'
Mon Oct 9 12:32:18 2017 us=459762 push_entry = 'dhcp-option NTP 172.27.224.1'
Mon Oct 9 12:32:18 2017 us=459771 push_entry = 'ping 55'
Mon Oct 9 12:32:18 2017 us=459780 push_entry = 'ping-restart 180'
Mon Oct 9 12:32:18 2017 us=459789 ifconfig_pool_defined = ENABLED
Mon Oct 9 12:32:18 2017 us=459799 ifconfig_pool_start = 172.27.224.2
Mon Oct 9 12:32:18 2017 us=459809 ifconfig_pool_end = 172.27.255.254
Mon Oct 9 12:32:18 2017 us=459818 ifconfig_pool_netmask = 255.255.224.0
Mon Oct 9 12:32:18 2017 us=459827 ifconfig_pool_persist_filename = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=459836 ifconfig_pool_persist_refresh_freq = 600
Mon Oct 9 12:32:18 2017 us=459845 ifconfig_ipv6_pool_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=459855 ifconfig_ipv6_pool_base = ::
Mon Oct 9 12:32:18 2017 us=459864 ifconfig_ipv6_pool_netbits = 0
Mon Oct 9 12:32:18 2017 us=459877 n_bcast_buf = 256
Mon Oct 9 12:32:18 2017 us=459887 tcp_queue_limit = 64
Mon Oct 9 12:32:18 2017 us=459896 real_hash_size = 256
Mon Oct 9 12:32:18 2017 us=459904 virtual_hash_size = 256
Mon Oct 9 12:32:18 2017 us=459914 client_connect_script = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=459923 learn_address_script = '/etc/openvpn/server/learn-address'
Mon Oct 9 12:32:18 2017 us=459932 client_disconnect_script = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=459940 client_config_dir = '/etc/openvpn/server/ccd'
Mon Oct 9 12:32:18 2017 us=459949 ccd_exclusive = DISABLED
Mon Oct 9 12:32:18 2017 us=459958 tmp_dir = '/tmp'
Mon Oct 9 12:32:18 2017 us=459967 push_ifconfig_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=460907 push_ifconfig_local = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=460926 push_ifconfig_remote_netmask = 0.0.0.0
Mon Oct 9 12:32:18 2017 us=460937 push_ifconfig_ipv6_defined = DISABLED
Mon Oct 9 12:32:18 2017 us=460949 push_ifconfig_ipv6_local = ::/0
Mon Oct 9 12:32:18 2017 us=460959 push_ifconfig_ipv6_remote = ::
Mon Oct 9 12:32:18 2017 us=460970 enable_c2c = DISABLED
Mon Oct 9 12:32:18 2017 us=460980 duplicate_cn = DISABLED
Mon Oct 9 12:32:18 2017 us=460990 cf_max = 0
Mon Oct 9 12:32:18 2017 us=460999 cf_per = 0
Mon Oct 9 12:32:18 2017 us=461009 max_clients = 1024
Mon Oct 9 12:32:18 2017 us=461019 max_routes_per_client = 256
Mon Oct 9 12:32:18 2017 us=461029 auth_user_pass_verify_script = '/etc/openvpn/server/user-pass-verify'
Mon Oct 9 12:32:18 2017 us=461039 auth_user_pass_verify_script_via_file = DISABLED
Mon Oct 9 12:32:18 2017 us=461049 auth_token_generate = DISABLED
Mon Oct 9 12:32:18 2017 us=461059 auth_token_lifetime = 0
Mon Oct 9 12:32:18 2017 us=461069 port_share_host = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=461078 port_share_port = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=461088 client = DISABLED
Mon Oct 9 12:32:18 2017 us=461098 pull = DISABLED
Mon Oct 9 12:32:18 2017 us=461108 auth_user_pass_file = '[UNDEF]'
Mon Oct 9 12:32:18 2017 us=461121 OpenVPN 2.4.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Jun 22 2017
Mon Oct 9 12:32:18 2017 us=461143 library versions: OpenSSL 1.0.2l 25 May 2017, LZO 2.08
Mon Oct 9 12:32:18 2017 us=472951 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mon Oct 9 12:32:18 2017 us=476944 Diffie-Hellman initialized with 2048 bit key
Mon Oct 9 12:32:18 2017 us=477569 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Oct 9 12:32:18 2017 us=485266 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Oct 9 12:32:18 2017 us=485357 TLS-Auth MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:32:18 2017 us=485876 ROUTE_GATEWAY 193.150.13.1/255.255.255.0 IFACE=eth0 HWADDR=a6:e9:7a:be:f5:02
Mon Oct 9 12:32:18 2017 us=485991 OpenVPN ROUTE: OpenVPN needs a gateway parameter for a --route option and no default was specified by either --route-gateway or --ifconfig options
Mon Oct 9 12:32:18 2017 us=486096 OpenVPN ROUTE: failed to parse/resolve route for host/network: 172.27.0.0
Mon Oct 9 12:32:18 2017 us=487156 TUN/TAP device tun1 opened
Mon Oct 9 12:32:18 2017 us=487305 TUN/TAP TX queue length set to 100
Mon Oct 9 12:32:18 2017 us=487392 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Mon Oct 9 12:32:18 2017 us=501713 /sbin/ip link set dev tun1 up mtu 1500
Mon Oct 9 12:32:18 2017 us=519657 /sbin/ip addr add dev tun1 172.27.224.1/16 broadcast 172.27.255.255
Mon Oct 9 12:32:18 2017 us=531904 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:32:18 2017 us=531963 Could not determine IPv4/IPv6 protocol. Using AF_INET
Mon Oct 9 12:32:18 2017 us=532039 Socket Buffers: R=[212992->212992] S=[212992->212992]
Mon Oct 9 12:32:18 2017 us=532072 UDPv4 link local (bound): [AF_INET][undef]:11194
Mon Oct 9 12:32:18 2017 us=532088 UDPv4 link remote: [AF_UNSPEC]
Mon Oct 9 12:32:18 2017 us=532116 MULTI: multi_init called, r=256 v=256
Mon Oct 9 12:32:18 2017 us=532322 IFCONFIG POOL: base=172.27.224.2 size=8189, ipv6=0
Mon Oct 9 12:32:18 2017 us=532399 Initialization Sequence Completed
Mon Oct 9 12:34:25 2017 us=502404 MULTI: multi_create_instance called
Mon Oct 9 12:34:25 2017 us=502542 62.141.29.83:37918 Re-using SSL/TLS context
Mon Oct 9 12:34:25 2017 us=502569 62.141.29.83:37918 LZO compression initializing
Mon Oct 9 12:34:25 2017 us=502745 62.141.29.83:37918 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:25 2017 us=502768 62.141.29.83:37918 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:25 2017 us=502821 62.141.29.83:37918 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:25 2017 us=502835 62.141.29.83:37918 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:25 2017 us=502881 62.141.29.83:37918 TLS: Initial packet from [AF_INET]62.141.29.83:37918, sid=daa17a0f 2a9bd379
Mon Oct 9 12:34:26 2017 us=97553 MULTI: multi_create_instance called
Mon Oct 9 12:34:26 2017 us=97657 37.48.34.217:63472 Re-using SSL/TLS context
Mon Oct 9 12:34:26 2017 us=97681 37.48.34.217:63472 LZO compression initializing
Mon Oct 9 12:34:26 2017 us=97796 37.48.34.217:63472 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:26 2017 us=97813 37.48.34.217:63472 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:26 2017 us=97852 37.48.34.217:63472 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:26 2017 us=97862 37.48.34.217:63472 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:26 2017 us=97900 37.48.34.217:63472 TLS: Initial packet from [AF_INET]37.48.34.217:63472, sid=9657abcc a38961ea
Mon Oct 9 12:34:30 2017 us=59230 MULTI: multi_create_instance called
Mon Oct 9 12:34:30 2017 us=59340 62.141.19.62:47444 Re-using SSL/TLS context
Mon Oct 9 12:34:30 2017 us=59365 62.141.19.62:47444 LZO compression initializing
Mon Oct 9 12:34:30 2017 us=59504 62.141.19.62:47444 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:30 2017 us=59524 62.141.19.62:47444 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:30 2017 us=59564 62.141.19.62:47444 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:30 2017 us=59586 62.141.19.62:47444 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:30 2017 us=59627 62.141.19.62:47444 TLS: Initial packet from [AF_INET]62.141.19.62:47444, sid=dc70fc28 a485c939
Mon Oct 9 12:34:32 2017 us=196980 MULTI: multi_create_instance called
Mon Oct 9 12:34:32 2017 us=197294 62.141.27.26:52445 Re-using SSL/TLS context
Mon Oct 9 12:34:32 2017 us=197435 62.141.27.26:52445 LZO compression initializing
Mon Oct 9 12:34:32 2017 us=197708 62.141.27.26:52445 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:32 2017 us=197807 62.141.27.26:52445 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:32 2017 us=197955 62.141.27.26:52445 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:32 2017 us=198051 62.141.27.26:52445 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:32 2017 us=198201 62.141.27.26:52445 TLS: Initial packet from [AF_INET]62.141.27.26:52445, sid=23ed7168 7dfdc44c
Mon Oct 9 12:34:32 2017 us=599022 MULTI: multi_create_instance called
Mon Oct 9 12:34:32 2017 us=599501 195.91.127.12:48431 Re-using SSL/TLS context
Mon Oct 9 12:34:32 2017 us=599621 195.91.127.12:48431 LZO compression initializing
Mon Oct 9 12:34:32 2017 us=599817 195.91.127.12:48431 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:32 2017 us=599933 195.91.127.12:48431 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:32 2017 us=600097 195.91.127.12:48431 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:32 2017 us=600184 195.91.127.12:48431 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:32 2017 us=600330 195.91.127.12:48431 TLS: Initial packet from [AF_INET]195.91.127.12:48431, sid=e4a5dd3e 126112a0
Mon Oct 9 12:34:32 2017 us=647534 MULTI: multi_create_instance called
Mon Oct 9 12:34:32 2017 us=647836 160.218.189.162:53538 Re-using SSL/TLS context
Mon Oct 9 12:34:32 2017 us=647942 160.218.189.162:53538 LZO compression initializing
Mon Oct 9 12:34:32 2017 us=648188 160.218.189.162:53538 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:32 2017 us=648290 160.218.189.162:53538 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:32 2017 us=648412 160.218.189.162:53538 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:32 2017 us=648530 160.218.189.162:53538 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:32 2017 us=648677 160.218.189.162:53538 TLS: Initial packet from [AF_INET]160.218.189.162:53538, sid=44cfd0f6 98db0df4
Mon Oct 9 12:34:33 2017 us=631434 MULTI: multi_create_instance called
Mon Oct 9 12:34:33 2017 us=631757 37.188.144.58:4003 Re-using SSL/TLS context
Mon Oct 9 12:34:33 2017 us=631937 37.188.144.58:4003 LZO compression initializing
Mon Oct 9 12:34:33 2017 us=632237 37.188.144.58:4003 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:33 2017 us=632372 37.188.144.58:4003 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:33 2017 us=632536 37.188.144.58:4003 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:33 2017 us=632669 37.188.144.58:4003 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:33 2017 us=632877 37.188.144.58:4003 TLS: Initial packet from [AF_INET]37.188.144.58:4003, sid=38379af5 42383138
Mon Oct 9 12:34:34 2017 us=719583 37.48.34.217:63472 VERIFY OK: depth=1, CN=prchal
Mon Oct 9 12:34:34 2017 us=720154 37.48.34.217:63472 VERIFY OK: depth=0, CN=cli_cdu
Mon Oct 9 12:34:34 2017 us=723679 160.218.189.162:53538 VERIFY OK: depth=1, CN=prchal
Mon Oct 9 12:34:34 2017 us=724215 160.218.189.162:53538 VERIFY OK: depth=0, CN=cli_cdu
Mon Oct 9 12:34:34 2017 us=808038 160.218.189.162:53538 peer info: IV_VER=2.4.0
Mon Oct 9 12:34:34 2017 us=808346 160.218.189.162:53538 peer info: IV_PLAT=linux
Mon Oct 9 12:34:34 2017 us=808428 160.218.189.162:53538 peer info: IV_PROTO=2
Mon Oct 9 12:34:34 2017 us=808508 160.218.189.162:53538 peer info: IV_NCP=2
Mon Oct 9 12:34:34 2017 us=808608 160.218.189.162:53538 peer info: IV_LZ4=1
Mon Oct 9 12:34:34 2017 us=808677 160.218.189.162:53538 peer info: IV_LZ4v2=1
Mon Oct 9 12:34:34 2017 us=808772 160.218.189.162:53538 peer info: IV_LZO=1
Mon Oct 9 12:34:34 2017 us=808850 160.218.189.162:53538 peer info: IV_COMP_STUB=1
Mon Oct 9 12:34:34 2017 us=808924 160.218.189.162:53538 peer info: IV_COMP_STUBv2=1
Mon Oct 9 12:34:34 2017 us=809028 160.218.189.162:53538 peer info: IV_TCPNL=1
Mon Oct 9 12:34:34 2017 us=811766 160.218.189.162:53538 TLS: Username/Password authentication succeeded for username 'BRPRE7P075C' [CN SET]
Mon Oct 9 12:34:34 2017 us=811856 160.218.189.162:53538 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1542', remote='link-mtu 1550'
Mon Oct 9 12:34:34 2017 us=811889 160.218.189.162:53538 WARNING: 'cipher' is used inconsistently, local='cipher BF-CBC', remote='cipher AES-256-GCM'
Mon Oct 9 12:34:34 2017 us=811907 160.218.189.162:53538 WARNING: 'auth' is used inconsistently, local='auth SHA1', remote='auth [null-digest]'
Mon Oct 9 12:34:34 2017 us=811927 160.218.189.162:53538 WARNING: 'keysize' is used inconsistently, local='keysize 128', remote='keysize 256'
Mon Oct 9 12:34:34 2017 us=887765 160.218.189.162:53538 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Mon Oct 9 12:34:34 2017 us=887865 160.218.189.162:53538 [BRPRE7P075C] Peer Connection Initiated with [AF_INET]160.218.189.162:53538
Mon Oct 9 12:34:34 2017 us=888072 BRPRE7P075C/160.218.189.162:53538 MULTI_sva: pool returned IPv4=172.27.224.2, IPv6=(Not enabled)
/etc/openvpn/server/learn-address: line 72: kill: (627) - Operation not permitted
Mon Oct 9 12:34:34 2017 us=906100 BRPRE7P075C/160.218.189.162:53538 MULTI: Learn: 172.27.224.2 -> BRPRE7P075C/160.218.189.162:53538
Mon Oct 9 12:34:34 2017 us=906154 BRPRE7P075C/160.218.189.162:53538 MULTI: primary virtual IP for BRPRE7P075C/160.218.189.162:53538: 172.27.224.2
Mon Oct 9 12:34:35 2017 us=252261 MULTI: multi_create_instance called
Mon Oct 9 12:34:35 2017 us=252365 195.91.112.219:58134 Re-using SSL/TLS context
Mon Oct 9 12:34:35 2017 us=252391 195.91.112.219:58134 LZO compression initializing
Mon Oct 9 12:34:35 2017 us=252519 195.91.112.219:58134 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:35 2017 us=252537 195.91.112.219:58134 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:35 2017 us=252581 195.91.112.219:58134 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:35 2017 us=252593 195.91.112.219:58134 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:35 2017 us=252649 195.91.112.219:58134 TLS: Initial packet from [AF_INET]195.91.112.219:58134, sid=def3a922 d4061025
Mon Oct 9 12:34:36 2017 us=156103 BRPRE7P075C/160.218.189.162:53538 PUSH: Received control message: 'PUSH_REQUEST'
Mon Oct 9 12:34:36 2017 us=156449 BRPRE7P075C/160.218.189.162:53538 SENT CONTROL [BRPRE7P075C]: 'PUSH_REPLY,route 172.27.224.1,route 172.28.0.0 255.255.0.0,dhcp-option DNS 172.27.224.1,dhcp-option DOMAIN cdu.vpn.aksignal.cz,dhcp-option NTP 172.27.224.1,ping 55,ping-restart 180,ifconfig 172.27.224.2 255.255.224.0,peer-id 5,cipher AES-256-GCM' (status=1)
Mon Oct 9 12:34:36 2017 us=156593 BRPRE7P075C/160.218.189.162:53538 Data Channel MTU parms [ L:1550 D:1450 EF:50 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:36 2017 us=156796 BRPRE7P075C/160.218.189.162:53538 Data Channel Encrypt: Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Oct 9 12:34:36 2017 us=156934 BRPRE7P075C/160.218.189.162:53538 Data Channel Decrypt: Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Oct 9 12:34:36 2017 us=599174 37.48.34.217:63472 peer info: IV_VER=2.3.4
Mon Oct 9 12:34:36 2017 us=599456 37.48.34.217:63472 peer info: IV_PLAT=linux
Mon Oct 9 12:34:36 2017 us=601841 37.48.34.217:63472 TLS: Username/Password authentication succeeded for username 'jhmd-cernovice-c' [CN SET]
Mon Oct 9 12:34:36 2017 us=602058 37.48.34.217:63472 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Oct 9 12:34:36 2017 us=602078 37.48.34.217:63472 WARNING: INSECURE cipher with block size less than 128 bit (64 bit). This allows attacks like SWEET32. Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Mon Oct 9 12:34:36 2017 us=602091 37.48.34.217:63472 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Oct 9 12:34:36 2017 us=602145 37.48.34.217:63472 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Oct 9 12:34:36 2017 us=602155 37.48.34.217:63472 WARNING: INSECURE cipher with block size less than 128 bit (64 bit). This allows attacks like SWEET32. Mitigate by using a --cipher with a larger block size (e.g. AES-256-CBC).
Mon Oct 9 12:34:36 2017 us=602167 37.48.34.217:63472 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Oct 9 12:34:36 2017 us=602177 37.48.34.217:63472 WARNING: cipher with small block size in use, reducing reneg-bytes to 64MB to mitigate SWEET32 attacks.
Mon Oct 9 12:34:36 2017 us=701204 MULTI: multi_create_instance called
Mon Oct 9 12:34:36 2017 us=701317 195.91.112.116:42216 Re-using SSL/TLS context
Mon Oct 9 12:34:36 2017 us=701336 195.91.112.116:42216 LZO compression initializing
Mon Oct 9 12:34:36 2017 us=701467 195.91.112.116:42216 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:36 2017 us=701485 195.91.112.116:42216 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:36 2017 us=701524 195.91.112.116:42216 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:36 2017 us=701535 195.91.112.116:42216 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:36 2017 us=701586 195.91.112.116:42216 TLS: Initial packet from [AF_INET]195.91.112.116:42216, sid=b84cc5ca a62c0a6b
Mon Oct 9 12:34:37 2017 us=126756 MULTI: multi_create_instance called
Mon Oct 9 12:34:37 2017 us=127075 37.48.7.85:58626 Re-using SSL/TLS context
Mon Oct 9 12:34:37 2017 us=127210 37.48.7.85:58626 LZO compression initializing
Mon Oct 9 12:34:37 2017 us=127436 37.48.7.85:58626 Control Channel MTU parms [ L:1622 D:1184 EF:66 EB:0 ET:0 EL:3 ]
Mon Oct 9 12:34:37 2017 us=127562 37.48.7.85:58626 Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
Mon Oct 9 12:34:37 2017 us=127722 37.48.7.85:58626 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Mon Oct 9 12:34:37 2017 us=127832 37.48.7.85:58626 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Mon Oct 9 12:34:37 2017 us=128003 37.48.7.85:58626 TLS: Initial packet from [AF_INET]37.48.7.85:58626, sid=59c435d2 cc4218f6
Mon Oct 9 12:34:37 2017 us=340446 37.48.34.217:63472 Control Channel: TLSv1, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-SHA, 2048 bit RSA
Mon Oct 9 12:34:37 2017 us=340748 37.48.34.217:63472 [jhmd-cernovice-c] Peer Connection Initiated with [AF_INET]37.48.34.217:63472
Mon Oct 9 12:34:37 2017 us=341001 jhmd-cernovice-c/37.48.34.217:63472 MULTI_sva: pool returned IPv4=172.27.224.3, IPv6=(Not enabled)
/etc/openvpn/server/learn-address: line 72: kill: (627) - Operation not permitted
Mon Oct 9 12:34:37 2017 us=358178 jhmd-cernovice-c/37.48.34.217:63472 MULTI: Learn: 172.27.224.3 -> jhmd-cernovice-c/37.48.34.217:63472
Mon Oct 9 12:34:37 2017 us=358223 jhmd-cernovice-c/37.48.34.217:63472 MULTI: primary virtual IP for jhmd-cernovice-c/37.48.34.217:63472: 172.27.224.3
Mon Oct 9 12:34:37 2017 us=653390 37.188.144.58:4003 VERIFY OK: depth=1, CN=prchal
Mon Oct 9 12:34:37 2017 us=653930 37.188.144.58:4003 VERIFY OK: depth=0, CN=cli_cdu
Mon Oct 9 12:34:38 2017 us=434307 37.188.144.58:4003 peer info: IV_VER=2.3.4

TiTex

you should also check apparmor , not sure but i think it's enabled by default in debian 9

jiriprchal

I'm not sure but I think it's disabled. It's not installed, running, not in kernel command line, aa-status not installed.

TiTex

openvpn is started as a service or from command line ?
check as which user/group is started either way , although if started from command line should run as the user you're logged in.

ps aux | grep openvpn

jiriprchal

As service, uid 0, gid 0.
But I tried it from command line as root and it worked.
So where is the difference?

TinCanTech

jiriprchal wrote

kill -HUP $(cat /run/dnsmasq/dnsmasq.pid)

Not sure this will make any difference due to the error of permission but try this:

/bin/kill -HUP $(cat /run/dnsmasq/dnsmasq.pid)

jiriprchal

It doesn't help.
kill: (627): Operation not permitted

TinCanTech

What is the complete script ?

jiriprchal

#!/bin/bash
# openvpn learn-address script to manage a hosts-like file
# - intended to allow dnsmasq to resolve openvpn clients
#   addn-hosts=/etc/hosts.openvpn-clients
# - written for openwrt (busybox), but should work most anywhere
#
# Changelog
# 2006-10-13 BDL original

# replace with a sub-domain of your domain, use a sub-domain to prevent VPN clients from stealing existing names
DOMAIN="cdu.vpn.aksignal.cz"
HOSTS="/run/openvpn/srv_cdu.hosts"
CONF="/etc/openvpn/srv_cdu.conf"
LOCKFILE="/var/lock/$(basename $HOSTS).lock"

action="$1"
ip="$2"
cn="$3"
fqdn="$cn.$DOMAIN"

echo -e "$(date +%T)\t$action\t$ip\t$cn" >> /run/openvpn/learn-address.log

if [ ! -e $HOSTS ]; then
	: > $HOSTS
fi

case "$action" in
	add|update)
		if [ -z "$ip" -o -z "$cn" ]; then
			echo "$0: IP and/or Common Name not provided" >&2
			exit 0
		fi
	;;
	delete)
		if [ -z "$ip" ]; then
			echo "$0: IP not provided" >&2
			exit 0
		fi
	;;
	*)
		echo "$0: unknown operation [$1]" >&2
		exit 1
	;;
esac

# check ip
if [[ ! $ip =~ ^[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}$ ]]; then
	exit 0
fi
l_ip=$(echo $ip | awk -F"." '{printf ("%.0f", $1 * 2^24 + $2 * 2^16 + $3 * 2^8 + $4)}')
l_pool_begin=$(awk '/^ifconfig-pool/ {print $2}' $CONF | awk -F"." '{printf ("%.0f", $1 * 2^24 + $2 * 2^16 + $3 * 2^8 + $4)}')
l_pool_end=$(awk '/^ifconfig-pool/ {print $3}' $CONF | awk -F"." '{printf ("%.0f", $1 * 2^24 + $2 * 2^16 + $3 * 2^8 + $4)}')
if [ $l_ip -lt $l_pool_begin ] || [ $l_ip -gt $l_pool_end ]; then
	exit 0
fi

# serialise concurrent accesses
(
	flock 200
	case "$action" in
		add | update )
			sed -i "/\<$ip\>\|\<$fqdn\>/d" "$HOSTS"
			echo -e "$ip\t$fqdn" >> "$HOSTS"
		;;
		delete )
			sed -i "/\<$ip\>/d" "$HOSTS"
		;;
	esac
) 200> $LOCKFILE

# signal dnsmasq to reread hosts file
kill -HUP $(cat /run/dnsmasq/dnsmasq.pid)

#change for www
/bin/chmod a+r /run/openvpn/srv_cdu.status

jiriprchal

Hi all,
I tried upgrade to 2.4.3 Debian backport but no success.
Definitely, if it's executed from command line it works. As a service or by init.d script (probably as service too) don't work.

TinCanTech

Perhaps there is something in the startup script you are using ?

jiriprchal

Startup script is Debian, it uses start-stop-daemon. It's only the difference.
Here is full script:

#!/bin/sh -e

### BEGIN INIT INFO
# Provides:          openvpn
# Required-Start:    $network $remote_fs $syslog
# Required-Stop:     $network $remote_fs $syslog
# Should-Start:      network-manager
# Should-Stop:       network-manager
# X-Start-Before:    $x-display-manager gdm kdm xdm wdm ldm sdm nodm
# X-Interactive:     true
# Default-Start:     2 3 4 5
# Default-Stop:      0 1 6
# Short-Description: Openvpn VPN service
# Description: This script will start OpenVPN tunnels as specified
#              in /etc/default/openvpn and /etc/openvpn/*.conf
### END INIT INFO

# Original version by Robert Leslie
# <rob@mars.org>, edited by iwj and cs
# Modified for openvpn by Alberto Gonzalez Iniesta <agi@inittab.org>
# Modified for restarting / starting / stopping single tunnels by Richard Mueller <mueller@teamix.net>

. /lib/lsb/init-functions

test $DEBIAN_SCRIPT_DEBUG && set -v -x

DAEMON=/usr/sbin/openvpn
DESC="virtual private network daemon"
CONFIG_DIR=/etc/openvpn
test -x $DAEMON || exit 0
test -d $CONFIG_DIR || exit 0

# Source defaults file; edit that file to configure this script.
AUTOSTART="all"
STATUSREFRESH=10
OMIT_SENDSIGS=0
if test -e /etc/default/openvpn ; then
  . /etc/default/openvpn
fi

start_vpn () {
    if grep -q '^[	 ]*daemon' $CONFIG_DIR/$NAME.conf ; then
      # daemon already given in config file
      DAEMONARG=
    else
      # need to daemonize
      DAEMONARG="--daemon ovpn-$NAME"
    fi

    if grep -q '^[	 ]*status ' $CONFIG_DIR/$NAME.conf ; then
      # status file already given in config file
      STATUSARG=""
    elif test $STATUSREFRESH -eq 0 ; then
      # default status file disabled in /etc/default/openvpn
      STATUSARG=""
    else
      # prepare default status file
      STATUSARG="--status /run/openvpn/$NAME.status $STATUSREFRESH"
    fi

    # tun using the "subnet" topology confuses the routing code that wrongly
    # emits ICMP redirects for client to client communications
    SAVED_DEFAULT_SEND_REDIRECTS=0
    if grep -q '^[[:space:]]*dev[[:space:]]*tun' $CONFIG_DIR/$NAME.conf && \
       grep -q '^[[:space:]]*topology[[:space:]]*subnet' $CONFIG_DIR/$NAME.conf ; then
        # When using "client-to-client", OpenVPN routes the traffic itself without
        # involving the TUN/TAP interface so no ICMP redirects are sent
        if ! grep -q '^[[:space:]]*client-to-client' $CONFIG_DIR/$NAME.conf ; then
            sysctl -w net.ipv4.conf.all.send_redirects=0 > /dev/null

            # Save the default value for send_redirects before disabling it
            # to make sure the tun device is created with send_redirects disabled
            SAVED_DEFAULT_SEND_REDIRECTS=$(sysctl -n net.ipv4.conf.default.send_redirects)

            if [ "$SAVED_DEFAULT_SEND_REDIRECTS" -ne 0 ]; then
              sysctl -w net.ipv4.conf.default.send_redirects=0 > /dev/null
            fi
        fi
    fi

    log_progress_msg "$NAME"
    STATUS=0

    start-stop-daemon --start --quiet --oknodo \
        --pidfile /run/openvpn/$NAME.pid \
        --exec $DAEMON -- $OPTARGS --writepid /run/openvpn/$NAME.pid \
        $DAEMONARG $STATUSARG --cd $CONFIG_DIR \
        --config $CONFIG_DIR/$NAME.conf || STATUS=1

    [ "$OMIT_SENDSIGS" -ne 1 ] || ln -s /run/openvpn/$NAME.pid /run/sendsigs.omit.d/openvpn.$NAME.pid

    # Set the back the original default value of send_redirects if it was changed
    if [ "$SAVED_DEFAULT_SEND_REDIRECTS" -ne 0 ]; then
      sysctl -w net.ipv4.conf.default.send_redirects=$SAVED_DEFAULT_SEND_REDIRECTS > /dev/null
    fi
}
stop_vpn () {
  start-stop-daemon --stop --quiet --oknodo \
      --pidfile $PIDFILE --exec $DAEMON --retry 10
  if [ "$?" -eq 0 ]; then
    rm -f $PIDFILE
    [ "$OMIT_SENDSIGS" -ne 1 ] || rm -f /run/sendsigs.omit.d/openvpn.$NAME.pid
    rm -f /run/openvpn/$NAME.status 2> /dev/null
  fi
}

case "$1" in
start)
  log_daemon_msg "Starting $DESC"

  # first create /run directory so it's present even
  # when no VPN are autostarted by this script, but later
  # by systemd openvpn@.service
  mkdir -p /run/openvpn

  # autostart VPNs
  if test -z "$2" ; then
    # check if automatic startup is disabled by AUTOSTART=none
    if test "x$AUTOSTART" = "xnone" -o -z "$AUTOSTART" ; then
      log_warning_msg " Autostart disabled."
      exit 0
    fi
    if test -z "$AUTOSTART" -o "x$AUTOSTART" = "xall" ; then
      # all VPNs shall be started automatically
      for CONFIG in `cd $CONFIG_DIR; ls *.conf 2> /dev/null`; do
        NAME=${CONFIG%%.conf}
        start_vpn
      done
    else
      # start only specified VPNs
      for NAME in $AUTOSTART ; do
        if test -e $CONFIG_DIR/$NAME.conf ; then
          start_vpn
        else
          log_failure_msg "No such VPN: $NAME"
          STATUS=1
        fi
      done
    fi
  #start VPNs from command line
  else
    while shift ; do
      [ -z "$1" ] && break
      if test -e $CONFIG_DIR/$1.conf ; then
        NAME=$1
        start_vpn
      else
       log_failure_msg " No such VPN: $1"
       STATUS=1
      fi
    done
  fi
  log_end_msg ${STATUS:-0}

  ;;
stop)
  log_daemon_msg "Stopping $DESC"

  if test -z "$2" ; then
    for PIDFILE in `ls /run/openvpn/*.pid 2> /dev/null`; do
      NAME=`echo $PIDFILE | cut -c14-`
      NAME=${NAME%%.pid}
      stop_vpn
      log_progress_msg "$NAME"
    done
  else
    while shift ; do
      [ -z "$1" ] && break
      if test -e /run/openvpn/$1.pid ; then
        PIDFILE=`ls /run/openvpn/$1.pid 2> /dev/null`
        NAME=`echo $PIDFILE | cut -c14-`
        NAME=${NAME%%.pid}
        stop_vpn
        log_progress_msg "$NAME"
      else
        log_failure_msg " (failure: No such VPN is running: $1)"
      fi
    done
  fi
  log_end_msg 0
  ;;
# Only 'reload' running VPNs. New ones will only start with 'start' or 'restart'.
reload|force-reload)
 log_daemon_msg "Reloading $DESC"
  for PIDFILE in `ls /run/openvpn/*.pid 2> /dev/null`; do
    NAME=`echo $PIDFILE | cut -c14-`
    NAME=${NAME%%.pid}
# If openvpn if running under a different user than root we'll need to restart
    if egrep '^[[:blank:]]*user[[:blank:]]' $CONFIG_DIR/$NAME.conf > /dev/null 2>&1 ; then
      stop_vpn
      start_vpn
      log_progress_msg "(restarted)"
    else
      kill -HUP `cat $PIDFILE` || true
    log_progress_msg "$NAME"
    fi
  done
  log_end_msg 0
  ;;

# Only 'soft-restart' running VPNs. New ones will only start with 'start' or 'restart'.
soft-restart)
 log_daemon_msg "$DESC sending SIGUSR1"
  for PIDFILE in `ls /run/openvpn/*.pid 2> /dev/null`; do
    NAME=`echo $PIDFILE | cut -c14-`
    NAME=${NAME%%.pid}
    kill -USR1 `cat $PIDFILE` || true
    log_progress_msg "$NAME"
  done
  log_end_msg 0
 ;;

restart)
  shift
  $0 stop ${@}
  $0 start ${@}
  ;;
cond-restart)
  log_daemon_msg "Restarting $DESC."
  for PIDFILE in `ls /run/openvpn/*.pid 2> /dev/null`; do
    NAME=`echo $PIDFILE | cut -c14-`
    NAME=${NAME%%.pid}
    stop_vpn
    start_vpn
  done
  log_end_msg 0
  ;;
status)
  GLOBAL_STATUS=0
  if test -z "$2" ; then
    # We want status for all defined VPNs.
    # Returns success if all autostarted VPNs are defined and running
    if test "x$AUTOSTART" = "xnone" ; then
      # Consider it a failure if AUTOSTART=none
      log_warning_msg "No VPN autostarted"
      GLOBAL_STATUS=1
    else
      if ! test -z "$AUTOSTART" -o "x$AUTOSTART" = "xall" ; then
        # Consider it a failure if one of the autostarted VPN is not defined
        for VPN in $AUTOSTART ; do
          if ! test -f $CONFIG_DIR/$VPN.conf ; then
            log_warning_msg "VPN '$VPN' is in AUTOSTART but is not defined"
            GLOBAL_STATUS=1
          fi
        done
      fi
    fi
    for CONFIG in `cd $CONFIG_DIR; ls *.conf 2> /dev/null`; do
      NAME=${CONFIG%%.conf}
      # Is it an autostarted VPN ?
      if test -z "$AUTOSTART" -o "x$AUTOSTART" = "xall" ; then
        AUTOVPN=1
      else
        if test "x$AUTOSTART" = "xnone" ; then
          AUTOVPN=0
        else
          AUTOVPN=0
          for VPN in $AUTOSTART; do
            if test "x$VPN" = "x$NAME" ; then
              AUTOVPN=1
            fi
          done
        fi
      fi
      if test "x$AUTOVPN" = "x1" ; then
        # If it is autostarted, then it contributes to global status
        status_of_proc -p /run/openvpn/${NAME}.pid openvpn "VPN '${NAME}'" || GLOBAL_STATUS=1
      else
        status_of_proc -p /run/openvpn/${NAME}.pid openvpn "VPN '${NAME}' (non autostarted)" || true
      fi
    done
  else
    # We just want status for specified VPNs.
    # Returns success if all specified VPNs are defined and running
    while shift ; do
      [ -z "$1" ] && break
      NAME=$1
      if test -e $CONFIG_DIR/$NAME.conf ; then
        # Config exists
        status_of_proc -p /run/openvpn/${NAME}.pid openvpn "VPN '${NAME}'" || GLOBAL_STATUS=1
      else
        # Config does not exist
        log_warning_msg "VPN '$NAME': missing $CONFIG_DIR/$NAME.conf file !"
        GLOBAL_STATUS=1
      fi
    done
  fi
  exit $GLOBAL_STATUS
  ;;
*)
  echo "Usage: $0 {start|stop|reload|restart|force-reload|cond-restart|soft-restart|status}" >&2
  exit 1
  ;;
esac

exit 0

# vim:set ai sts=2 sw=2 tw=0:

TiTex

jiriprchal wrote It doesn't help.
kill: (627): Operation not permitted

that's a permission issue , are you sure that openvpn doesn't drop root privileges after it is started ?

jiriprchal

Yes, I am. As you can see, not configured to do so, not logged in, checked by ps, checked by echoing uid in script learn-address. Ran from command line OK.

TiTex

so if you start openvpn service with something like

openvpn --config server.conf &

as root everything ok ?
and if you start it as service start openvpn (or systemctl) does stupid things ?

jiriprchal

Absolutely yes.

TiTex

did you check the autogenerated systemctl service file if there's nothing weird in it ? (if it is autogenerated service from an init script)

systemctl status openvpn - will show you the service file and it's filesystem location
systemct cat openvpn - will show you its content.

jiriprchal

Here it is, but I don't see anythink relevant.

root@vps0825:~# systemctl status openvpn
● openvpn.service - OpenVPN service
   Loaded: loaded (/lib/systemd/system/openvpn.service; enabled; vendor preset: enabled)
   Active: active (exited) since Mon 2017-10-16 09:50:47 UTC; 2min 59s ago
  Process: 8452 ExecStart=/bin/true (code=exited, status=0/SUCCESS)
 Main PID: 8452 (code=exited, status=0/SUCCESS)

Oct 16 09:50:47 vps0825 systemd[1]: Starting OpenVPN service...
Oct 16 09:50:47 vps0825 systemd[1]: Started OpenVPN service.
root@vps0825:~# systemctl cat openvpn
# /lib/systemd/system/openvpn.service
# This service is actually a systemd target,
# but we are using a service since targets cannot be reloaded.

[Unit]
Description=OpenVPN service
After=network.target

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/bin/true
ExecReload=/bin/true
WorkingDirectory=/etc/openvpn

[Install]
WantedBy=multi-user.target