Opened 13 years ago

Closed 13 years ago

Last modified 13 years ago

#142 closed Bug / Defect (notabug)

OpenVPN 2.2 executes user-defined "up" script even when server is down

Reported by: exes Owned by:
Priority: major Milestone:
Component: Configuration Version: OpenVPN 2.2.0 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc:

Description

For this test, I changed my user defined script to simply "echo script_up" or "echo script_down" for up/down respectively. Below are my client side logs and both the client and server configurations.

I'm running 2.2.0 on the client side, and 2.1.3 on the server side. Both sides are running Debian Linux 6.

For the following logs, the server side OpenVPN process is not running.

Client Logs:

Thu Jun 2 14:28:22 2011 us=682296 Current Parameter Settings:
Thu Jun 2 14:28:22 2011 us=682416 config = '/etc/openvpn/some_config.conf'
Thu Jun 2 14:28:22 2011 us=682438 mode = 0
Thu Jun 2 14:28:22 2011 us=682455 persist_config = DISABLED
Thu Jun 2 14:28:22 2011 us=682472 persist_mode = 1
Thu Jun 2 14:28:22 2011 us=682487 show_ciphers = DISABLED
Thu Jun 2 14:28:22 2011 us=682503 show_digests = DISABLED
Thu Jun 2 14:28:22 2011 us=682518 show_engines = DISABLED
Thu Jun 2 14:28:22 2011 us=682533 genkey = DISABLED
Thu Jun 2 14:28:22 2011 us=682548 key_pass_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682563 show_tls_ciphers = DISABLED
Thu Jun 2 14:28:22 2011 us=682581 Connection profiles [default]:
Thu Jun 2 14:28:22 2011 us=682597 proto = udp
Thu Jun 2 14:28:22 2011 us=682613 local = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682628 local_port = 0
Thu Jun 2 14:28:22 2011 us=682644 remote = 'hostname.domain.tld'
Thu Jun 2 14:28:22 2011 us=682660 remote_port = 1250
Thu Jun 2 14:28:22 2011 us=682675 remote_float = DISABLED
Thu Jun 2 14:28:22 2011 us=682691 bind_defined = DISABLED
Thu Jun 2 14:28:22 2011 us=682706 bind_local = DISABLED
Thu Jun 2 14:28:22 2011 us=682721 connect_retry_seconds = 5
Thu Jun 2 14:28:22 2011 us=682737 connect_timeout = 10
Thu Jun 2 14:28:22 2011 us=682755 connect_retry_max = 0
Thu Jun 2 14:28:22 2011 us=682781 socks_proxy_server = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682798 socks_proxy_port = 0
Thu Jun 2 14:28:22 2011 us=682813 socks_proxy_retry = DISABLED
Thu Jun 2 14:28:22 2011 us=682831 Connection profiles END
Thu Jun 2 14:28:22 2011 us=682847 remote_random = DISABLED
Thu Jun 2 14:28:22 2011 us=682864 ipchange = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682880 dev = 'tun1'
Thu Jun 2 14:28:22 2011 us=682895 dev_type = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682910 dev_node = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682925 lladdr = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=682941 topology = 1
Thu Jun 2 14:28:22 2011 us=682956 tun_ipv6 = DISABLED
Thu Jun 2 14:28:22 2011 us=682971 ifconfig_local = '192.168.249.163'
Thu Jun 2 14:28:22 2011 us=682986 ifconfig_remote_netmask = '192.168.249.162'
Thu Jun 2 14:28:22 2011 us=683001 ifconfig_noexec = DISABLED
Thu Jun 2 14:28:22 2011 us=683016 ifconfig_nowarn = DISABLED
Thu Jun 2 14:28:22 2011 us=683031 shaper = 0
Thu Jun 2 14:28:22 2011 us=683046 tun_mtu = 1500
Thu Jun 2 14:28:22 2011 us=683061 tun_mtu_defined = ENABLED
Thu Jun 2 14:28:22 2011 us=683076 link_mtu = 1500
Thu Jun 2 14:28:22 2011 us=683091 link_mtu_defined = DISABLED
Thu Jun 2 14:28:22 2011 us=683106 tun_mtu_extra = 0
Thu Jun 2 14:28:22 2011 us=683121 tun_mtu_extra_defined = DISABLED
Thu Jun 2 14:28:22 2011 us=683137 fragment = 0
Thu Jun 2 14:28:22 2011 us=683152 mtu_discover_type = -1
Thu Jun 2 14:28:22 2011 us=683167 mtu_test = 0
Thu Jun 2 14:28:22 2011 us=683181 mlock = DISABLED
Thu Jun 2 14:28:22 2011 us=683197 keepalive_ping = 10
Thu Jun 2 14:28:22 2011 us=683211 keepalive_timeout = 120
Thu Jun 2 14:28:22 2011 us=683226 inactivity_timeout = 0
Thu Jun 2 14:28:22 2011 us=683241 ping_send_timeout = 10
Thu Jun 2 14:28:22 2011 us=683864 ping_rec_timeout = 120
Thu Jun 2 14:28:22 2011 us=683899 ping_rec_timeout_action = 2
Thu Jun 2 14:28:22 2011 us=683929 ping_timer_remote = DISABLED
Thu Jun 2 14:28:22 2011 us=683958 remap_sigusr1 = 0
Thu Jun 2 14:28:22 2011 us=683988 explicit_exit_notification = 0
Thu Jun 2 14:28:22 2011 us=684016 persist_tun = ENABLED
Thu Jun 2 14:28:22 2011 us=684045 persist_local_ip = DISABLED
Thu Jun 2 14:28:22 2011 us=684073 persist_remote_ip = DISABLED
Thu Jun 2 14:28:22 2011 us=684100 persist_key = ENABLED
Thu Jun 2 14:28:22 2011 us=684128 mssfix = 1450
Thu Jun 2 14:28:22 2011 us=684155 passtos = DISABLED
Thu Jun 2 14:28:22 2011 us=684182 resolve_retry_seconds = 1000000000
Thu Jun 2 14:28:22 2011 us=684209 username = 'nobody'
Thu Jun 2 14:28:22 2011 us=684235 groupname = 'nogroup'
Thu Jun 2 14:28:22 2011 us=684265 chroot_dir = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=684302 cd_dir = '/etc/openvpn'
Thu Jun 2 14:28:22 2011 us=684330 writepid = '/var/run/openvpn.some_config.pid'
Thu Jun 2 14:28:22 2011 us=684355 up_script = '/bin/echo script_up'
Thu Jun 2 14:28:22 2011 us=684381 down_script = '/bin/echo script_down'
Thu Jun 2 14:28:22 2011 us=684405 down_pre = DISABLED
Thu Jun 2 14:28:22 2011 us=684430 up_restart = DISABLED
Thu Jun 2 14:28:22 2011 us=684454 up_delay = DISABLED
Thu Jun 2 14:28:22 2011 us=684479 daemon = ENABLED
Thu Jun 2 14:28:22 2011 us=684503 inetd = 0
Thu Jun 2 14:28:22 2011 us=684527 log = ENABLED
Thu Jun 2 14:28:22 2011 us=684551 suppress_timestamps = DISABLED
Thu Jun 2 14:28:22 2011 us=684575 nice = 0
Thu Jun 2 14:28:22 2011 us=684599 verbosity = 4
Thu Jun 2 14:28:22 2011 us=684622 mute = 0
Thu Jun 2 14:28:22 2011 us=684645 gremlin = 0
Thu Jun 2 14:28:22 2011 us=684668 status_file = 'some_config/status.log'
Thu Jun 2 14:28:22 2011 us=684692 status_file_version = 1
Thu Jun 2 14:28:22 2011 us=684715 status_file_update_freq = 60
Thu Jun 2 14:28:22 2011 us=684738 occ = ENABLED
Thu Jun 2 14:28:22 2011 us=684761 rcvbuf = 65536
Thu Jun 2 14:28:22 2011 us=684784 sndbuf = 65536
Thu Jun 2 14:28:22 2011 us=684807 sockflags = 0
Thu Jun 2 14:28:22 2011 us=684829 fast_io = DISABLED
Thu Jun 2 14:28:22 2011 us=684852 lzo = 0
Thu Jun 2 14:28:22 2011 us=684874 route_script = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=684897 route_default_gateway = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=684920 route_default_metric = 0
Thu Jun 2 14:28:22 2011 us=684942 route_noexec = DISABLED
Thu Jun 2 14:28:22 2011 us=684967 route_delay = 0
Thu Jun 2 14:28:22 2011 us=684983 route_delay_window = 30
Thu Jun 2 14:28:22 2011 us=684998 route_delay_defined = DISABLED
Thu Jun 2 14:28:22 2011 us=685013 route_nopull = DISABLED
Thu Jun 2 14:28:22 2011 us=685029 route_gateway_via_dhcp = DISABLED
Thu Jun 2 14:28:22 2011 us=685045 max_routes = 100
Thu Jun 2 14:28:22 2011 us=685060 allow_pull_fqdn = DISABLED
Thu Jun 2 14:28:22 2011 us=685076 management_addr = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685092 management_port = 0
Thu Jun 2 14:28:22 2011 us=685107 management_user_pass = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685123 management_log_history_cache = 250
Thu Jun 2 14:28:22 2011 us=685139 management_echo_buffer_size = 100
Thu Jun 2 14:28:22 2011 us=685155 management_write_peer_info_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685171 management_client_user = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685186 management_client_group = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685202 management_flags = 0
Thu Jun 2 14:28:22 2011 us=685218 shared_secret_file = 'some_config/static.key'
Thu Jun 2 14:28:22 2011 us=685234 key_direction = 0
Thu Jun 2 14:28:22 2011 us=685250 ciphername_defined = ENABLED
Thu Jun 2 14:28:22 2011 us=685265 ciphername = 'BF-CBC'
Thu Jun 2 14:28:22 2011 us=685280 authname_defined = ENABLED
Thu Jun 2 14:28:22 2011 us=685296 authname = 'SHA1'
Thu Jun 2 14:28:22 2011 us=685311 prng_hash = 'SHA1'
Thu Jun 2 14:28:22 2011 us=685326 prng_nonce_secret_len = 16
Thu Jun 2 14:28:22 2011 us=685342 keysize = 0
Thu Jun 2 14:28:22 2011 us=685357 engine = DISABLED
Thu Jun 2 14:28:22 2011 us=685373 replay = ENABLED
Thu Jun 2 14:28:22 2011 us=685389 mute_replay_warnings = DISABLED
Thu Jun 2 14:28:22 2011 us=685405 replay_window = 64
Thu Jun 2 14:28:22 2011 us=685421 replay_time = 15
Thu Jun 2 14:28:22 2011 us=685436 packet_id_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685452 use_iv = ENABLED
Thu Jun 2 14:28:22 2011 us=685468 test_crypto = DISABLED
Thu Jun 2 14:28:22 2011 us=685483 tls_server = DISABLED
Thu Jun 2 14:28:22 2011 us=685499 tls_client = DISABLED
Thu Jun 2 14:28:22 2011 us=685515 key_method = 2
Thu Jun 2 14:28:22 2011 us=685530 ca_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685546 ca_path = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685561 dh_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685588 cert_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685605 priv_key_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685621 pkcs12_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685636 cipher_list = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685652 tls_verify = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685668 tls_export_cert = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685684 tls_remote = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685699 crl_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685716 ns_cert_type = 0
Thu Jun 2 14:28:22 2011 us=685732 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685748 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685763 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685778 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685793 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685809 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685823 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685838 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685853 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685868 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685883 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685898 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685914 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685929 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685944 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685959 remote_cert_ku[i] = 0
Thu Jun 2 14:28:22 2011 us=685974 remote_cert_eku = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=685989 tls_timeout = 2
Thu Jun 2 14:28:22 2011 us=686004 renegotiate_bytes = 0
Thu Jun 2 14:28:22 2011 us=686019 renegotiate_packets = 0
Thu Jun 2 14:28:22 2011 us=686034 renegotiate_seconds = 3600
Thu Jun 2 14:28:22 2011 us=686049 handshake_window = 60
Thu Jun 2 14:28:22 2011 us=686064 transition_window = 3600
Thu Jun 2 14:28:22 2011 us=686079 single_session = DISABLED
Thu Jun 2 14:28:22 2011 us=686094 push_peer_info = DISABLED
Thu Jun 2 14:28:22 2011 us=686109 tls_exit = DISABLED
Thu Jun 2 14:28:22 2011 us=686125 tls_auth_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=686141 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686157 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686172 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686188 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686203 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686218 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686234 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686249 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686264 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686279 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686294 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686309 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686324 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686340 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686355 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686370 pkcs11_protected_authentication = DISABLED
Thu Jun 2 14:28:22 2011 us=686387 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686403 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686418 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686434 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686449 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686464 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686480 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686495 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686510 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686525 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686550 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686566 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686582 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686597 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686612 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686628 pkcs11_private_mode = 00000000
Thu Jun 2 14:28:22 2011 us=686643 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686658 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686673 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686688 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686703 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686722 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686749 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686775 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686800 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686823 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686846 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686869 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686892 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686916 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686940 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686965 pkcs11_cert_private = DISABLED
Thu Jun 2 14:28:22 2011 us=686989 pkcs11_pin_cache_period = -1
Thu Jun 2 14:28:22 2011 us=687013 pkcs11_id = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687037 pkcs11_id_management = DISABLED
Thu Jun 2 14:28:22 2011 us=687083 server_network = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687117 server_netmask = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687143 server_bridge_ip = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687171 server_bridge_netmask = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687197 server_bridge_pool_start = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687225 server_bridge_pool_end = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687254 ifconfig_pool_defined = DISABLED
Thu Jun 2 14:28:22 2011 us=687273 ifconfig_pool_start = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687291 ifconfig_pool_end = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687308 ifconfig_pool_netmask = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687324 ifconfig_pool_persist_filename = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687339 ifconfig_pool_persist_refresh_freq = 600
Thu Jun 2 14:28:22 2011 us=687355 n_bcast_buf = 256
Thu Jun 2 14:28:22 2011 us=687370 tcp_queue_limit = 64
Thu Jun 2 14:28:22 2011 us=687386 real_hash_size = 256
Thu Jun 2 14:28:22 2011 us=687401 virtual_hash_size = 256
Thu Jun 2 14:28:22 2011 us=687416 client_connect_script = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687432 learn_address_script = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687448 client_disconnect_script = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687448 client_config_dir = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687448 ccd_exclusive = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 tmp_dir = '/tmp'
Thu Jun 2 14:28:22 2011 us=687448 push_ifconfig_defined = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 push_ifconfig_local = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687448 push_ifconfig_remote_netmask = 0.0.0.0
Thu Jun 2 14:28:22 2011 us=687448 enable_c2c = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 duplicate_cn = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 cf_max = 0
Thu Jun 2 14:28:22 2011 us=687448 cf_per = 0
Thu Jun 2 14:28:22 2011 us=687448 max_clients = 1024
Thu Jun 2 14:28:22 2011 us=687448 max_routes_per_client = 256
Thu Jun 2 14:28:22 2011 us=687448 auth_user_pass_verify_script = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687448 auth_user_pass_verify_script_via_file = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 ssl_flags = 0
Thu Jun 2 14:28:22 2011 us=687448 port_share_host = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687448 port_share_port = 0
Thu Jun 2 14:28:22 2011 us=687448 client = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 pull = DISABLED
Thu Jun 2 14:28:22 2011 us=687448 auth_user_pass_file = '[UNDEF]'
Thu Jun 2 14:28:22 2011 us=687448 OpenVPN 2.2.0 i486-linux-gnu [SSL] [LZO2] [EPOLL] [PKCS11] [eurephia] built on Apr 24 2011
Thu Jun 2 14:28:22 2011 us=687448 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Thu Jun 2 14:28:22 2011 us=687673 Static Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Thu Jun 2 14:28:22 2011 us=687735 Static Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Jun 2 14:28:22 2011 us=687846 Static Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Thu Jun 2 14:28:22 2011 us=687866 Static Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Jun 2 14:28:22 2011 us=687923 Socket Buffers: R=[112640->131072] S=[112640->131072]
Thu Jun 2 14:28:22 2011 us=688664 WARNING: potential TUN/TAP adapter subnet conflict between local LAN [192.168.249.0/255.255.255.0] and remote VPN [192.168.249.163/255.255.255.255]
Thu Jun 2 14:28:22 2011 us=690065 TUN/TAP device tun1 opened
Thu Jun 2 14:28:22 2011 us=696013 TUN/TAP TX queue length set to 100
Thu Jun 2 14:28:22 2011 us=696048 /sbin/ifconfig tun1 192.168.249.163 pointopoint 192.168.249.162 mtu 1500
Thu Jun 2 14:28:22 2011 us=702316 /bin/echo script_up tun1 1500 1544 192.168.249.163 192.168.249.162 init
script_up tun1 1500 1544 192.168.249.163 192.168.249.162 init
Thu Jun 2 14:28:22 2011 us=710706 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:28:22 2011 us=710750 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:28:22 2011 us=710758 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:28:22 2011 us=710786 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:28:22 2011 us=710797 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:28:22 2011 us=711114 GID set to nogroup
Thu Jun 2 14:28:22 2011 us=711130 UID set to nobody
Thu Jun 2 14:28:22 2011 us=711130 UDPv4 link local: [undef]
Thu Jun 2 14:28:22 2011 us=711145 UDPv4 link remote: a.b.c.d:port#
Thu Jun 2 14:30:22 2011 us=440862 Inactivity timeout (--ping-restart), restarting
Thu Jun 2 14:30:22 2011 us=440901 TCP/UDP: Closing socket
Thu Jun 2 14:30:22 2011 us=440955 SIGUSR1[soft,ping-restart] received, process restarting
Thu Jun 2 14:30:22 2011 us=440988 Restart pause, 2 second(s)
Thu Jun 2 14:30:24 2011 us=441769 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Thu Jun 2 14:30:24 2011 us=441912 Re-using pre-shared static key
Thu Jun 2 14:30:24 2011 us=441998 Socket Buffers: R=[112640->131072] S=[112640->131072]
Thu Jun 2 14:30:24 2011 us=442219 Preserving previous TUN/TAP instance: tun1
Thu Jun 2 14:30:24 2011 us=442277 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:30:24 2011 us=442372 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:30:24 2011 us=442418 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:30:24 2011 us=442485 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:30:24 2011 us=442539 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:30:24 2011 us=442591 UDPv4 link local: [undef]
Thu Jun 2 14:30:24 2011 us=442636 UDPv4 link remote: a.b.c.d:port#
Thu Jun 2 14:32:24 2011 us=827452 Inactivity timeout (--ping-restart), restarting
Thu Jun 2 14:32:24 2011 us=827558 TCP/UDP: Closing socket
Thu Jun 2 14:32:24 2011 us=827604 SIGUSR1[soft,ping-restart] received, process restarting
Thu Jun 2 14:32:24 2011 us=827627 Restart pause, 2 second(s)
Thu Jun 2 14:32:26 2011 us=827844 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Thu Jun 2 14:32:26 2011 us=827954 Re-using pre-shared static key
Thu Jun 2 14:32:26 2011 us=828005 Socket Buffers: R=[112640->131072] S=[112640->131072]
Thu Jun 2 14:32:26 2011 us=828141 Preserving previous TUN/TAP instance: tun1
Thu Jun 2 14:32:26 2011 us=828168 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:32:26 2011 us=828217 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:32:26 2011 us=828234 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:32:26 2011 us=828267 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:32:26 2011 us=828293 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:32:26 2011 us=828318 UDPv4 link local: [undef]
Thu Jun 2 14:32:26 2011 us=828338 UDPv4 link remote: a.b.c.d:port#
Thu Jun 2 14:34:26 2011 us=77890 Inactivity timeout (--ping-restart), restarting
Thu Jun 2 14:34:26 2011 us=80270 TCP/UDP: Closing socket
Thu Jun 2 14:34:26 2011 us=80486 SIGUSR1[soft,ping-restart] received, process restarting
Thu Jun 2 14:34:26 2011 us=80639 Restart pause, 2 second(s)
Thu Jun 2 14:34:28 2011 us=81011 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Thu Jun 2 14:34:28 2011 us=81142 Re-using pre-shared static key
Thu Jun 2 14:34:28 2011 us=81200 Socket Buffers: R=[112640->131072] S=[112640->131072]
Thu Jun 2 14:34:28 2011 us=81338 Preserving previous TUN/TAP instance: tun1
Thu Jun 2 14:34:28 2011 us=81365 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:34:28 2011 us=81413 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:34:28 2011 us=81431 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:34:28 2011 us=81463 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:34:28 2011 us=81489 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:34:28 2011 us=81514 UDPv4 link local: [undef]
Thu Jun 2 14:34:28 2011 us=81534 UDPv4 link remote: a.b.c.d:port#
Thu Jun 2 14:36:28 2011 us=566348 Inactivity timeout (--ping-restart), restarting
Thu Jun 2 14:36:28 2011 us=566460 TCP/UDP: Closing socket
Thu Jun 2 14:36:28 2011 us=566508 SIGUSR1[soft,ping-restart] received, process restarting
Thu Jun 2 14:36:28 2011 us=566535 Restart pause, 2 second(s)
Thu Jun 2 14:36:30 2011 us=569261 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Thu Jun 2 14:36:30 2011 us=569362 Re-using pre-shared static key
Thu Jun 2 14:36:30 2011 us=569431 Socket Buffers: R=[112640->131072] S=[112640->131072]
Thu Jun 2 14:36:30 2011 us=569581 Preserving previous TUN/TAP instance: tun1
Thu Jun 2 14:36:30 2011 us=569638 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:36:30 2011 us=569690 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:36:30 2011 us=569707 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:36:30 2011 us=569850 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:36:30 2011 us=569888 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:36:30 2011 us=569915 UDPv4 link local: [undef]
Thu Jun 2 14:36:30 2011 us=569936 UDPv4 link remote: a.b.c.d:port#
Thu Jun 2 14:38:30 2011 us=266472 Inactivity timeout (--ping-restart), restarting
Thu Jun 2 14:38:30 2011 us=266600 TCP/UDP: Closing socket
Thu Jun 2 14:38:30 2011 us=266663 SIGUSR1[soft,ping-restart] received, process restarting
Thu Jun 2 14:38:30 2011 us=266706 Restart pause, 2 second(s)
Thu Jun 2 14:38:32 2011 us=266901 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Thu Jun 2 14:38:32 2011 us=267011 Re-using pre-shared static key
Thu Jun 2 14:38:32 2011 us=267064 Socket Buffers: R=[112640->131072] S=[112640->131072]
Thu Jun 2 14:38:32 2011 us=267200 Preserving previous TUN/TAP instance: tun1
Thu Jun 2 14:38:32 2011 us=267226 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:38:32 2011 us=267276 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:38:32 2011 us=267293 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:38:32 2011 us=267326 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:38:32 2011 us=267352 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:38:32 2011 us=267378 UDPv4 link local: [undef]
Thu Jun 2 14:38:32 2011 us=267398 UDPv4 link remote: a.b.c.d:port#

