main_thread.cpp

00001 
00002 /***************************************************************************
00003  *  main_thread.cpp - Fawkes main thread
00004  *
00005  *  Created: Thu Nov  2 16:47:50 2006
00006  *  Copyright  2006-2009  Tim Niemueller [www.niemueller.de]
00007  *
00008  ****************************************************************************/
00009 
00010 /*  This program is free software; you can redistribute it and/or modify
00011  *  it under the terms of the GNU General Public License as published by
00012  *  the Free Software Foundation; either version 2 of the License, or
00013  *  (at your option) any later version. A runtime exception applies to
00014  *  this software (see LICENSE.GPL_WRE file mentioned below for details).
00015  *
00016  *  This program is distributed in the hope that it will be useful,
00017  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
00018  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
00019  *  GNU Library General Public License for more details.
00020  *
00021  *  Read the full text in the LICENSE.GPL_WRE file in the doc directory.
00022  */
00023 
00024 #include <mainapp/main_thread.h>
00025 
00026 #include <mainapp/network_manager.h>
00027 #include <mainapp/thread_manager.h>
00028 
00029 #include <core/threading/interruptible_barrier.h>
00030 #include <core/exceptions/system.h>
00031 #include <config/sqlite.h>
00032 #include <config/net_handler.h>
00033 #include <utils/logging/multi.h>
00034 #include <utils/logging/console.h>
00035 #include <utils/logging/liblogger.h>
00036 #include <utils/logging/factory.h>
00037 #include <utils/system/argparser.h>
00038 #include <utils/time/clock.h>
00039 #include <utils/time/wait.h>
00040 #include <netcomm/utils/network_logger.h>
00041 
00042 #include <blackboard/local.h>
00043 #include <aspect/inifin.h>
00044 #include <plugin/manager.h>
00045 #include <plugin/loader.h>
00046 #include <plugin/net/handler.h>
00047 
00048 #include <cstdio>
00049 #include <cstring>
00050 #include <cerrno>
00051 #include <sys/types.h>
00052 #include <sys/stat.h>
00053 
00054 #include <core/macros.h>
00055 
00056 using namespace fawkes;
00057 
00058 /** @class FawkesMainThread mainapp/main_thread.h
00059  * Fawkes main thread.
00060  * This thread initializes all important stuff like the BlackBoard,
00061  * handles plugins and wakes up threads at defined hooks.
00062  *
00063  * @author Tim Niemueller
00064  */
00065 
00066 
00067 /** Constructor.
00068  * @param argp argument parser
00069  */
00070 FawkesMainThread::FawkesMainThread(ArgumentParser *argp)
00071   : Thread("FawkesMainThread")
00072 {
00073   __blackboard        = NULL;
00074   __config_nethandler = NULL;
00075   __config            = NULL;
00076   __plugin_manager    = NULL;
00077   __network_manager   = NULL;
00078   __thread_manager    = NULL;
00079   __aspect_inifin     = NULL;
00080 
00081   __mainloop_thread   = NULL;
00082   __mainloop_mutex    = new Mutex();
00083   __mainloop_barrier  = new InterruptibleBarrier(__mainloop_mutex, 2);
00084 
00085   __plugin_mutex      = new Mutex();
00086 
00087   __argp = argp;
00088 
00089   /* Logging stuff */
00090   const char *tmp;
00091   Logger::LogLevel log_level = Logger::LL_DEBUG;
00092   if ( __argp->has_arg("q") ) {
00093     log_level = Logger::LL_INFO;
00094     if ( (tmp = __argp->arg("q")) != NULL ) {
00095       for (unsigned int i = 0; i < strlen(tmp); ++i) {
00096         if ( tmp[i] == 'q' ) {
00097           switch (log_level) {
00098           case Logger::LL_INFO:  log_level = Logger::LL_WARN; break;
00099           case Logger::LL_WARN:  log_level = Logger::LL_ERROR; break;
00100           case Logger::LL_ERROR: log_level = Logger::LL_NONE; break;
00101           default: break;
00102           }
00103         }
00104       }
00105     }
00106   } else if ( (tmp = __argp->arg("l")) != NULL ) {
00107     if ( strcmp(tmp, "debug") == 0 ) {
00108       log_level = Logger::LL_DEBUG;
00109     } else if ( strcmp(tmp, "info") == 0 ) {
00110       log_level = Logger::LL_INFO;
00111     } else if ( strcmp(tmp, "warn") == 0 ) {
00112       log_level = Logger::LL_WARN;
00113     } else if ( strcmp(tmp, "error") == 0 ) {
00114       log_level = Logger::LL_ERROR;
00115     } else if ( strcmp(tmp, "none") == 0 ) {
00116       log_level = Logger::LL_NONE;
00117     } else {
00118       printf("Unknown log level '%s', using default\n", tmp);
00119     }
00120   }
00121 
00122   if ( (tmp = __argp->arg("L")) != NULL ) {
00123     try {
00124       __multi_logger = LoggerFactory::multilogger_instance(tmp);
00125     } catch (Exception &e) {
00126       e.append("Initializing multi logger failed");
00127       destruct();
00128       throw;
00129     }
00130   } else {
00131     __multi_logger = new MultiLogger(new ConsoleLogger());
00132   }
00133 
00134   __multi_logger->set_loglevel(log_level);
00135   LibLogger::init(__multi_logger);
00136 
00137   /* Prepare home dir directory, just in case */
00138   const char *homedir = getenv("HOME");
00139   if (homedir) {
00140     char *userdir;
00141     if (asprintf(&userdir, "%s/%s", homedir, USERDIR) != -1) {
00142       if (access(userdir, W_OK) != 0) {
00143         if (mkdir(userdir, S_IRWXU | S_IRWXG | S_IROTH | S_IXOTH) == -1) {
00144           __multi_logger->log_warn("FawkesMainThread", "Failed to create .fawkes "
00145                                    "directory %s, trying without", userdir);
00146         }
00147       }
00148       free(userdir);
00149     }
00150   }
00151 
00152   /* Config stuff */
00153   __sqlite_conf = new SQLiteConfiguration(CONFDIR);
00154   __config = __sqlite_conf;
00155   __config->load(__argp->arg("c"), __argp->arg("d"));
00156 
00157   try {
00158     SQLiteConfiguration::SQLiteValueIterator *i =
00159       __sqlite_conf->modified_iterator();
00160     while (i->next()) {
00161       std::string modtype = i->get_modtype();
00162       if (modtype == "changed") {
00163         __multi_logger->log_warn("FawkesMainThread",  "Default config value CHANGED: %s (was: %s now: %s)",
00164                                  i->path(), i->get_oldvalue().c_str(),
00165                                  i->get_as_string().c_str());
00166       } else if (modtype == "erased") {
00167         __multi_logger->log_warn("FawkesMainThread",  "Default config value ERASED:  %s",
00168                                  i->path());
00169       } else {
00170         __multi_logger->log_debug("FawkesMainThread", "Default config value ADDED:   %s (value: %s)",
00171                                   i->path(), i->get_as_string().c_str());
00172       }
00173     }
00174     delete i;
00175   } catch (Exception &e) {
00176     __multi_logger->log_warn("FawkesMainThread", "Failed to read modified default config values, no dump?");
00177   }
00178 
00179   /* Clock */
00180   __clock = Clock::instance();
00181 
00182   std::string bb_magic_token = "";
00183   unsigned int bb_size = 2097152;
00184   try {
00185     bb_magic_token = __config->get_string("/fawkes/mainapp/blackboard_magic_token");
00186     __multi_logger->log_info("FawkesMainApp", "BlackBoard magic token defined. "
00187                              "Using shared memory BlackBoard.");
00188   } catch (Exception &e) {
00189     // ignore
00190   }
00191   try {
00192     bb_size = __config->get_uint("/fawkes/mainapp/blackboard_size");
00193   } catch (Exception &e) {
00194     __multi_logger->log_warn("FawkesMainApp", "BlackBoard size not defined. "
00195                              "Will use %u, saving to default DB", bb_size);
00196     __config->set_default_uint("/fawkes/mainapp/blackboard_size", bb_size);
00197   }
00198 
00199   unsigned int net_tcp_port     = 1910;
00200   std::string  net_service_name = "Fawkes on %h";
00201   try {
00202     net_tcp_port = __config->get_uint("/fawkes/mainapp/net/tcp_port");
00203   } catch (Exception &e) {}  // ignore, we stick with the default
00204   if (net_tcp_port > 65535)  net_tcp_port = 1910;
00205   try {
00206     net_service_name = __config->get_string("/fawkes/mainapp/net/service_name");
00207   } catch (Exception &e) {}  // ignore, we stick with the default
00208 
00209   // Cleanup stale BlackBoard shared memory segments if requested
00210   if ( __argp->has_arg("C") ) {
00211     LocalBlackBoard::cleanup(bb_magic_token.c_str(), /* output with lister? */ true);
00212   }
00213 
00214   /* Managers */
00215   try {
00216     if ( bb_magic_token == "") {
00217       __blackboard       = new LocalBlackBoard(bb_size);
00218     } else {
00219       __blackboard       = new LocalBlackBoard(bb_size, bb_magic_token.c_str());
00220     }
00221     __thread_manager     = new FawkesThreadManager();
00222     __aspect_inifin      = new AspectIniFin(__blackboard,
00223                                             __thread_manager->aspect_collector(),
00224                                             __config, __multi_logger, __clock);
00225     __thread_manager->set_inifin(__aspect_inifin, __aspect_inifin);
00226     __plugin_manager     = new PluginManager(__thread_manager, __config,
00227                                              "/fawkes/meta_plugins/");
00228     __network_manager    = new FawkesNetworkManager(__thread_manager, net_tcp_port,
00229                                                     net_service_name.c_str());
00230     __config_nethandler  = new ConfigNetworkHandler(__config, __network_manager->hub());
00231   } catch (Exception &e) {
00232     e.append("Initializing managers failed");
00233     destruct();
00234     throw;
00235   }
00236 
00237   __network_logger = new NetworkLogger(__network_manager->hub(), log_level);
00238   __multi_logger->add_logger(__network_logger);
00239 
00240   __aspect_inifin->set_fnet_hub( __network_manager->hub() );
00241   __aspect_inifin->set_network_members( __network_manager->nnresolver(),
00242                                         __network_manager->service_publisher(),
00243                                         __network_manager->service_browser() );
00244   __aspect_inifin->set_plugin_manager(__plugin_manager);
00245   __aspect_inifin->set_mainloop_employer(this);
00246   __aspect_inifin->set_logger_employer(this);
00247   __aspect_inifin->set_blocked_timing_executor(__thread_manager);
00248 
00249   __plugin_nethandler = new PluginNetworkHandler(__plugin_manager,
00250                                                  __network_manager->hub(),
00251                                                  __plugin_mutex);
00252   __plugin_nethandler->start();
00253 
00254   __blackboard->start_nethandler(__network_manager->hub());
00255 
00256   __loop_start = new Time(__clock);
00257   __loop_end   = new Time(__clock);
00258   try {
00259     __max_thread_time_usec = __config->get_uint("/fawkes/mainapp/max_thread_time");
00260   } catch (Exception &e) {
00261     __max_thread_time_usec = 30000;
00262     __multi_logger->log_info("FawkesMainApp", "Maximum thread time not set, assuming 30ms.");
00263   }
00264   __max_thread_time_nanosec = __max_thread_time_usec * 1000;
00265 
00266   __time_wait = NULL;
00267   try {
00268     __desired_loop_time_usec = __config->get_uint("/fawkes/mainapp/desired_loop_time");
00269     if ( __desired_loop_time_usec > 0 ) {
00270       __time_wait = new TimeWait(__clock, __desired_loop_time_usec);
00271     }
00272   } catch (Exception &e) {
00273     __desired_loop_time_usec = 0;
00274     __multi_logger->log_info("FawkesMainApp", "Desired loop time not set, assuming 0");
00275   }
00276 
00277   __desired_loop_time_sec  = (float)__desired_loop_time_usec / 1000000.f;
00278 
00279   try {
00280     __enable_looptime_warnings = __config->get_bool("/fawkes/mainapp/enable_looptime_warnings");
00281     if(!__enable_looptime_warnings) {
00282       __multi_logger->log_debug(name(), "loop time warnings are disabled");
00283     }
00284   } catch(Exception &e) {
00285     __enable_looptime_warnings = true;
00286   }
00287 }
00288 
00289 
00290 /** Destructor. */
00291 FawkesMainThread::~FawkesMainThread()
00292 {
00293   destruct();
00294 }
00295 
00296 
00297 /** Destruct.
00298  * Mimics destructor, but may be called in ctor exceptions.
00299  */
00300 void
00301 FawkesMainThread::destruct()
00302 {
00303   try {
00304     __sqlite_conf->try_dump();
00305   } catch (CouldNotOpenFileException &e) {
00306     if (e.get_errno() == EACCES) {
00307       __multi_logger->log_warn("FawkesMainThread", "Cannot write to dump file, "
00308                                "no write ");
00309       __multi_logger->log_warn("FawkesMainThread", "permission for file or "
00310                                "directory. This");
00311       __multi_logger->log_warn("FawkesMainThread", "usually happens if running "
00312                                "with system-wide");
00313       __multi_logger->log_warn("FawkesMainThread", "installed Fawkes as non-root "
00314                                "user. Make");
00315       __multi_logger->log_warn("FawkesMainThread", "configuration changes to the "
00316                                "host-based");
00317       __multi_logger->log_warn("FawkesMainThread", "database (set as non-default "
00318                                "values).");
00319     } else {
00320       __multi_logger->log_warn("FawkesMainThread", "Failed to dump default "
00321                                "config (open), exception follows.");
00322       __multi_logger->log_warn("FawkesMainThread", e);
00323     }
00324   } catch (Exception &e) {
00325     __multi_logger->log_warn("FawkesMainThread", "Failed to dump default config, "
00326                              "exception follows.");
00327     __multi_logger->log_warn("FawkesMainThread", e);
00328   }
00329 
00330   // Must delete network logger first since network manager has to die before the LibLogger
00331   // is finalized.
00332   __multi_logger->remove_logger(__network_logger);
00333   delete __network_logger;
00334 
00335   if ( __plugin_nethandler ) {
00336     __plugin_nethandler->cancel();
00337     __plugin_nethandler->join();
00338     delete __plugin_nethandler;
00339   }
00340   delete __plugin_manager;
00341   delete __blackboard;
00342   delete __config_nethandler;
00343   delete __config;
00344   delete __network_manager;
00345   delete __thread_manager;
00346   delete __aspect_inifin;
00347   delete __time_wait;
00348   delete __loop_start;
00349   delete __loop_end;
00350 
00351   delete __mainloop_barrier;
00352   delete __mainloop_mutex;
00353 
00354   delete __plugin_mutex;
00355 
00356   // implicitly frees multi_logger and all sub-loggers
00357   LibLogger::finalize();
00358 
00359   Clock::finalize();
00360 }
00361 
00362 void
00363 FawkesMainThread::once()
00364 {
00365   if ( __argp->has_arg("p") ) {
00366     try {
00367       __plugin_manager->load(__argp->arg("p"));
00368     } catch (Exception &e) {
00369       __multi_logger->log_error("FawkesMainThread", "Failed to load plugins %s, "
00370                                 "exception follows", __argp->arg("p"));
00371       __multi_logger->log_error("FawkesMainThread", e);
00372     }
00373   } else {
00374     try {
00375       __plugin_manager->load("default");
00376     } catch (PluginLoadException &e) {
00377       if (e.plugin_name() != "default") {
00378         // only print if name is not default, i.e. one of the plugins that
00379         // the default meta plugin
00380         __multi_logger->log_error("FawkesMainThread", "Failed to load default "
00381                                   "plugins, exception follows");
00382         __multi_logger->log_error("FawkesMainThread", e);
00383       }
00384     } catch (Exception &e) {
00385         __multi_logger->log_error("FawkesMainThread", "Failed to load default "
00386                                   "plugins, exception follows");
00387         __multi_logger->log_error("FawkesMainThread", e);
00388     }
00389   }
00390 }
00391 
00392 void
00393 FawkesMainThread::set_mainloop_thread(Thread *mainloop_thread)
00394 {
00395   loopinterrupt_antistarve_mutex->lock();
00396   __mainloop_mutex->lock();
00397   __mainloop_barrier->interrupt();
00398   __mainloop_thread = mainloop_thread;
00399   __mainloop_mutex->unlock();
00400   loopinterrupt_antistarve_mutex->unlock();
00401 }
00402 
00403 
00404 void
00405 FawkesMainThread::add_logger(Logger *logger)
00406 {
00407   __multi_logger->add_logger(logger);
00408 }
00409 
00410 
00411 void
00412 FawkesMainThread::remove_logger(Logger *logger)
00413 {
00414   __multi_logger->remove_logger(logger);
00415 }
00416 
00417 
00418 void
00419 FawkesMainThread::loop()
00420 {
00421   if ( ! __thread_manager->timed_threads_exist() ) {
00422     __multi_logger->log_debug("FawkesMainThread", "No timed threads exist, waiting");
00423     try {
00424       __thread_manager->wait_for_timed_threads();
00425       __multi_logger->log_debug("FawkesMainThread", "Timed threads have been added, "
00426                                 "running main loop now");
00427     } catch (InterruptedException &e) {
00428       __multi_logger->log_debug("FawkesMainThread", "Waiting for timed threads interrupted");
00429       return;
00430     }
00431   }
00432 
00433   __plugin_mutex->lock();
00434 
00435   try {
00436     if ( __time_wait ) {
00437       __time_wait->mark_start();
00438     }
00439     __loop_start->stamp_systime();
00440       
00441     CancelState old_state;
00442     set_cancel_state(CANCEL_DISABLED, &old_state);
00443 
00444     __mainloop_mutex->lock();
00445 
00446     if (unlikely(__mainloop_thread != NULL)) {
00447       try {
00448         if (likely(__mainloop_thread != NULL)) {
00449           __mainloop_thread->wakeup(__mainloop_barrier);
00450           __mainloop_barrier->wait();
00451         }
00452       } catch (Exception &e) {
00453         __multi_logger->log_warn("FawkesMainThread", e);
00454       }
00455     } else {
00456 
00457       CancelState old_state;
00458       set_cancel_state(CANCEL_DISABLED, &old_state);
00459       try {
00460         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_PRE_LOOP,       __max_thread_time_nanosec );
00461         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_SENSOR,         __max_thread_time_nanosec );
00462         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_SENSOR_PROCESS, __max_thread_time_nanosec );
00463         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_WORLDSTATE,     __max_thread_time_nanosec );
00464         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_THINK,          __max_thread_time_nanosec );
00465         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_SKILL,          __max_thread_time_nanosec );
00466         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_ACT,            __max_thread_time_nanosec );
00467         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_ACT_EXEC,       __max_thread_time_nanosec );
00468         __thread_manager->wakeup_and_wait( BlockedTimingAspect::WAKEUP_HOOK_POST_LOOP,      __max_thread_time_nanosec );
00469       } catch (Exception &e) {
00470         if (__enable_looptime_warnings) {
00471           __multi_logger->log_error("FawkesMainThread", e);
00472         }
00473       }
00474     }
00475     __mainloop_mutex->unlock();
00476     set_cancel_state(old_state);
00477 
00478     test_cancel();
00479 
00480     __thread_manager->try_recover(__recovered_threads);
00481     if ( ! __recovered_threads.empty() ) {
00482       // threads have been recovered!
00483       __multi_logger->log_error(name(), "Threads recovered %zu", __recovered_threads.size());
00484       if(__enable_looptime_warnings) {
00485         if ( __recovered_threads.size() == 1 ) {
00486           __multi_logger->log_warn("FawkesMainThread", "The thread %s could be "
00487                                    "recovered and resumes normal operation",
00488                                    __recovered_threads.front().c_str());
00489         } else {
00490           std::string s;
00491           for (std::list<std::string>::iterator i = __recovered_threads.begin();
00492                i != __recovered_threads.end(); ++i) {
00493             s += *i + " ";
00494           }
00495           
00496           __multi_logger->log_warn("FawkesMainThread", "The following threads could be "
00497                                    "recovered and resumed normal operation: %s", s.c_str());
00498         }
00499       }
00500       __recovered_threads.clear();
00501     }
00502 
00503     if (__desired_loop_time_sec > 0) {
00504       __loop_end->stamp_systime();
00505       float loop_time = *__loop_end - __loop_start;
00506       if(__enable_looptime_warnings) {
00507         if (loop_time > __desired_loop_time_sec) {
00508           __multi_logger->log_warn("FawkesMainThread", "Loop time exceeded, "
00509                                    "desired: %f sec (%u usec),  actual: %f sec",
00510                                    __desired_loop_time_sec, __desired_loop_time_usec,
00511                                    loop_time);
00512         }
00513       }
00514     }
00515 
00516     __plugin_mutex->unlock();
00517 
00518     if ( __time_wait ) {
00519       __time_wait->wait_systime();
00520     } else {
00521       yield();
00522     }
00523   } catch (Exception &e) {
00524     __multi_logger->log_warn("FawkesMainThread",
00525                              "Exception caught while executing default main "
00526                              "loop, ignoring.");
00527     __multi_logger->log_warn("FawkesMainThread", e);
00528   } catch (std::exception &e) {
00529     __multi_logger->log_warn("FawkesMainThread",
00530                              "STL Exception caught while executing default main "
00531                              "loop, ignoring. (what: %s)", e.what());
00532   }
00533   // catch ... is not a good idea, would catch cancellation exception
00534   // at least needs to be rethrown.
00535 }