Long setup time

larry

I'm just getting started with openvpn. I've set up a server on OpenBSD with openvpn 2.1.4, and I'm connecting with Linux and Windows clients (2.2.0). Everything works, but establishing the connection takes well over a minute.

The first delay is here:

Mon Jun 27 21:43:11 2011 TLS: Initial packet from xx.xx.xx.xx:1194, sid=374a76c5 4da0843d
Mon Jun 27 21:43:28 2011 VERIFY OK: depth=1, /C=XX/ST=YYYY/....

and the second here

Mon Jun 27 21:43:28 2011 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Mon Jun 27 21:43:28 2011 VERIFY EKU OK
Mon Jun 27 21:43:28 2011 VERIFY OK: depth=0, /C=XX/ST=YYYY/.....
Mon Jun 27 21:44:05 2011 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key

What can explain this delay and how can I fix it? It exceeds the builtin timeout in networkmanager-openvpn so this method cannot be used for connecting at all.

maikcat

hi there,

can you please post configs?

>Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

hmm...

please post configs!

Michael.

larry

Sure.

server:

local ip.addr.of.server
port 1194
proto udp
dev tun0
ca /etc/openvpn/keys/ca.crt
cert /etc/openvpn/keys/server.crt
key /etc/openvpn/keys/server.key  # This file should be kept secret
dh /etc/openvpn/keys/dh1024.pem
server 10.1.2.0 255.255.255.0
ifconfig-pool-persist ipp.txt
push "route x.x.x.x 255.255.255.0"
push "dhcp-option DNS x.x.x.1"
push "dhcp-option DNS x.x.x.2"
keepalive 10 120
comp-lzo
user _openvpn
group _openvpn
persist-key
persist-tun
status /var/log/openvpn-status.log
log-append  /var/log/openvpnlog
verb 3
plugin /etc/openvpn/radiusplugin.so /etc/openvpn/radiusplugin.cnf
writepid /var/run/openvpn.pid

I'm using the radius plugin, but leaving it out and using certificates only does not change the basic problem.

client:

script-security 2
up /etc/openvpn/up.sh
down /etc/openvpn/down.sh
client
dev tun
proto udp
remote ip.add.of.server 1194
resolv-retry infinite
nobind
persist-key
persist-tun
ca /etc/openvpn/ca.crt
cert /etc/openvpn/client1.crt
key /etc/openvpn/client1.key
comp-lzo
verb 3
auth-user-pass
remote-cert-tls server
auth-nocache

I built the config files straight from the examples subdir, and followed http://www.openvpn.net/index.php/open-source/documentation/howto.html to the letter.

maikcat

hi there,

can you remove from your client config this:
>remote-cert-tls server

also just to remind you ,you can use also this directive tls-auth

tell us if changes something..

Michael.

larry

IIRC I added remote-cert-tls server in response to a warning issued by the client during connection, and the delay was just the same before. But I will test this again to be sure.

I have not considered tls-auth as it requires yet another key.

One thing: is there a complete reference that lists all server and client config file directives? I couldn't find one.

larry

I removed remote-cert-tls and tried again, no change:

Mon Jul  4 18:28:41 2011 OpenVPN 2.1.4 i686-pc-linux-gnu [SSL] [LZO2] [EPOLL] built on Jun 22 2011
Enter Auth Username:user
Enter Auth Password:*****
Mon Jul  4 18:28:46 2011 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Mon Jul  4 18:28:46 2011 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mon Jul  4 18:28:46 2011 LZO compression initialized
Mon Jul  4 18:28:46 2011 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Mon Jul  4 18:28:46 2011 Socket Buffers: R=[110592->131072] S=[110592->131072]
Mon Jul  4 18:28:46 2011 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Mon Jul  4 18:28:46 2011 Local Options hash (VER=V4): '41690919'
Mon Jul  4 18:28:46 2011 Expected Remote Options hash (VER=V4): '530fdded'
Mon Jul  4 18:28:46 2011 UDPv4 link local: [undef]
Mon Jul  4 18:28:46 2011 UDPv4 link remote: xx.xx.xx.xx:1194
Mon Jul  4 18:28:46 2011 TLS: Initial packet from xx.xx.xx.xx:1194, sid=329d23b5 356ee00e
Mon Jul  4 18:29:01 2011 VERIFY OK: depth=1, /C=XX/ST=...
Mon Jul  4 18:29:01 2011 VERIFY OK: depth=0, /C=XX/ST=...
Mon Jul  4 18:29:33 2011 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Jul  4 18:29:33 2011 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Jul  4 18:29:33 2011 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Jul  4 18:29:33 2011 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Jul  4 18:29:34 2011 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Mon Jul  4 18:29:34 2011 [server] Peer Connection Initiated with xx.xx.xx.xx:1194
Mon Jul  4 18:29:36 2011 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Mon Jul  4 18:29:40 2011 PUSH: Received control message: 'PUSH_REPLY,route yy.yy.yy.0 255.255.255.0,dhcp-option DNS yy.yy.yy.2,dhcp-option DNS yy.yy.yy.2,route zz.zz.zz.1,topology net30,ping 10,ping-restart 120,ifconfig zz.zz.zz..6 zz.zz.zz.5'
Mon Jul  4 18:29:40 2011 OPTIONS IMPORT: timers and/or timeouts modified
Mon Jul  4 18:29:40 2011 OPTIONS IMPORT: --ifconfig/up options modified
Mon Jul  4 18:29:40 2011 OPTIONS IMPORT: route options modified
Mon Jul  4 18:29:40 2011 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Mon Jul  4 18:29:40 2011 ROUTE default_gateway=192.168.1.254
Mon Jul  4 18:29:40 2011 TUN/TAP device tun0 opened
Mon Jul  4 18:29:40 2011 TUN/TAP TX queue length set to 100
Mon Jul  4 18:29:40 2011 /sbin/ifconfig tun0 zz.zz.zz.6 pointopoint zz.zz.zz.5 mtu 1500
Mon Jul  4 18:29:40 2011 /etc/openvpn/up.sh tun0 1500 1542 zz.zz.zz.6 zz.zz.zz.5 init
 * Stopping dnsmasq ... [ ok ]
 * Starting dnsmasq ... [ ok ]
Mon Jul  4 18:29:40 2011 /sbin/route add -net yy.yy.yy.0 netmask 255.255.255.0 gw zz.zz.zz.5
Mon Jul  4 18:29:40 2011 /sbin/route add -net zz.zz.zz.1 netmask 255.255.255.255 gw zz.zz.zz.5
Mon Jul  4 18:29:40 2011 Initialization Sequence Completed

Then I tried tls-auth, same result:

Mon Jul  4 18:48:23 2011 OpenVPN 2.1.4 i686-pc-linux-gnu [SSL] [LZO2] [EPOLL] built on Jun 22 2011
Enter Auth Username:user
Enter Auth Password:*****
Mon Jul  4 18:48:27 2011 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Mon Jul  4 18:48:27 2011 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mon Jul  4 18:48:27 2011 Control Channel Authentication: using '/tmp/openvpn/ta.key' as a OpenVPN static key file
Mon Jul  4 18:48:27 2011 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Jul  4 18:48:27 2011 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Jul  4 18:48:27 2011 LZO compression initialized
Mon Jul  4 18:48:27 2011 Control Channel MTU parms [ L:1542 D:166 EF:66 EB:0 ET:0 EL:0 ]
Mon Jul  4 18:48:27 2011 Socket Buffers: R=[110592->131072] S=[110592->131072]
Mon Jul  4 18:48:27 2011 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Mon Jul  4 18:48:27 2011 Local Options hash (VER=V4): '504e774e'
Mon Jul  4 18:48:27 2011 Expected Remote Options hash (VER=V4): '14168603'
Mon Jul  4 18:48:27 2011 UDPv4 link local: [undef]
Mon Jul  4 18:48:27 2011 UDPv4 link remote: xx.xx.xx.xx:1194
Mon Jul  4 18:48:27 2011 TLS: Initial packet from xx.xx.xx.xx:1194, sid=b5332cf6 4ec8e7f7
Mon Jul  4 18:48:44 2011 VERIFY OK: depth=1, /C=XX/ST=...
Mon Jul  4 18:48:44 2011 VERIFY OK: depth=0, /C=XX/ST=...
Mon Jul  4 18:49:13 2011 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Jul  4 18:49:13 2011 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Jul  4 18:49:13 2011 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mon Jul  4 18:49:13 2011 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mon Jul  4 18:49:16 2011 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Mon Jul  4 18:49:16 2011 [server] Peer Connection Initiated with xx.xx.xx.xx:1194
Mon Jul  4 18:49:18 2011 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Mon Jul  4 18:49:22 2011 PUSH: Received control message: 'PUSH_REPLY,route yy.yy.yy.0 255.255.255.0,dhcp-option DNS yy.yy.yy.2,dhcp-option DNS yy.yy.yy.1,route zz.zz.zz.1,topology net30,ping 10,ping-restart 120,ifconfig zz.zz.zz.6 zz.zz.zz.5'
Mon Jul  4 18:49:22 2011 OPTIONS IMPORT: timers and/or timeouts modified
Mon Jul  4 18:49:22 2011 OPTIONS IMPORT: --ifconfig/up options modified
Mon Jul  4 18:49:22 2011 OPTIONS IMPORT: route options modified
Mon Jul  4 18:49:22 2011 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Mon Jul  4 18:49:22 2011 ROUTE default_gateway=192.168.1.254
Mon Jul  4 18:49:22 2011 TUN/TAP device tun0 opened
Mon Jul  4 18:49:22 2011 TUN/TAP TX queue length set to 100
Mon Jul  4 18:49:22 2011 /sbin/ifconfig tun0 zz.zz.zz.6 pointopoint zz.zz.zz.5 mtu 1500
Mon Jul  4 18:49:22 2011 /etc/openvpn/up.sh tun0 1500 1542 zz.zz.zz.6 zz.zz.zz.5 init
 * Stopping dnsmasq ... [ ok ]
 * Starting dnsmasq ... [ ok ]
Mon Jul  4 18:49:23 2011 /sbin/route add -net yy.yy.yy.0 netmask 255.255.255.0 gw zz.zz.zz.5
Mon Jul  4 18:49:23 2011 /sbin/route add -net zz.zz.zz.1 netmask 255.255.255.255 gw zz.zz.zz.5
Mon Jul  4 18:49:23 2011 Initialization Sequence Completed

maikcat

hi there,

maybe i am blind but i dont see whats wrong with the last logs you post...

maybe this:

>WARNING: No server certificate verification method has been enabled

just add to your client

ns-cert-type server

Michael.

larry

This works, and I can see in the client log that the additional cert check is made. But the connection setup still takes around a minute.

I was wondering whether the WAN connection plays a part in the delay; the last leg to the server is a dedicated 2Mbps wireless link. But the link quality seems good, I have pinged the server for 10 minutes and got 0% packet loss.

maikcat

can you post logs at the time the connection hangs?

Michael.

larry

Here goes. Note that I have increased verbosity to 5.

The delays seem to be associated with the logged "WR" sequences, which I presume are associated with server-client communication. They, in fact appear to come in slowly, with pauses of seconds between batches.

Should I disable or change lzo compression? Could that be the cause of the problem?