Client Configuration:

remote hostname.domain.tld port#
nobind
proto udp
dev tun1
keepalive 10 120

secret some_config/static.key

ifconfig 192.168.249.163 192.168.249.162

user nobody
group nogroup

resolv-retry infinite

persist-key
persist-tun

status some_config/status.log
log some_config/openvpn.log

verb 4

script-security 2
up "/bin/echo script_up"
down "/bin/echo script_down"

Server Configuration:
The server side was down for the logs above.

port port#
proto udp
dev tun3
keepalive 10 120

secret some_config/static.key

ifconfig 192.168.249.162 192.168.249.163

user nobody
group nogroup

persist-key
persist-tun

status some_config/status.log
log some_config/openvpn.log

verb 4

script-security 2
up /sbin/fwctl_restart
down /sbin/fwctl_restart

Change History (5)

comment:1 Changed 13 years ago by krzee king

Summary: OpenVPN 2.2 executes user-defined "up" script before connection is attempted → OpenVPN 2.2 executes user-defined "up" script even when server is down

comment:2 Changed 13 years ago by exes

When I use the route-up directive, rather than up, the same behavior is observed.

...
Thu Jun 2 14:49:50 2011 us=916389 TUN/TAP device tun1 opened
Thu Jun 2 14:49:50 2011 us=916413 TUN/TAP TX queue length set to 100
Thu Jun 2 14:49:50 2011 us=916442 /sbin/ifconfig tun1 192.168.249.163 pointopoint 192.168.249.162 mtu 1500
script_up
Thu Jun 2 14:49:50 2011 us=920022 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:4 ET:0 EL:0 ]
Thu Jun 2 14:49:50 2011 us=920060 Local Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.162 192.168.249.163,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:49:50 2011 us=920067 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto UDPv4,ifconfig 192.168.249.163 192.168.249.162,cipher BF-CBC,auth SHA1,keysize 128,secret'
Thu Jun 2 14:49:50 2011 us=920093 Local Options hash (VER=V4): 'fee93d1d'
Thu Jun 2 14:49:50 2011 us=920104 Expected Remote Options hash (VER=V4): '46b0e37b'
Thu Jun 2 14:49:50 2011 us=927735 GID set to nogroup
Thu Jun 2 14:49:50 2011 us=927807 UID set to nobody
Thu Jun 2 14:49:50 2011 us=927825 UDPv4 link local: [undef]
Thu Jun 2 14:49:50 2011 us=927837 UDPv4 link remote: a.b.c.d:port#
...

comment:3 Changed 13 years ago by David Sommerseth

Resolution: → notabug
Status: new → closed

From what I can understand, this behaviour is expected in this setup. The man page says:

       --up cmd
              Shell command to run after successful  TUN/TAP  device
              open (pre --user UID change).  The up script is useful
              for specifying route commands which route  IP  traffic
              destined  for private subnets which exist at the other
              end of the VPN connection into the tunnel.

When you use ifconfig with IP address config, the TUN/TAP device is opened, it is even configured. And this is why both the --up and --route-up scripts are executed. It is not a requirement that --up/--route-up is executed after the connection is established.

If you rather use --ifconfig-pool on the server side and --pull on the client side, you can then skip --ifconfig in the client config. In this setup openvpn would behave as you expect.

comment:4 Changed 13 years ago by David Sommerseth

Milestone: release 2.2.0

comment:5 Changed 13 years ago by David Sommerseth

Component: Generic / unclassified → Configuration
Note: See TracTickets for help on using tickets.