[OpenVPN home] [Date Prev] [Date Index] [Date Next]
[OpenVPN mailing lists] [Thread Prev] [Thread Index] [Thread Next]
Google
 
Web openvpn.net

Re: [Openvpn-devel] [BUG] sometimes --ping 30 stops: select() timeout=31536000 seconds (exactly one year)!


  • Subject: Re: [Openvpn-devel] [BUG] sometimes --ping 30 stops: select() timeout=31536000 seconds (exactly one year)!
  • From: "James Yonan" <jim@xxxxxxxxx>
  • Date: Fri, 28 May 2004 21:15:40 -0000

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 <vda@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx> 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
> Openvpn-devel@xxxxxxxxxxxxxxxxxxxxx
> https://lists.sourceforge.net/lists/listinfo/openvpn-devel
> 



-- 




____________________________________________
Openvpn-devel mailing list
Openvpn-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.sourceforge.net/lists/listinfo/openvpn-devel