logging update
[pingcheck] / src / host / pingscheduler.cpp
1 /*
2 The software in this package is distributed under the GNU General
3 Public License version 2 (with a special exception described below).
4
5 A copy of GNU General Public License (GPL) is included in this distribution,
6 in the file COPYING.GPL.
7
8 As a special exception, if other files instantiate templates or use macros
9 or inline functions from this file, or you compile this file and link it
10 with other works to produce a work based on this file, this file
11 does not by itself cause the resulting work to be covered
12 by the GNU General Public License.
13
14 However the source code for this file must still be made available
15 in accordance with section (3) of the GNU General Public License.
16
17 This exception does not invalidate any other reasons why a work based
18 on this file might be covered by the GNU General Public License.
19 */
20 #include "host/pingscheduler.h"
21
22 #include <iostream>
23 #include <limits>
24
25 #include <boost/bind.hpp>
26 #include <boost/foreach.hpp>
27
28 #include <logfunc.hpp>
29
30 #include "boost_assert_handler.h"
31 #include "host/pingerfactory.h"
32 #include "dns/dnsmaster.h"
33 #include "icmp/icmppinger.h"
34 #include "link/linkstatus.h"
35
36 using namespace std;
37 using boost::asio::io_service;
38 using boost::bind;
39 using boost::date_time::time_resolution_traits_adapted64_impl;
40 using boost::posix_time::microsec_clock;
41 using boost::posix_time::ptime;
42 using boost::posix_time::seconds;
43 using boost::shared_ptr;
44 using I2n::Logger::GlobalLogger;
45
46 //-----------------------------------------------------------------------------
47 // PingScheduler
48 //-----------------------------------------------------------------------------
49
50 /**
51  * @brief Parameterized constructor.
52  *
53  * @param io_serv The one @c io_serv object that controls async processing
54  * @param network_interface The name of the network interface sending the pings.
55  * @param destination_address The remote address to ping.
56  * @param destination_port The remote port to ping.
57  * @param ping_protocol_list A list of protocols to use.
58  * @param ping_interval_in_sec Amount of time between each ping.
59  * @param ping_fail_percentage_limit Maximum amount of pings that can fail.
60  * @param link_analyzer The object to monitor the link status.
61  * @param first_delay Delay in seconds from start_pinging to first ping attempt
62  */
63 PingScheduler::PingScheduler(
64         const IoServiceItem io_serv,
65         const string &network_interface,
66         const string &destination_address,
67         const uint16_t destination_port,
68         const PingProtocolList &ping_protocol_list,
69         const long ping_interval_in_sec,
70         const int ping_fail_percentage_limit,
71         const int ping_reply_timeout,
72         LinkStatusItem link_analyzer,
73         const int first_delay
74
75 ) :
76     IoService( io_serv ),
77     NetworkInterfaceName( network_interface ),
78     DestinationAddress( destination_address ),
79     DestinationPort( destination_port ),
80     Protocols( ping_protocol_list ),
81     ProtocolIter(),
82     PingIntervalInSec( ping_interval_in_sec ),
83     FirstDelay( first_delay ),
84     NextPingTimer( *io_serv ),
85     TimeSentLastPing( microsec_clock::universal_time() ),
86     PingReplyTimeout( ping_reply_timeout ),
87     HostAnalyzer( destination_address, ping_fail_percentage_limit,
88                   link_analyzer ),
89     Resolver(),
90     Ping(),
91     WantToPing( false ),
92     LogPrefix(),
93     ContinueOnOutdatedIps( false )
94 {
95     BOOST_ASSERT( !network_interface.empty() );
96     BOOST_ASSERT( !destination_address.empty() );
97     BOOST_ASSERT( ( 0 < destination_port ) &&
98                   ( destination_port < numeric_limits<uint16_t>::max() ) );
99     BOOST_ASSERT( 0 < ping_interval_in_sec );
100     BOOST_ASSERT( (0 <= ping_fail_percentage_limit) &&
101                   ( ping_fail_percentage_limit <= 100) );
102
103     update_log_prefix();
104
105     init_ping_protocol();
106 }
107
108 /**
109  * @brief Destructor.
110  */
111 PingScheduler::~PingScheduler()
112 {
113 }
114
115 void PingScheduler::stop_pinging()
116 {
117     // stop pinger and resolver
118     GlobalLogger.debug() << LogPrefix << "scheduler: stop pinging";
119     Ping->stop_pinging();
120     cancel_resolve(true);
121
122     // now cancel the own timer in case that pinger cancelation called callback
123     GlobalLogger.debug() << LogPrefix << "scheduler: cancel timer";
124     NextPingTimer.cancel();
125 }
126
127 /**
128  * @brief Start into infinite loop of calls to ping
129  *
130  * Does not start yet but set NextPingTimer (possibly to 0), so action starts
131  *   when io_service is started
132  */
133 void PingScheduler::start_pinging()
134 {
135     if ( FirstDelay > 0 )
136         GlobalLogger.info() << LogPrefix << "Delaying first ping by "
137                                          << FirstDelay << "s";
138     else
139         GlobalLogger.info() << LogPrefix << "Schedule ping as soon as possible";
140
141     (void) NextPingTimer.expires_from_now( seconds( FirstDelay ) );
142     NextPingTimer.async_wait( bind( &PingScheduler::ping, this,
143                                           boost::asio::placeholders::error ) );
144 }
145
146
147 /**
148  * @brief call Ping::ping and schedule a call to ping_done_handler when finished
149  */
150 void PingScheduler::ping(const boost::system::error_code &error)
151 {
152     if ( error )
153     {   // get here, e.g. by NextPingTimer.cancel in stop_pinging
154         if ( error ==  boost::asio::error::operation_aborted )
155             GlobalLogger.error() << LogPrefix << "Timer for ping was cancelled!"
156                                  << " --> Stopping";
157         else
158             GlobalLogger.error() << LogPrefix << "Received error " << error
159                                  << " waiting for ping! Stopping";
160         return;
161     }
162
163     // ping as soon as dns is ready
164     WantToPing = true;
165     ping_when_ready();
166 }
167
168
169 void PingScheduler::ping_when_ready()
170 {
171     if ( !WantToPing )
172     {
173         GlobalLogger.info() << LogPrefix << "waiting for ping request "
174             << "(should take no more than than " << PingIntervalInSec << "s)";
175         return;
176     }
177     else if ( Resolver && Resolver->is_resolving() )
178     {
179         GlobalLogger.info() << LogPrefix << "waiting for DNS to finish";
180         return;
181     }
182     else if ( !Resolver )
183         // should not happen, but check anyway
184         GlobalLogger.warning() << LogPrefix << "Have no resolver!";
185
186     GlobalLogger.info() << LogPrefix << "start ping";
187     WantToPing = false;
188
189     // try to get an up-to-date IP (ContinueOnOutdatedIps may only be set
190     //   because a CNAME was out of date -- IPs may still be current)
191     HostAddress ip = Resolver->get_next_ip();
192
193     if ( !ip.is_valid() )
194     {   // this can happen in 2 cases: if ContinueOnOutdatedIps==true
195         // or when ip went out of date between resolve and now
196         // --> try to use outdated IP
197         GlobalLogger.info() << LogPrefix << "Checking for outdated IPs";
198         bool check_up_to_date = false;
199         ip = Resolver->get_next_ip(check_up_to_date);
200     }
201     if ( !ip.is_valid() )
202     {   // still no valid IP --> should not happen
203         GlobalLogger.error() << LogPrefix << "Not even outdated IP to ping "
204              << "-- this should not have happened!! Treat like a failed ping.";
205         if (DnsMaster::get_instance()->get_resolved_ip_ttl_threshold() > 0)
206             GlobalLogger.warning() << LogPrefix << "This probably happened "
207                 << "because you specified a TTL threshold > 0 but resolving"
208                 << " had no effect on TTLs since external cache is only "
209                 << "updated when TTL=0 is reached.";
210
211         // skip the ping and directly call ping_done_handler
212         ping_done_handler(false);
213     }
214     else
215     {
216         uint32_t ttl = ip.get_ttl().get_updated_value();
217         std::string expiry;
218         if (ttl == 0)
219             expiry = "out of date!";
220         else
221         {
222             boost::posix_time::ptime now =
223                                   boost::posix_time::second_clock::local_time();
224             expiry = boost::posix_time::to_simple_string(now + seconds(ttl));
225         }
226
227         GlobalLogger.info() << LogPrefix << "pinging IP " << ip.get_ip()
228             << " with TTL " << ttl << "s (" << expiry << ")";
229         Ping->ping( ip.get_ip(),
230                     DestinationPort,
231                     boost::bind(&PingScheduler::ping_done_handler, this, _1) );
232     }
233 }
234
235
236 //------------------------------------------------------------------------------
237 // Post Processing of Ping result
238 //------------------------------------------------------------------------------
239
240 /**
241  * @brief called when Ping::ping is done; calls functions to update
242  *   statistics, ping interval and elapsed time;
243  *   schedules a call to ping, thereby closing the loop
244  */
245 void PingScheduler::ping_done_handler( const bool ping_success )
246 {
247     GlobalLogger.info() << LogPrefix << "Ping done with success = "
248                                      << ping_success;
249
250     // post-processing
251     // You must call these 3 methods exactly in this order
252     // TODO Fix this method, once it has a semantic dependency with the
253     // update_ping_statistics method, because it depends on the PingAnalyzer
254     // statistics to update the exceeded_ping_failed_limit
255     HostAnalyzer.update_ping_statistics( ping_success );
256     update_ping_interval();
257     update_ping_elapsed_time();
258
259     if (ping_success)
260     {   // reset ContinueOnOutdatedIps
261         ContinueOnOutdatedIps = false;
262         update_log_prefix();
263     }
264
265     // get next protocol, possibly start resolving IPs
266     update_ping_protocol();
267
268     // schedule next ping
269     (void) NextPingTimer.expires_from_now( seconds( PingIntervalInSec ) );
270     NextPingTimer.async_wait( bind( &PingScheduler::ping, this,
271                                          boost::asio::placeholders::error ) );
272 }
273
274 void PingScheduler::update_ping_interval()
275 {
276     // have to ping more often?
277     if ( HostAnalyzer.exceeded_ping_failed_limit() )
278     {
279         PingIntervalInSec.speed_up();
280
281         GlobalLogger.debug() << LogPrefix << "- Speeding up ping interval to: "
282                              << PingIntervalInSec << "s";
283     }
284     else
285     {
286         PingIntervalInSec.back_to_original();
287
288         GlobalLogger.debug() << LogPrefix << "- Stick to the original ping "
289                              << "interval: " << PingIntervalInSec << "s";
290     }
291 }
292
293 void PingScheduler::update_ping_elapsed_time()
294 {
295     ptime now = microsec_clock::universal_time();
296     time_resolution_traits_adapted64_impl::int_type elapsed_time_in_sec =
297             (now - TimeSentLastPing).total_seconds();
298     GlobalLogger.debug() << LogPrefix << "- Time elapsed since last ping: "
299                                       << elapsed_time_in_sec << "s";
300
301     TimeSentLastPing = microsec_clock::universal_time();
302 }
303
304
305 //------------------------------------------------------------------------------
306 // Ping Protocol Rotation
307 //------------------------------------------------------------------------------
308
309 void PingScheduler::init_ping_protocol()
310 {
311     ProtocolIter = Protocols.end();
312     get_next_ping_protocol();
313 }
314
315 void PingScheduler::update_ping_protocol()
316 {
317     if ( can_change_ping_protocol() )
318     {
319         get_next_ping_protocol();
320     }
321 }
322
323 void PingScheduler::get_next_ping_protocol()
324 {
325     GlobalLogger.debug() << LogPrefix
326         << "------------------------------------------------------------------";
327     ++ProtocolIter;
328     if (ProtocolIter == Protocols.end())
329         ProtocolIter = Protocols.begin();
330     PingProtocol ping_protocol = *ProtocolIter;
331     // --> ProtocolIter still points to currently used protocol which is
332     //     required in dns_resolve_callback
333
334     if (Ping)
335         Ping->stop_pinging();
336
337     Ping = PingerFactory::createPinger(ping_protocol, IoService,
338                                        NetworkInterfaceName, PingReplyTimeout);
339
340     update_dns_resolver( ping_protocol );
341
342 }
343
344 bool PingScheduler::can_change_ping_protocol() const
345 {
346     // TODO can_change_ping_protocol() and get_next_ping_protocol() may be
347     // implemented in a Algorithm class that can be exchanged in this class to
348     // provide an algorithm neutral class
349     return true;
350 }
351
352 //------------------------------------------------------------------------------
353 // DNS host name resolution
354 //------------------------------------------------------------------------------
355
356 // show "!" after host name if running on outdated IPs
357 void PingScheduler::update_log_prefix()
358 {
359     std::stringstream temp;
360     temp << "Sched(" << DestinationAddress;
361     if (ContinueOnOutdatedIps)
362         temp << "!";
363     temp << "): ";
364     LogPrefix = temp.str();
365 }
366
367 void PingScheduler::update_dns_resolver( PingProtocol current_protocol )
368 {
369     if (Resolver && Resolver->is_resolving())
370         cancel_resolve(false);
371
372     if (ContinueOnOutdatedIps)
373     {
374         ContinueOnOutdatedIps = false;
375         update_log_prefix();
376     }
377
378     // DNS master caches created resolvers and resolved IPs, so this will
379     // probably just return an existing resolver with already resolved IPs for
380     // requested protocol ( ICMP/TCP is ignored, only IPv4/v6 is important)
381     Resolver = DnsMaster::get_instance()->get_resolver_for(DestinationAddress,
382                                                            current_protocol);
383
384     // get number of up-to-date IPs
385     // TODO should check here, if they will be up to date in PingIntervalInSec
386     bool check_up_to_date = true;
387     int ip_count = Resolver->get_resolved_ip_count(check_up_to_date);
388     if (ip_count > 0)
389     {
390         GlobalLogger.info() << LogPrefix << "Set resolved_ip_count to "
391             << ip_count << " (IPs may be outdated=" << !check_up_to_date << ")";
392         HostAnalyzer.set_resolved_ip_count( ip_count );
393
394         if (Resolver->is_resolving())
395             GlobalLogger.warning() << LogPrefix << "have up to date IPs but "
396                 << "resolver seems to be resolving all the same... "
397                 << "Start pinging anyway!";
398         ping_when_ready();
399     }
400     else
401     {
402         GlobalLogger.info() << LogPrefix
403                             << "No up-to-date IPs --> start resolve";
404         start_resolving_ping_address();
405         // set resolved_ip_count will be called in resolve callback
406     }
407 }
408
409 void PingScheduler::start_resolving_ping_address()
410 {
411     Resolver->async_resolve( boost::bind(&PingScheduler::dns_resolve_callback,
412                                           this, _1, _2) );
413 }
414
415 void PingScheduler::dns_resolve_callback(const bool was_success,
416                                          const int recursion_count)
417 {
418     GlobalLogger.info() << LogPrefix << "dns resolution finished "
419                         << "with success = " << was_success << " "
420                         << "after " << recursion_count << " recursions";
421
422     if ( was_success )
423     {
424         // trust that a successfull DNS resolve means we have an IP with TTL>0
425         int ip_count = Resolver->get_resolved_ip_count(!ContinueOnOutdatedIps);
426         if (ip_count == 0)
427         {   // this will create trouble in HostAnalyzer
428             GlobalLogger.warning() << LogPrefix
429                 << "Should not have reached this case: resolve was "
430                 << "successfull but still have no IPs (up-to-date="
431                 << !ContinueOnOutdatedIps << ")!";
432             if (DnsMaster::get_instance()->get_resolved_ip_ttl_threshold() > 0)
433                 GlobalLogger.warning() << LogPrefix << "This probably happened "
434                     << "because you specified a TTL threshold > 0 but resolving"
435                     << " had no effect on TTLs since external cache is only "
436                     << "updated when TTL=0 is reached.";
437         }
438         else
439         {
440             GlobalLogger.info() << LogPrefix << "Set resolved_ip_count to "
441                 << ip_count << " (IPs may be outdated="
442                 << ContinueOnOutdatedIps << ") --> could ping now";
443             HostAnalyzer.set_resolved_ip_count( ip_count );
444         }
445         ping_when_ready();
446     }
447     else
448     {   // host name resolution failed; try again bypassing first outdated CNAME
449         // or using cached IP
450         ContinueOnOutdatedIps = true;
451         update_log_prefix();
452
453         std::string skip_host = Resolver->get_skip_cname();
454
455         if (skip_host.empty())
456         {   // continue with IP
457             GlobalLogger.notice() << LogPrefix << "DNS failed, "
458                 << "try anyway with cached data";
459
460             int ip_count = Resolver->get_resolved_ip_count(false);
461             GlobalLogger.info() << LogPrefix << "Set resolved_ip_count to "
462                 << ip_count << " (IPs may be outdated=" << true << ")";
463             HostAnalyzer.set_resolved_ip_count( ip_count );
464
465             ping_when_ready();
466         }
467         else
468         {   // have CNAME to continue
469             GlobalLogger.notice() << LogPrefix << "DNS failed, "
470                 << "try again skipping a CNAME and resolving "
471                 << skip_host << " directly";
472
473             cancel_resolve(false);
474
475             // now create new resolver
476             Resolver = DnsMaster::get_instance()
477                                    ->get_resolver_for(skip_host, *ProtocolIter);
478             start_resolving_ping_address();
479         }
480     }
481 }
482
483 /**
484  * cancel resolver if force_cancel or if it is not resolving DestinationAddress
485  *
486  * Resolvers have a life on their own: they are cached by DnsMaster so never go
487  *   out of scope and even after calling callbacks, there might still be a
488  *   longterm timer active to re-try resolving.
489  * We want to cancel that long-term timer only if the Resolver is not for our
490  *   real, original DestinationAddress but a CNAME, which can happen when trying
491  *   to skip cnames and working on out-dated IPs
492  */
493 void PingScheduler::cancel_resolve(const bool force_cancel)
494 {
495     if (force_cancel)
496     {
497         GlobalLogger.info() << "Cancelling resolver (forced)";
498         Resolver->cancel_resolve();
499     }
500     else if ( Resolver->get_hostname() == DestinationAddress )
501         GlobalLogger.info() << LogPrefix
502                             << "Leave original resolver active in background";
503     else
504     {
505         GlobalLogger.info() << LogPrefix << "Cancel resolver for "
506             << Resolver->get_hostname() << " since is not the original "
507             << DestinationAddress;
508         Resolver->cancel_resolve();
509     }
510 }
511