Merge pull request #780 from Deedss/feature/event-information-on-waiting

Expand logging information when genericEvent is waiting

Author: PengZheng

documents/framework.md

@@ -304,3 +304,4 @@ The following framework properties are supported:
 | CELIX_AUTO_INSTALL                                           | ""            | The bundles to install after the framework is started. Multiple bundles can be provided separated by a space.                                                                         |         
 | CELIX_LOGGING_DEFAULT_ACTIVE_LOG_LEVEL                       | "info"        | The default active log level for created log services. Possible values are "trace", "debug", "info", "warning", "error" and "fatal".                                                  |
 | CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS | "2"           | The allowed processing time for scheduled events in seconds, if processing takes longer a warning message will be logged.                                                             |
+| CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS | "5" | The allowed processing time for generic events in seconds, if processing takes longer a warning message will be logged.                                                             |

libs/framework/gtest/src/CelixFrameworkTestSuite.cc

@@ -88,6 +88,40 @@ TEST_F(CelixFrameworkTestSuite, TimedWaitEventQueueTest) {
     EXPECT_EQ(CELIX_SUCCESS, status);
 }
 
+TEST_F(CelixFrameworkTestSuite, GenericEventTimeoutPropertyTest) {
+    celix_properties_t* config;
+    auto status = celix_properties_load("config.properties", 0, &config);
+    EXPECT_EQ(CELIX_SUCCESS, status);
+    celix_properties_set(config, "CELIX_LOGGING_DEFAULT_ACTIVE_LOG_LEVEL" , "warning");
+    celix_properties_set(config, CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS, "0.010");
+
+    framework_t* fw = celix_frameworkFactory_createFramework(config);
+    ASSERT_TRUE(fw != nullptr);
+
+    // Start capturing stdout
+    ::testing::internal::CaptureStderr();
+
+    //When there is a emtpy event queue
+    celix_framework_waitForEmptyEventQueue(fw);
+    
+    //And a generic event is fired, that block the queue for 20ms
+    auto callback = [](void* /*data*/) {
+        std::this_thread::sleep_for(std::chrono::milliseconds{20});
+    };
+    long eventId = celix_framework_fireGenericEvent(fw, -1L, -1L, "test", nullptr, callback, nullptr, nullptr);
+
+    //Then waiting for the event queue will have logged errors
+    celix_framework_waitForGenericEvent(fw, eventId);
+
+    // And the log will contain a printed warning
+    auto log = ::testing::internal::GetCapturedStderr();
+    auto expected = "Generic event 'test' (id=" + std::to_string(eventId) + ")";
+    EXPECT_TRUE(log.find(expected) != std::string::npos) << "Got " << log; 
+
+    // Cleanup framework
+    celix_frameworkFactory_destroyFramework(fw);
+}
+
 TEST_F(CelixFrameworkTestSuite, AsyncInstallStartStopUpdateAndUninstallBundleTest) {
     long bndId = celix_framework_installBundleAsync(framework.get(), SIMPLE_TEST_BUNDLE1_LOCATION, false);
     EXPECT_GE(bndId, 0);

libs/framework/include/celix/Constants.h

@@ -223,4 +223,12 @@ namespace celix {
      * Should be a boolean value.
      */
     constexpr const char* const FRAMEWORK_CONDITION_SERVICES_ENABLED = CELIX_FRAMEWORK_CONDITION_SERVICES_ENABLED;
+
+    /**
+     * @brief Celix framework property (named "CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS") to configure the timeout time 
+     * for generic events in seconds.
+     * Default is 5.0
+     * Should be a double value.
+     */
+    constexpr const char* const ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS = CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS;
 }

libs/framework/include/celix_constants.h

@@ -281,6 +281,21 @@ extern "C" {
  */
 #define CELIX_DEFAULT_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS 2.0
 
+/*!
+ * @brief Celix framework environment property (named "CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS")
+ * to configure the allowed processing time for a generic event callback or a remove callback before a warning
+ * log message is printed that the processing time is too long.
+ * Should be a double value in seconds.
+ */
+#define CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS                                                   \
+    "CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS"
+
+/**
+ * @brief The default , in seconds, allowed processing time for a processing a generic event or a remove callback
+ * before a warning log message is printed.
+ */
+#define CELIX_DEFAULT_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS 5.0
+
 /**
  * @brief Celix framework environment property (named "CELIX_FRAMEWORK_CONDITION_SERVICES_ENABLED") to configure 
  * whether framework condition services are enabled or not.

libs/framework/src/framework.c

@@ -252,6 +252,10 @@ celix_status_t framework_create(framework_pt *out, celix_properties_t* config) {
     framework->dispatcher.eventQueue = malloc(sizeof(celix_framework_event_t) * framework->dispatcher.eventQueueCap);
     framework->dispatcher.dynamicEventQueue = celix_arrayList_create();
     framework->dispatcher.scheduledEvents = celix_longHashMap_create();
+    framework->dispatcher.genericEventTimeoutInSeconds = celix_framework_getConfigPropertyAsDouble(framework,
+                                                  CELIX_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS,
+                                                  CELIX_DEFAULT_ALLOWED_PROCESSING_TIME_FOR_GENERIC_EVENT_IN_SECONDS,
+                                                  NULL);
 
     celix_framework_createAndStoreFrameworkUUID(framework);
 
@@ -2663,37 +2667,42 @@ long celix_framework_nextScheduledEventId(framework_t *fw) {
     return __atomic_fetch_add(&fw->dispatcher.nextScheduledEventId, 1, __ATOMIC_RELAXED);
 }
 
-/**
- * @brief Checks if a generic event with the provided eventId is in progress.
- */
-static bool celix_framework_isGenericEventInProgress(celix_framework_t* fw, long eventId) {
-    // precondition fw->dispatcher.mutex locked)
+static celix_framework_event_t* celix_framework_getGenericEvent(celix_framework_t* fw, long eventId) {
+    // precondition fw->dispatcher.mutex locked
     for (int i = 0; i < fw->dispatcher.eventQueueSize; ++i) {
         int index = (fw->dispatcher.eventQueueFirstEntry + i) % fw->dispatcher.eventQueueCap;
         celix_framework_event_t* e = &fw->dispatcher.eventQueue[index];
         if (e->type == CELIX_GENERIC_EVENT && e->genericEventId == eventId) {
-            return true;;
+            return e;
         }
     }
     for (int i = 0; i < celix_arrayList_size(fw->dispatcher.dynamicEventQueue); ++i) {
         celix_framework_event_t* e = celix_arrayList_get(fw->dispatcher.dynamicEventQueue, i);
         if (e->type == CELIX_GENERIC_EVENT && e->genericEventId == eventId) {
-            return true;
+            return e;
         }
     }
-    return false;
+    return NULL;
 }
 
 void celix_framework_waitForGenericEvent(celix_framework_t* fw, long eventId) {
     assert(!celix_framework_isCurrentThreadTheEventLoop(fw));
-    struct timespec logAbsTime = celixThreadCondition_getDelayedTime(5);
+    struct timespec logAbsTime = celixThreadCondition_getDelayedTime(fw->dispatcher.genericEventTimeoutInSeconds);
     celixThreadMutex_lock(&fw->dispatcher.mutex);
-    while (celix_framework_isGenericEventInProgress(fw, eventId)) {
+    celix_framework_event_t* event = celix_framework_getGenericEvent(fw, eventId);
+    while (event) {
         celix_status_t waitStatus =
             celixThreadCondition_waitUntil(&fw->dispatcher.cond, &fw->dispatcher.mutex, &logAbsTime);
-        if (waitStatus == ETIMEDOUT) {
-            fw_log(fw->logger, CELIX_LOG_LEVEL_WARNING, "Generic event with id %li not finished.", eventId);
-            logAbsTime = celixThreadCondition_getDelayedTime(5);
+        event = celix_framework_getGenericEvent(fw, eventId);
+        if (waitStatus == ETIMEDOUT && event != NULL) {
+            fw_log(fw->logger,
+                   CELIX_LOG_LEVEL_WARNING,
+                   "Generic event '%s' (id=%li) for bundle '%s' (id=%li) not finished",
+                   event->genericEventName ? event->genericEventName : "unnamed",
+                   eventId,
+                   event->bndEntry ? celix_bundle_getSymbolicName(event->bndEntry->bnd) : "unnamed",
+                   event->bndEntry ? event->bndEntry->bndId : -1l);
+            logAbsTime = celixThreadCondition_getDelayedTime(fw->dispatcher.genericEventTimeoutInSeconds);
         }
     }
     celixThreadMutex_unlock(&fw->dispatcher.mutex);

libs/framework/src/framework_private.h

@@ -188,6 +188,8 @@ struct celix_framework {
             int nbEvent; // number of pending generic events
         } stats;
         celix_long_hash_map_t *scheduledEvents; //key = scheduled event id, entry = celix_framework_scheduled_event_t*. Used for scheduled events
+
+        double genericEventTimeoutInSeconds; // Timeout for printing an warning on unfinished generic events
     } dispatcher;
 
     celix_framework_logger_t* logger;