Wed Jul  6 20:54:46 2011 us=373058 Current Parameter Settings:
Wed Jul  6 20:54:46 2011 us=373209   config = '/tmp/client.conf'
Wed Jul  6 20:54:46 2011 us=373237   mode = 0
Wed Jul  6 20:54:46 2011 us=373260   persist_config = DISABLED
Wed Jul  6 20:54:46 2011 us=373281   persist_mode = 1
Wed Jul  6 20:54:46 2011 us=373301   show_ciphers = DISABLED
Wed Jul  6 20:54:46 2011 us=373321   show_digests = DISABLED
Wed Jul  6 20:54:46 2011 us=373356   show_engines = DISABLED
Wed Jul  6 20:54:46 2011 us=373377   genkey = DISABLED
Wed Jul  6 20:54:46 2011 us=373397   key_pass_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373416   show_tls_ciphers = DISABLED
Wed Jul  6 20:54:46 2011 us=373436 Connection profiles [default]:
Wed Jul  6 20:54:46 2011 us=373456   proto = udp
Wed Jul  6 20:54:46 2011 us=373475   local = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373494   local_port = 0
Wed Jul  6 20:54:46 2011 us=373515   remote = 'xx.xx.xx.xx'
Wed Jul  6 20:54:46 2011 us=373535   remote_port = 1194
Wed Jul  6 20:54:46 2011 us=373554   remote_float = DISABLED
Wed Jul  6 20:54:46 2011 us=373573   bind_defined = DISABLED
Wed Jul  6 20:54:46 2011 us=373592   bind_local = DISABLED
Wed Jul  6 20:54:46 2011 us=373611   connect_retry_seconds = 5
Wed Jul  6 20:54:46 2011 us=373630   connect_timeout = 10
Wed Jul  6 20:54:46 2011 us=373649   connect_retry_max = 0
Wed Jul  6 20:54:46 2011 us=373669   socks_proxy_server = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373688   socks_proxy_port = 0
Wed Jul  6 20:54:46 2011 us=373707   socks_proxy_retry = DISABLED
Wed Jul  6 20:54:46 2011 us=373726 Connection profiles END
Wed Jul  6 20:54:46 2011 us=373744   remote_random = DISABLED
Wed Jul  6 20:54:46 2011 us=373763   ipchange = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373782   dev = 'tun'
Wed Jul  6 20:54:46 2011 us=373800   dev_type = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373819   dev_node = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373838   lladdr = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373856   topology = 1
Wed Jul  6 20:54:46 2011 us=373875   tun_ipv6 = DISABLED
Wed Jul  6 20:54:46 2011 us=373895   ifconfig_local = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373914   ifconfig_remote_netmask = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=373932   ifconfig_noexec = DISABLED
Wed Jul  6 20:54:46 2011 us=373951   ifconfig_nowarn = DISABLED
Wed Jul  6 20:54:46 2011 us=373970   shaper = 0
Wed Jul  6 20:54:46 2011 us=373988   tun_mtu = 1500
Wed Jul  6 20:54:46 2011 us=374007   tun_mtu_defined = ENABLED
Wed Jul  6 20:54:46 2011 us=374026   link_mtu = 1500
Wed Jul  6 20:54:46 2011 us=374044   link_mtu_defined = DISABLED
Wed Jul  6 20:54:46 2011 us=374063   tun_mtu_extra = 0
Wed Jul  6 20:54:46 2011 us=374082   tun_mtu_extra_defined = DISABLED
Wed Jul  6 20:54:46 2011 us=374101   fragment = 0
Wed Jul  6 20:54:46 2011 us=374120   mtu_discover_type = -1
Wed Jul  6 20:54:46 2011 us=374139   mtu_test = 0
Wed Jul  6 20:54:46 2011 us=374158   mlock = DISABLED
Wed Jul  6 20:54:46 2011 us=374177   keepalive_ping = 0
Wed Jul  6 20:54:46 2011 us=374195   keepalive_timeout = 0
Wed Jul  6 20:54:46 2011 us=374214   inactivity_timeout = 0
Wed Jul  6 20:54:46 2011 us=374238   ping_send_timeout = 0
Wed Jul  6 20:54:46 2011 us=374258   ping_rec_timeout = 0
Wed Jul  6 20:54:46 2011 us=374277   ping_rec_timeout_action = 0
Wed Jul  6 20:54:46 2011 us=374296   ping_timer_remote = DISABLED
Wed Jul  6 20:54:46 2011 us=374329   remap_sigusr1 = 0
Wed Jul  6 20:54:46 2011 us=374350   explicit_exit_notification = 0
Wed Jul  6 20:54:46 2011 us=374369   persist_tun = ENABLED
Wed Jul  6 20:54:46 2011 us=374388   persist_local_ip = DISABLED
Wed Jul  6 20:54:46 2011 us=374407   persist_remote_ip = DISABLED
Wed Jul  6 20:54:46 2011 us=374425   persist_key = ENABLED
Wed Jul  6 20:54:46 2011 us=374444   mssfix = 1450
Wed Jul  6 20:54:46 2011 us=374462   passtos = DISABLED
Wed Jul  6 20:54:46 2011 us=374481   resolve_retry_seconds = 1000000000
Wed Jul  6 20:54:46 2011 us=374500   username = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=374519   groupname = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=374545   chroot_dir = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=374565   cd_dir = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=374586   writepid = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=374605   up_script = '/etc/openvpn/up.sh'
Wed Jul  6 20:54:46 2011 us=374624   down_script = '/etc/openvpn/down.sh'
Wed Jul  6 20:54:46 2011 us=374643   down_pre = DISABLED
Wed Jul  6 20:54:46 2011 us=374662   up_restart = DISABLED
Wed Jul  6 20:54:46 2011 us=374681   up_delay = DISABLED
Wed Jul  6 20:54:46 2011 us=374699   daemon = DISABLED
Wed Jul  6 20:54:46 2011 us=374718   inetd = 0
Wed Jul  6 20:54:46 2011 us=374737   log = DISABLED
Wed Jul  6 20:54:46 2011 us=374756   suppress_timestamps = DISABLED
Wed Jul  6 20:54:46 2011 us=374774   nice = 0
Wed Jul  6 20:54:46 2011 us=374793   verbosity = 5
Wed Jul  6 20:54:46 2011 us=374811   mute = 0
Wed Jul  6 20:54:46 2011 us=374830   gremlin = 0
Wed Jul  6 20:54:46 2011 us=374848   status_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=374867   status_file_version = 1
Wed Jul  6 20:54:46 2011 us=374885   status_file_update_freq = 60
Wed Jul  6 20:54:46 2011 us=374904   occ = ENABLED
Wed Jul  6 20:54:46 2011 us=374923   rcvbuf = 65536
Wed Jul  6 20:54:46 2011 us=374942   sndbuf = 65536
Wed Jul  6 20:54:46 2011 us=374960   sockflags = 0
Wed Jul  6 20:54:46 2011 us=374978   fast_io = DISABLED
Wed Jul  6 20:54:46 2011 us=374997   lzo = 7
Wed Jul  6 20:54:46 2011 us=375015   route_script = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375034   route_default_gateway = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375053   route_default_metric = 0
Wed Jul  6 20:54:46 2011 us=375072   route_noexec = DISABLED
Wed Jul  6 20:54:46 2011 us=375090   route_delay = 0
Wed Jul  6 20:54:46 2011 us=375109   route_delay_window = 30
Wed Jul  6 20:54:46 2011 us=375128   route_delay_defined = DISABLED
Wed Jul  6 20:54:46 2011 us=375147   route_nopull = DISABLED
Wed Jul  6 20:54:46 2011 us=375166   route_gateway_via_dhcp = DISABLED
Wed Jul  6 20:54:46 2011 us=375185   max_routes = 100
Wed Jul  6 20:54:46 2011 us=375204   allow_pull_fqdn = DISABLED
Wed Jul  6 20:54:46 2011 us=375224   management_addr = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375243   management_port = 0
Wed Jul  6 20:54:46 2011 us=375263   management_user_pass = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375283   management_log_history_cache = 250
Wed Jul  6 20:54:46 2011 us=375303   management_echo_buffer_size = 100
Wed Jul  6 20:54:46 2011 us=375323   management_write_peer_info_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375369   management_client_user = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375390   management_client_group = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375410   management_flags = 0
Wed Jul  6 20:54:46 2011 us=375434   shared_secret_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375455   key_direction = 2
Wed Jul  6 20:54:46 2011 us=375475   ciphername_defined = ENABLED
Wed Jul  6 20:54:46 2011 us=375494   ciphername = 'BF-CBC'
Wed Jul  6 20:54:46 2011 us=375513   authname_defined = ENABLED
Wed Jul  6 20:54:46 2011 us=375532   authname = 'SHA1'
Wed Jul  6 20:54:46 2011 us=375551   prng_hash = 'SHA1'
Wed Jul  6 20:54:46 2011 us=375571   prng_nonce_secret_len = 16
Wed Jul  6 20:54:46 2011 us=375590   keysize = 0
Wed Jul  6 20:54:46 2011 us=375609   engine = DISABLED
Wed Jul  6 20:54:46 2011 us=375628   replay = ENABLED
Wed Jul  6 20:54:46 2011 us=375647   mute_replay_warnings = DISABLED
Wed Jul  6 20:54:46 2011 us=375667   replay_window = 64
Wed Jul  6 20:54:46 2011 us=375686   replay_time = 15
Wed Jul  6 20:54:46 2011 us=375706   packet_id_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375725   use_iv = ENABLED
Wed Jul  6 20:54:46 2011 us=375744   test_crypto = DISABLED
Wed Jul  6 20:54:46 2011 us=375763   tls_server = DISABLED
Wed Jul  6 20:54:46 2011 us=375782   tls_client = ENABLED
Wed Jul  6 20:54:46 2011 us=375801   key_method = 2
Wed Jul  6 20:54:46 2011 us=375820   ca_file = '/tmp/openvpn/ca.crt'
Wed Jul  6 20:54:46 2011 us=375840   ca_path = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375859   dh_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375878   cert_file = '/tmp/openvpn/client1.crt'
Wed Jul  6 20:54:46 2011 us=375897   priv_key_file = '/tmp/openvpn/client1.key'
Wed Jul  6 20:54:46 2011 us=375918   pkcs12_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375938   cipher_list = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375956   tls_verify = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375975   tls_remote = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=375994   crl_file = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=376013   ns_cert_type = 64
Wed Jul  6 20:54:46 2011 us=376033   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376052   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376071   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376089   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376108   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376126   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376144   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376162   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376180   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376198   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376216   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376234   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376253   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376271   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376290   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376319   remote_cert_ku[i] = 0
Wed Jul  6 20:54:46 2011 us=376340   remote_cert_eku = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=376360   tls_timeout = 2
Wed Jul  6 20:54:46 2011 us=376378   renegotiate_bytes = 0
Wed Jul  6 20:54:46 2011 us=376397   renegotiate_packets = 0
Wed Jul  6 20:54:46 2011 us=376416   renegotiate_seconds = 3600
Wed Jul  6 20:54:46 2011 us=376435   handshake_window = 60
Wed Jul  6 20:54:46 2011 us=376454   transition_window = 3600
Wed Jul  6 20:54:46 2011 us=376473   single_session = DISABLED
Wed Jul  6 20:54:46 2011 us=376491   push_peer_info = DISABLED
Wed Jul  6 20:54:46 2011 us=376510   tls_exit = DISABLED
Wed Jul  6 20:54:46 2011 us=376529   tls_auth_file = '/tmp/openvpn/ta.key'
Wed Jul  6 20:54:46 2011 us=376569   server_network = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376594   server_netmask = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376617   server_bridge_ip = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376640   server_bridge_netmask = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376663   server_bridge_pool_start = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376686   server_bridge_pool_end = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376706   ifconfig_pool_defined = DISABLED
Wed Jul  6 20:54:46 2011 us=376729   ifconfig_pool_start = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376751   ifconfig_pool_end = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376773   ifconfig_pool_netmask = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=376793   ifconfig_pool_persist_filename = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=376813   ifconfig_pool_persist_refresh_freq = 600
Wed Jul  6 20:54:46 2011 us=376836   n_bcast_buf = 256
Wed Jul  6 20:54:46 2011 us=376855   tcp_queue_limit = 64
Wed Jul  6 20:54:46 2011 us=376875   real_hash_size = 256
Wed Jul  6 20:54:46 2011 us=376895   virtual_hash_size = 256
Wed Jul  6 20:54:46 2011 us=376918   client_connect_script = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=376942   learn_address_script = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=376965   client_disconnect_script = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=376985   client_config_dir = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=377006   ccd_exclusive = DISABLED
Wed Jul  6 20:54:46 2011 us=377027   tmp_dir = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=377046   push_ifconfig_defined = DISABLED
Wed Jul  6 20:54:46 2011 us=377069   push_ifconfig_local = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=377092   push_ifconfig_remote_netmask = 0.0.0.0
Wed Jul  6 20:54:46 2011 us=377111   enable_c2c = DISABLED
Wed Jul  6 20:54:46 2011 us=377130   duplicate_cn = DISABLED
Wed Jul  6 20:54:46 2011 us=377150   cf_max = 0
Wed Jul  6 20:54:46 2011 us=377169   cf_per = 0
Wed Jul  6 20:54:46 2011 us=377188   max_clients = 1024
Wed Jul  6 20:54:46 2011 us=377207   max_routes_per_client = 256
Wed Jul  6 20:54:46 2011 us=377226   auth_user_pass_verify_script = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=377248   auth_user_pass_verify_script_via_file = DISABLED
Wed Jul  6 20:54:46 2011 us=377267   ssl_flags = 0
Wed Jul  6 20:54:46 2011 us=377287   port_share_host = '[UNDEF]'
Wed Jul  6 20:54:46 2011 us=377316   port_share_port = 0
Wed Jul  6 20:54:46 2011 us=377338   client = ENABLED
Wed Jul  6 20:54:46 2011 us=377357   pull = ENABLED
Wed Jul  6 20:54:46 2011 us=377377   auth_user_pass_file = 'stdin'
Wed Jul  6 20:54:46 2011 us=377403 OpenVPN 2.1.4 i686-pc-linux-gnu [SSL] [LZO2] [EPOLL] built on Jun 22 2011
Wed Jul  6 20:54:54 2011 us=964422 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Wed Jul  6 20:54:54 2011 us=997838 Control Channel Authentication: using '/tmp/openvpn/ta.key' as a OpenVPN static key file
Wed Jul  6 20:54:54 2011 us=997998 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jul  6 20:54:54 2011 us=998070 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jul  6 20:54:54 2011 us=998184 LZO compression initialized
Wed Jul  6 20:54:54 2011 us=998495 Control Channel MTU parms [ L:1542 D:166 EF:66 EB:0 ET:0 EL:0 ]
Wed Jul  6 20:54:54 2011 us=998631 Socket Buffers: R=[110592->131072] S=[110592->131072]
Wed Jul  6 20:54:54 2011 us=998704 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul  6 20:54:54 2011 us=998796 Local Options String: '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'
Wed Jul  6 20:54:54 2011 us=998852 Expected Remote Options String: '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'
Wed Jul  6 20:54:54 2011 us=998943 Local Options hash (VER=V4): '504e774e'
Wed Jul  6 20:54:54 2011 us=999013 Expected Remote Options hash (VER=V4): '14168603'
Wed Jul  6 20:54:54 2011 us=999088 UDPv4 link local: [undef]
Wed Jul  6 20:54:54 2011 us=999150 UDPv4 link remote: xx.xx.xx.xx:1194
WR
Wed Jul  6 20:54:55 2011 us=73789 TLS: Initial packet from xx.xx.xx.xx:1194, sid=a02d3c38 fe859222
WWWWRRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWR
Wed Jul  6 20:55:10 2011 us=141701 VERIFY OK: depth=1, /C=xx/....
Wed Jul  6 20:55:10 2011 us=142359 VERIFY OK: nsCertType=SERVER
Wed Jul  6 20:55:10 2011 us=142392 VERIFY OK: depth=0, /C=xx/...
WRWRWRWRWRWWWWRWRWRWRWRWRWRRWWRWRWWWRWRWRRRWRWWWWRWRRRWRWWWRRWRWRWRWRWRWRRWRWRWRWRWRWRWWWWRRRWRWR
Wed Jul  6 20:55:36 2011 us=66763 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Wed Jul  6 20:55:36 2011 us=66885 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Jul  6 20:55:36 2011 us=67085 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Wed Jul  6 20:55:36 2011 us=67119 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
WWR
Wed Jul  6 20:55:39 2011 us=779232 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Wed Jul  6 20:55:39 2011 us=779329 [server] Peer Connection Initiated with xx.xx.xx.xx:1194
Wed Jul  6 20:55:42 2011 us=225923 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
WRRWRWR
Wed Jul  6 20:55:46 2011 us=527410 PUSH: Received control message: 'PUSH_REPLY,route zz.zz.zz.0 255.255.255.0,dhcp-option DNS zz.zz.zz.2,dhcp-option DNS zz.zz.zz.1,route yy.yy.yy.1,topology net30,ping 10,ping-restart 120,ifconfig yy.yy.yy.6 yy.yy.yy.5'
Wed Jul  6 20:55:46 2011 us=527626 OPTIONS IMPORT: timers and/or timeouts modified
Wed Jul  6 20:55:46 2011 us=527668 OPTIONS IMPORT: --ifconfig/up options modified
Wed Jul  6 20:55:46 2011 us=527690 OPTIONS IMPORT: route options modified
Wed Jul  6 20:55:46 2011 us=527735 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Wed Jul  6 20:55:46 2011 us=528105 ROUTE default_gateway=192.168.211.254
Wed Jul  6 20:55:46 2011 us=529104 TUN/TAP device tun0 opened
Wed Jul  6 20:55:46 2011 us=529372 TUN/TAP TX queue length set to 100
Wed Jul  6 20:55:46 2011 us=533598 /sbin/ifconfig tun0 yy.yy.yy.6 pointopoint yy.yy.yy.5 mtu 1500
Wed Jul  6 20:55:46 2011 us=552224 /etc/openvpn/up.sh tun0 1500 1542 yy.yy.yy.6 yy.yy.yy.5 init
 * Stopping dnsmasq ... [ ok ]
 * Starting dnsmasq ... [ ok ]
Wed Jul  6 20:55:46 2011 us=784646 /sbin/route add -net zz.zz.zz.0 netmask 255.255.255.0 gw yy.yy.yy.5
Wed Jul  6 20:55:46 2011 us=796571 /sbin/route add -net yy.yy.yy.1 netmask 255.255.255.255 gw yy.yy.yy.5
Wed Jul  6 20:55:46 2011 us=797281 Initialization Sequence Completed

larry

I think I have found the problem: it's the firewall on my home gateway. For some reason, NAT is buggy on my custom kernel, and reverting to the distribution kernel fixes it. Now the setup time is pretty short, as expected, and I'm left with the radius authentication problem described in another thread.