I was puzzled why sometimes openvpn ceases to generate
'--ping 30' packets. I instrumented it a bit,
here is a pseudo-patch:
errlevel.h:
+#define D_PING LOGLEV(4, 0, 0) /* show --ping packets */
....
-#define D_INTERVAL LOGLEV(8, 70, M_DEBUG) /* show interval.h
debugging info */
+#define D_INTERVAL LOGLEV(4, 70, M_DEBUG) /* show interval.h
debugging info */
ping-inline.h: (check_ping_send now will explain why it do not send pings)
static inline void
check_ping_send (struct context *c)
{
void check_ping_send_dowork (struct context *c);
if (!c->options.ping_send_timeout) { msg (D_PING, "PING:
!c->options.ping_send_timeout"); return; }
if (c->c2.to_link.len) { msg (D_PING, "PING: c->c2.to_link.len <> 0");
return; }
if (!event_timeout_trigger (&c->c2.ping_send_interval, &c->c2.timeval))
{ msg (D_PING, "PING:
!event_timeout_trigger(%ld,%ld)",(long)(c->c2.ping_send_interval.last),
(long)c->c2.timeval.tv_sec); return; }
check_ping_send_dowork (c);
}
ping.c:check_ping_send_dowork (struct context *c): (log pings)
...
encrypt_sign (c, true);
+ msg (D_PING, "PING: SENT");
}
forward.c:void single_select (struct context *c): (log large select timeouts)
...
/*
* Wait for something to happen.
*/
c->c2.select_status = 1; /* this will be our return "status" if select
doesn't get called */
if (!c->sig->signal_received && !SOCKET_READ_RESIDUAL (c->c2.link_socket))
{
if (check_debug_level (D_SELECT))
show_select_status (c);
+ if(((unsigned long)c->c2.timeval.tv_sec) >= 28) { //vda
+ msg(D_PING, "PING: select timeout=%ld", (long)c->c2.timeval.tv_sec);
+ }
c->c2.select_status = SELECT (&c->c2.event_wait, &c->c2.timeval);
check_status (c->c2.select_status, "select", NULL, NULL);
}
With --ping 30, select shall _never_ have timeout>30 secs, right?
I was lucky. Bug struck me soon after I restarted openvpn.
Here is the full log:
Fri May 28 22:59:11 2004 Current Parameter Settings:
Fri May 28 22:59:11 2004 config = '[UNDEF]'
Fri May 28 22:59:11 2004 mode = 0
Fri May 28 22:59:11 2004 persist_config = DISABLED
Fri May 28 22:59:11 2004 persist_mode = 1
Fri May 28 22:59:11 2004 show_ciphers = DISABLED
Fri May 28 22:59:11 2004 show_digests = DISABLED
Fri May 28 22:59:11 2004 genkey = DISABLED
Fri May 28 22:59:11 2004 askpass = DISABLED
Fri May 28 22:59:11 2004 show_tls_ciphers = DISABLED
Fri May 28 22:59:11 2004 proto = 0
Fri May 28 22:59:11 2004 local = '1.1.4.1'
Fri May 28 22:59:11 2004 remote_list[0] = {'1.1.4.2', 8002}
Fri May 28 22:59:11 2004 remote_random = DISABLED
Fri May 28 22:59:11 2004 local_port = 8002
Fri May 28 22:59:11 2004 remote_port = 8002
Fri May 28 22:59:11 2004 remote_float = DISABLED
Fri May 28 22:59:11 2004 ipchange = '[UNDEF]'
Fri May 28 22:59:11 2004 bind_local = ENABLED
Fri May 28 22:59:11 2004 dev = 'tun'
Fri May 28 22:59:11 2004 dev_type = '[UNDEF]'
Fri May 28 22:59:11 2004 dev_node = '[UNDEF]'
Fri May 28 22:59:11 2004 tun_ipv6 = DISABLED
Fri May 28 22:59:11 2004 ifconfig_local = '1.1.5.1'
Fri May 28 22:59:11 2004 ifconfig_remote_netmask = '1.1.5.2'
Fri May 28 22:59:11 2004 ifconfig_noexec = DISABLED
Fri May 28 22:59:11 2004 ifconfig_nowarn = DISABLED
Fri May 28 22:59:11 2004 shaper = 0
Fri May 28 22:59:11 2004 tun_mtu = 1434
Fri May 28 22:59:11 2004 tun_mtu_defined = ENABLED
Fri May 28 22:59:11 2004 link_mtu = 1500
Fri May 28 22:59:11 2004 link_mtu_defined = DISABLED
Fri May 28 22:59:11 2004 tun_mtu_extra = 0
Fri May 28 22:59:11 2004 tun_mtu_extra_defined = DISABLED
Fri May 28 22:59:11 2004 fragment = 0
Fri May 28 22:59:11 2004 mtu_discover_type = -1
Fri May 28 22:59:11 2004 mtu_test = 0
Fri May 28 22:59:11 2004 mlock = DISABLED
Fri May 28 22:59:11 2004 inactivity_timeout = 0
Fri May 28 22:59:11 2004 ping_send_timeout = 30
Fri May 28 22:59:11 2004 ping_rec_timeout = 0
Fri May 28 22:59:11 2004 ping_rec_timeout_action = 0
Fri May 28 22:59:11 2004 ping_timer_remote = DISABLED
Fri May 28 22:59:11 2004 persist_tun = DISABLED
Fri May 28 22:59:11 2004 persist_local_ip = DISABLED
Fri May 28 22:59:11 2004 persist_remote_ip = DISABLED
Fri May 28 22:59:11 2004 persist_key = DISABLED
Fri May 28 22:59:11 2004 mssfix = 1450
Fri May 28 22:59:11 2004 passtos = DISABLED
Fri May 28 22:59:11 2004 resolve_retry_seconds = 0
Fri May 28 22:59:11 2004 connect_retry_seconds = 5
Fri May 28 22:59:11 2004 username = '[UNDEF]'
Fri May 28 22:59:11 2004 groupname = '[UNDEF]'
Fri May 28 22:59:11 2004 chroot_dir = '[UNDEF]'
Fri May 28 22:59:11 2004 cd_dir = '[UNDEF]'
Fri May 28 22:59:11 2004 writepid = '[UNDEF]'
Fri May 28 22:59:11 2004 up_script = '[UNDEF]'
Fri May 28 22:59:11 2004 down_script = '[UNDEF]'
Fri May 28 22:59:11 2004 up_restart = DISABLED
Fri May 28 22:59:11 2004 daemon = DISABLED
Fri May 28 22:59:11 2004 inetd = 0
Fri May 28 22:59:11 2004 log = DISABLED
Fri May 28 22:59:11 2004 nice = 0
Fri May 28 22:59:11 2004 verbosity = 4
Fri May 28 22:59:11 2004 mute = 0
Fri May 28 22:59:11 2004 gremlin = DISABLED
Fri May 28 22:59:11 2004 occ = ENABLED
Fri May 28 22:59:11 2004 rcvbuf = 65536
Fri May 28 22:59:11 2004 sndbuf = 65536
Fri May 28 22:59:11 2004 http_proxy_server = '[UNDEF]'
Fri May 28 22:59:11 2004 http_proxy_port = 0
Fri May 28 22:59:11 2004 http_proxy_auth_method = '[UNDEF]'
Fri May 28 22:59:11 2004 http_proxy_auth_file = '[UNDEF]'
Fri May 28 22:59:11 2004 http_proxy_retry = DISABLED
Fri May 28 22:59:11 2004 socks_proxy_server = '[UNDEF]'
Fri May 28 22:59:11 2004 socks_proxy_port = 0
Fri May 28 22:59:11 2004 socks_proxy_retry = DISABLED
Fri May 28 22:59:11 2004 comp_lzo = DISABLED
Fri May 28 22:59:11 2004 comp_lzo_adaptive = ENABLED
Fri May 28 22:59:11 2004 route_script = '[UNDEF]'
Fri May 28 22:59:11 2004 route_default_gateway = '[UNDEF]'
Fri May 28 22:59:11 2004 route_noexec = DISABLED
Fri May 28 22:59:11 2004 route_delay = 0
Fri May 28 22:59:11 2004 route_delay_defined = DISABLED
Fri May 28 22:59:11 2004 shared_secret_file = '/.local/var/service/ovpn-1/key'
Fri May 28 22:59:11 2004 key_direction = 0
Fri May 28 22:59:11 2004 ciphername_defined = ENABLED
Fri May 28 22:59:11 2004 ciphername = 'BF-CBC'
Fri May 28 22:59:11 2004 authname_defined = ENABLED
Fri May 28 22:59:11 2004 authname = 'SHA1'
Fri May 28 22:59:11 2004 keysize = 0
Fri May 28 22:59:11 2004 replay = ENABLED
Fri May 28 22:59:11 2004 replay_window = 64
Fri May 28 22:59:11 2004 replay_time = 15
Fri May 28 22:59:11 2004 packet_id_file = '[UNDEF]'
Fri May 28 22:59:11 2004 use_iv = ENABLED
Fri May 28 22:59:11 2004 test_crypto = DISABLED
Fri May 28 22:59:11 2004 tls_server = DISABLED
Fri May 28 22:59:11 2004 tls_client = DISABLED
Fri May 28 22:59:11 2004 key_method = 2
Fri May 28 22:59:11 2004 ca_file = '[UNDEF]'
Fri May 28 22:59:11 2004 dh_file = '[UNDEF]'
Fri May 28 22:59:11 2004 cert_file = '[UNDEF]'
Fri May 28 22:59:11 2004 priv_key_file = '[UNDEF]'
Fri May 28 22:59:11 2004 cipher_list = '[UNDEF]'
Fri May 28 22:59:11 2004 tls_verify = '[UNDEF]'
Fri May 28 22:59:11 2004 tls_remote = '[UNDEF]'
Fri May 28 22:59:11 2004 crl_file = '[UNDEF]'
Fri May 28 22:59:11 2004 tls_timeout = 2
Fri May 28 22:59:11 2004 renegotiate_bytes = 0
Fri May 28 22:59:11 2004 renegotiate_packets = 0
Fri May 28 22:59:11 2004 renegotiate_seconds = 3600
Fri May 28 22:59:11 2004 handshake_window = 60
Fri May 28 22:59:11 2004 transition_window = 3600
Fri May 28 22:59:11 2004 single_session = DISABLED
Fri May 28 22:59:11 2004 tls_auth_file = '[UNDEF]'
Fri May 28 22:59:11 2004 pull = DISABLED
Fri May 28 22:59:11 2004 ifconfig_pool_defined = DISABLED
Fri May 28 22:59:11 2004 ifconfig_pool_start = 0.0.0.0
Fri May 28 22:59:11 2004 ifconfig_pool_end = 0.0.0.0
Fri May 28 22:59:11 2004 n_bcast_buf = 256
Fri May 28 22:59:11 2004 real_hash_size = 256
Fri May 28 22:59:11 2004 virtual_hash_size = 256
Fri May 28 22:59:11 2004 client_connect_script = '[UNDEF]'
Fri May 28 22:59:11 2004 client_disconnect_script = '[UNDEF]'
Fri May 28 22:59:11 2004 client_config_dir = '[UNDEF]'
Fri May 28 22:59:11 2004 tmp_dir = '[UNDEF]'
Fri May 28 22:59:11 2004 push_ifconfig_defined = DISABLED
Fri May 28 22:59:11 2004 push_ifconfig_local = 0.0.0.0
Fri May 28 22:59:11 2004 push_ifconfig_remote_netmask = 0.0.0.0
Fri May 28 22:59:11 2004 enable_c2c = DISABLED
Fri May 28 22:59:11 2004 cf_max = 0
Fri May 28 22:59:11 2004 cf_per = 0
Fri May 28 22:59:11 2004 OpenVPN 2.0_beta1 i386-pc-linux-gnu [SSL] [LZO] built
on May 28 2004
Fri May 28 22:59:11 2004 Static Encrypt: Cipher 'BF-CBC' initialized with 128
bit key
Fri May 28 22:59:11 2004 Static Encrypt: Using 160 bit message hash 'SHA1' for
HMAC authentication
Fri May 28 22:59:11 2004 Static Decrypt: Cipher 'BF-CBC' initialized with 128
bit key
Fri May 28 22:59:11 2004 Static Decrypt: Using 160 bit message hash 'SHA1' for
HMAC authentication
Fri May 28 22:59:11 2004 WARNING: normally if you use --mssfix and/or
--fragment, you should also set --tun-mtu 1500 (currently it is 1434)
Fri May 28 22:59:11 2004 TUN/TAP device tun0 opened
Fri May 28 22:59:11 2004 TUN/TAP TX queue length set to 100
Fri May 28 22:59:11 2004 /bin/ifconfig tun0 1.1.5.1 pointopoint 1.1.5.2 mtu 1434
Fri May 28 22:59:11 2004 Data Channel MTU parms [ L:1478 D:1450 EF:44 EB:0 ET:0
EL:0 ]
Fri May 28 22:59:11 2004 Local Options String: 'V3,dev-type tun,link-mtu
1478,tun-mtu 1434,proto UDPv4,ifconfig 1.1.5.2 1.1.5.1,cipher BF-CBC,
Fri May 28 22:59:11 2004 Expected Remote Options String: 'V3,dev-type
tun,link-mtu 1478,tun-mtu 1434,proto UDPv4,ifconfig 1.1.5.1 1.1.5.2,ciph
Fri May 28 22:59:11 2004 Local Options hash (VER=V3): '5194cd41'
Fri May 28 22:59:11 2004 Expected Remote Options hash (VER=V3): 'e341fa03'
Fri May 28 22:59:11 2004 Socket Buffers: R=[110592->131072] S=[110592->131072]
Fri May 28 22:59:11 2004 UDPv4 link local (bound): 1.1.4.1:8002
Fri May 28 22:59:11 2004 UDPv4 link remote: 1.1.4.2:8002
Fri May 28 22:59:11 2004 EVENT event_timeout_wakeup (2/2)
Fri May 28 22:59:11 2004 EVENT event_timeout_trigger (30)
Fri May 28 22:59:11 2004 PING: SENT
Fri May 28 22:59:11 2004 TIMER: coarse timer wakeup 2 seconds
Fri May 28 22:59:11 2004 RANDOM USEC=670225
Fri May 28 22:59:11 2004 write UDPv4 []: Network is unreachable (code=101)
Fri May 28 22:59:12 2004 write UDPv4 []: Network is unreachable (code=101)
Fri May 28 22:59:12 2004 write UDPv4 []: Network is unreachable (code=101)
Fri May 28 22:59:12 2004 write UDPv4 []: Network is unreachable (code=101)
Fri May 28 22:59:13 2004 EVENT event_timeout_trigger (2)
Fri May 28 22:59:13 2004 EVENT event_timeout_wakeup (2/2)
Fri May 28 22:59:13 2004 PING: c->c2.to_link.len <> 0
Fri May 28 22:59:13 2004 TIMER: coarse timer wakeup 2 seconds
Fri May 28 22:59:13 2004 write UDPv4 []: Network is unreachable (code=101)
Fri May 28 22:59:15 2004 EVENT event_timeout_trigger (2)
Fri May 28 22:59:15 2004 EVENT event_timeout_wakeup (2/2)
Fri May 28 22:59:15 2004 PING: c->c2.to_link.len <> 0
Fri May 28 22:59:15 2004 TIMER: coarse timer wakeup 2 seconds
Fri May 28 22:59:15 2004 Peer Connection Initiated with 1.1.4.2:8002
Fri May 28 22:59:18 2004 EVENT event_timeout_trigger (2)
Fri May 28 22:59:18 2004 EVENT event_timeout_wakeup (2/2)
Fri May 28 22:59:18 2004 PING: !event_timeout_trigger(1085774355,2)
Fri May 28 22:59:18 2004 TIMER: coarse timer wakeup 2 seconds
Fri May 28 22:59:21 2004 EVENT event_timeout_trigger (10)
Fri May 28 22:59:21 2004 EVENT event_timeout_wakeup (10/10)
Fri May 28 22:59:21 2004 PING: !event_timeout_trigger(1085774355,10)
Fri May 28 22:59:21 2004 TIMER: coarse timer wakeup 10 seconds
Fri May 28 22:59:21 2004 RANDOM USEC=682209
Fri May 28 22:59:32 2004 EVENT event_timeout_wakeup (27/30)
Fri May 28 22:59:32 2004 PING: !event_timeout_trigger(1085774369,27)
Fri May 28 22:59:32 2004 TIMER: coarse timer wakeup 27 seconds
Fri May 28 22:59:32 2004 RANDOM USEC=168112
Fri May 28 22:59:43 2004 RANDOM USEC=310535
Fri May 28 22:59:53 2004 RANDOM USEC=567338
Fri May 28 22:59:59 2004 PING: c->c2.to_link.len <> 0
Fri May 28 22:59:59 2004 TIMER: coarse timer wakeup 31536000 seconds
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 22:59:59 2004 PING: select timeout=31536000
Fri May 28 23:00:04 2004 RANDOM USEC=262969
Fri May 28 23:00:04 2004 PING: select timeout=31535995
Fri May 28 23:00:04 2004 PING: select timeout=31535995
Fri May 28 23:00:04 2004 PING: select timeout=31535995
Fri May 28 23:00:04 2004 PING: select timeout=31535995
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:10 2004 PING: select timeout=31535989
Fri May 28 23:00:14 2004 RANDOM USEC=111391
Fri May 28 23:00:14 2004 PING: select timeout=31535985
Fri May 28 23:00:14 2004 PING: select timeout=31535985
Fri May 28 23:00:14 2004 PING: select timeout=31535985
Fri May 28 23:00:14 2004 PING: select timeout=31535985
and so on. openvpn will abstain from sending pings now
for eaxctly 365 days (I think :). Further log contains
records of two kinds only:
Fri May 28 23:24:36 2004 RANDOM USEC=565465 (random)
and
Fri May 28 23:24:36 2004 PING: select timeout=31534523 (counting down)
Here is how I start openvpn:
openvpn \
--secret key \
--dev tun \
--proto udp \
--port 8002 \
--local 1.1.4.1 \
--remote 1.1.4.2 \
--ifconfig 1.1.5.1 1.1.5.2 \
--tun-mtu 1434 \
--ping 30 \
--verb 4 \
NB: I run ntp (strata=3) on this box.
--
vda
