Denis,
I think I see the bug:
/*
* Should we ping the remote?
*/
static inline void
check_ping_send (struct context *c)
{
void check_ping_send_dowork (struct context *c);
if (c->options.ping_send_timeout
&& !c->c2.to_link.len
&& event_timeout_trigger (&c->c2.ping_send_interval,
&c->c2.timeval))
check_ping_send_dowork (c);
}
if c->c2.to_link.len is nonzero (which happens if the outgoing TCP/UDP buffer
is already full) then event_timeout_trigger is not called, meaning that
c->c2.timeval (the earliest wakeup) is not updated. The solution is probably
to pass the boolean !c->c2.to_link.len as another parm to
event_timeout_trigger so that it can still update c->c2.timeval even if the
outgoing buffer is full. I will fix in b3.
Thanks for noticing the bug and for coding the instrumentation to isolate it.
James
James Yonan <[email protected]> said:
> Denis,
>
> That looks like a possible bug in the coarse timer update logic. The coarse
> timer deals with events scheduled at a resolution denoted by an integer number
> of seconds, such as pings. A timeout of one year is used as kind of
> "effectively infinite" time interval. If you see this large timeout, it means
> that the ping event is losing its place in the coarse timer event queue --
> probably a bug.
>
> James
>
> Denis Vlasenko <[email protected]> said:
>
> > 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
> >
> >
> >
> > -------------------------------------------------------
> > This SF.Net email is sponsored by: Oracle 10g
> > Get certified on the hottest thing ever to hit the market... Oracle 10g.
> > Take an Oracle 10g class now, and we'll give you the exam FREE.
> > http://ads.osdn.com/?ad_id=3149&alloc_id=8166&op=click
> > _______________________________________________
> > Openvpn-devel mailing list
> > [email protected]
> > https://lists.sourceforge.net/lists/listinfo/openvpn-devel
> >
>
>
>
> --
>
>
>
>
>
> -------------------------------------------------------
> This SF.Net email is sponsored by: Oracle 10g
> Get certified on the hottest thing ever to hit the market... Oracle 10g.
> Take an Oracle 10g class now, and we'll give you the exam FREE.
> http://ads.osdn.com/?ad_id=3149&alloc_id=8166&op=click
> _______________________________________________
> Openvpn-devel mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/openvpn-devel
>
--
