Enhance notification logging

- More details from the local context (notification, user, checkable, command names)
- Notice logs for when this notification object is paused in HA enabled zones
- Notice logs for interval=0 reminder notifications
- Object name for skipping recovery notifications when problem hasn't been notified before

diff --git a/lib/icinga/checkable-notification.cpp b/lib/icinga/checkable-notification.cpp
index 1a2c183639d801d71a014c16e6485e66e36525bd..2a909769c4292333dd0e815a5d7c69e8b330e6a4 100644 (file)
--- a/lib/icinga/checkable-notification.cpp
+++ b/lib/icinga/checkable-notification.cpp
@@ -44,7 +44,9 @@ void Checkable::ResetNotificationNumbers()
 
 void Checkable::SendNotifications(NotificationType type, const CheckResult::Ptr& cr, const String& author, const String& text)
 {
-       CONTEXT("Sending notifications for object '" + GetName() + "'");
+       String checkableName = GetName();
+
+       CONTEXT("Sending notifications for object '" + checkableName + "'");
 
        bool force = GetForceNextNotification();
 
@@ -53,31 +55,31 @@ void Checkable::SendNotifications(NotificationType type, const CheckResult::Ptr&
        if (!IcingaApplication::GetInstance()->GetEnableNotifications() || !GetEnableNotifications()) {
                if (!force) {
                        Log(LogInformation, "Checkable")
-                               << "Notifications are disabled for service '" << GetName() << "'.";
+                               << "Notifications are disabled for checkable '" << checkableName << "'.";
                        return;
                }
        }
 
-       Log(LogInformation, "Checkable")
-               << "Checking for configured notifications for object '" << GetName() << "'";
-
        std::set<Notification::Ptr> notifications = GetNotifications();
 
-       if (notifications.empty())
-               Log(LogInformation, "Checkable")
-                       << "Checkable '" << GetName() << "' does not have any notifications.";
+       Log(LogInformation, "Checkable")
+               << "Checkable '" << checkableName << "' has " << notifications.size() << " notification(s). Proceeding with filters, successful sends will be logged.";
 
-       Log(LogDebug, "Checkable")
-               << "Checkable '" << GetName() << "' has " << notifications.size() << " notification(s).";
+       if (notifications.empty())
+               return;
 
        for (const Notification::Ptr& notification : notifications) {
                try {
-                       if (!notification->IsPaused())
+                       if (!notification->IsPaused()) {
                                notification->BeginExecuteNotification(type, cr, force, false, author, text);
+                       } else {
+                               Log(LogNotice, "Notification")
+                                       << "Notification '" << notification->GetName() << "': HA cluster active, this endpoint does not have the authority (paused=true). Skipping.";
+                       }
                } catch (const std::exception& ex) {
                        Log(LogWarning, "Checkable")
-                               << "Exception occurred during notification for service '"
-                               << GetName() << "': " << DiagnosticInformation(ex);
+                               << "Exception occurred during notification '" << notification->GetName() << "' for checkable '"
+                               << GetName() << "': " << DiagnosticInformation(ex, false);
                }
        }
 }

diff --git a/lib/icinga/notification.cpp b/lib/icinga/notification.cpp
index ba6ca49b4d2bb1a9fd063cf9f83497a5358baa10..41982cd309e0dc65dcaddb9f9eaca75f4db89816 100644 (file)
--- a/lib/icinga/notification.cpp
+++ b/lib/icinga/notification.cpp
@@ -260,8 +260,10 @@ String Notification::NotificationTypeToString(NotificationType type)
 
 void Notification::BeginExecuteNotification(NotificationType type, const CheckResult::Ptr& cr, bool force, bool reminder, const String& author, const String& text)
 {
+       String notificationName = GetName();
+
        Log(LogNotice, "Notification")
-               << "Attempting to send " << (reminder ? "reminder " : " ") << "notifications for notification object '" << GetName() << "'.";
+               << "Attempting to send " << (reminder ? "reminder " : " ") << "notifications for notification object '" << notificationName << "'.";
 
        Checkable::Ptr checkable = GetCheckable();
 
@@ -270,7 +272,7 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                if (tp && !tp->IsInside(Utility::GetTime())) {
                        Log(LogNotice, "Notification")
-                               << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '" << GetName()
+                               << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '" << notificationName
                                << "': not in timeperiod '" << tp->GetName() << "'";
                        return;
                }
@@ -284,8 +286,8 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                        if (timesBegin != Empty && timesBegin >= 0 && now < checkable->GetLastHardStateChange() + timesBegin) {
                                Log(LogNotice, "Notification")
-                                       << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '" << GetName()
-                                       << "': before specified begin time (" << Utility::FormatDuration(timesBegin) << ")";
+                                       << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
+                                       << notificationName << "': before specified begin time (" << Utility::FormatDuration(timesBegin) << ")";
 
                                /* we need to adjust the next notification time
                                 * to now + begin delaying the first notification
@@ -299,8 +301,8 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                        if (timesEnd != Empty && timesEnd >= 0 && now > checkable->GetLastHardStateChange() + timesEnd) {
                                Log(LogNotice, "Notification")
-                                       << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '" << GetName()
-                                       << "': after specified end time (" << Utility::FormatDuration(timesEnd) << ")";
+                                       << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
+                                       << notificationName << "': after specified end time (" << Utility::FormatDuration(timesEnd) << ")";
                                return;
                        }
                }
@@ -314,7 +316,8 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                if (!(ftype & GetTypeFilter())) {
                        Log(LogNotice, "Notification")
-                               << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '" << GetName() << "': type '"
+                               << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
+                               << notificationName << "': type '"
                                << NotificationTypeToStringInternal(type) << "' does not match type filter: "
                                << NotificationFilterToString(GetTypeFilter(), GetTypeFilterMap()) << ".";
 
@@ -353,14 +356,16 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                        if (!(fstate & GetStateFilter())) {
                                Log(LogNotice, "Notification")
-                                       << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '" << GetName() << "': state '" << stateStr
+                                       << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
+                                       << notificationName << "': state '" << stateStr
                                        << "' does not match state filter: " << NotificationFilterToString(GetStateFilter(), GetStateFilterMap()) << ".";
                                return;
                        }
                }
        } else {
                Log(LogNotice, "Notification")
-                       << "Not checking " << (reminder ? "reminder " : " ") << "notification filters for notification object '" << GetName() << "': Notification was forced.";
+                       << "Not checking " << (reminder ? "reminder " : " ") << "notification filters for notification object '"
+                       << notificationName << "': Notification was forced.";
        }
 
        {
@@ -400,13 +405,14 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                if (!user->GetEnableNotifications()) {
                        Log(LogNotice, "Notification")
-                               << "Disabled notifications for user '" << userName << "'. Not sending notification.";
+                               << "Notification object '" << notificationName << "': Disabled notifications for user '"
+                               << userName << "'. Not sending notification.";
                        continue;
                }
 
                if (!CheckNotificationUserFilters(type, user, force, reminder)) {
                        Log(LogNotice, "Notification")
-                               << "Notification filters for user '" << userName << "' not matched. Not sending notification.";
+                               << "Notification object '" << notificationName << "': Filters for user '" << userName << "' not matched. Not sending notification.";
                        continue;
                }
 
@@ -414,8 +420,8 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
                if (type == NotificationRecovery) {
                        if (!notifiedProblemUsers->Contains(userName) && (NotificationProblem & user->GetTypeFilter())) {
                                Log(LogNotice, "Notification")
-                                       << "We did not notify user '" << userName
-                                       << "' (Problem types enabled) for a problem before. Not sending recovery notification.";
+                                       << "Notification object '" << notificationName << "': We did not notify user '" << userName
+                                       << "' (Problem types enabled) for a problem before. Not sending Recovery notification.";
                                continue;
                        }
                }
@@ -424,7 +430,7 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
                if (type == NotificationAcknowledgement) {
                        if (!notifiedProblemUsers->Contains(userName) && (NotificationProblem & user->GetTypeFilter())) {
                                Log(LogNotice, "Notification")
-                                       << "We did not notify user '" << userName
+                                       << "Notification object '" << notificationName << "': We did not notify user '" << userName
                                        << "' (Problem types enabled) for a problem before. Not sending acknowledgement notification.";
                                continue;
                        }
@@ -432,7 +438,7 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
                Log(LogInformation, "Notification")
                        << "Sending " << (reminder ? "reminder " : "") << "'" << NotificationTypeToStringInternal(type) << "' notification '"
-                       << GetName() << "' for user '" << userName << "'";
+                       << notificationName << "' for user '" << userName << "'";
 
                Utility::QueueAsyncCallback(std::bind(&Notification::ExecuteNotificationHelper, this, type, user, cr, force, author, text));
 
@@ -454,13 +460,16 @@ void Notification::BeginExecuteNotification(NotificationType type, const CheckRe
 
 bool Notification::CheckNotificationUserFilters(NotificationType type, const User::Ptr& user, bool force, bool reminder)
 {
+       String notificationName = GetName();
+       String userName = user->GetName();
+
        if (!force) {
                TimePeriod::Ptr tp = user->GetPeriod();
 
                if (tp && !tp->IsInside(Utility::GetTime())) {
                        Log(LogNotice, "Notification")
                                << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
-                               << GetName() << " and user '" << user->GetName()
+                               << notificationName << " and user '" << userName
                                << "': user period not in timeperiod '" << tp->GetName() << "'";
                        return false;
                }
@@ -468,7 +477,8 @@ bool Notification::CheckNotificationUserFilters(NotificationType type, const Use
                unsigned long ftype = type;
 
                Log(LogDebug, "Notification")
-                       << "User notification, Type '" << NotificationTypeToStringInternal(type)
+                       << "User '" << userName << "' notification '" << notificationName
+                       << "', Type '" << NotificationTypeToStringInternal(type)
                        << "', TypeFilter: " << NotificationFilterToString(user->GetTypeFilter(), GetTypeFilterMap())
                        << " (FType=" << ftype << ", TypeFilter=" << GetTypeFilter() << ")";
 
@@ -476,7 +486,7 @@ bool Notification::CheckNotificationUserFilters(NotificationType type, const Use
                if (!(ftype & user->GetTypeFilter())) {
                        Log(LogNotice, "Notification")
                                << "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
-                               << GetName() << " and user '" << user->GetName() << "': type '"
+                               << notificationName << " and user '" << userName << "': type '"
                                << NotificationTypeToStringInternal(type) << "' does not match type filter: "
                                << NotificationFilterToString(user->GetTypeFilter(), GetTypeFilterMap()) << ".";
                        return false;
@@ -501,14 +511,15 @@ bool Notification::CheckNotificationUserFilters(NotificationType type, const Use
                        }
 
                        Log(LogDebug, "Notification")
-                               << "User notification, State '" << stateStr << "', StateFilter: "
+                               << "User '" << userName << "' notification '" << notificationName
+                               << "', State '" << stateStr << "', StateFilter: "
                                << NotificationFilterToString(user->GetStateFilter(), GetStateFilterMap())
                                << " (FState=" << fstate << ", StateFilter=" << user->GetStateFilter() << ")";
 
                        if (!(fstate & user->GetStateFilter())) {
                                Log(LogNotice, "Notification")
                                        << "Not " << (reminder ? "reminder " : " ") << "sending notifications for notification object '"
-                                       << GetName() << " and user '" << user->GetName() << "': state '" << stateStr
+                                       << notificationName << " and user '" << userName << "': state '" << stateStr
                                        << "' does not match state filter: " << NotificationFilterToString(user->GetStateFilter(), GetStateFilterMap()) << ".";
                                return false;
                        }
@@ -516,7 +527,7 @@ bool Notification::CheckNotificationUserFilters(NotificationType type, const Use
        } else {
                Log(LogNotice, "Notification")
                        << "Not checking " << (reminder ? "reminder " : " ") << "notification filters for notification object '"
-                       << GetName() << "' and user '" << user->GetName() << "': Notification was forced.";
+                       << notificationName << "' and user '" << userName << "': Notification was forced.";
        }
 
        return true;
@@ -524,29 +535,37 @@ bool Notification::CheckNotificationUserFilters(NotificationType type, const Use
 
 void Notification::ExecuteNotificationHelper(NotificationType type, const User::Ptr& user, const CheckResult::Ptr& cr, bool force, const String& author, const String& text)
 {
-       try {
-               NotificationCommand::Ptr command = GetCommand();
+       String notificationName = GetName();
+       String userName = user->GetName();
+       String checkableName = GetCheckable()->GetName();
 
-               if (!command) {
-                       Log(LogDebug, "Notification")
-                               << "No command found for notification '" << GetName() << "'. Skipping execution.";
-                       return;
-               }
+       NotificationCommand::Ptr command = GetCommand();
 
+       if (!command) {
+               Log(LogDebug, "Notification")
+                       << "No command found for notification '" << notificationName << "'. Skipping execution.";
+               return;
+       }
+
+       String commandName = command->GetName();
+
+       try {
                command->Execute(this, user, cr, type, author, text);
 
                /* required by compatlogger */
-               Service::OnNotificationSentToUser(this, GetCheckable(), user, type, cr, author, text, command->GetName(), nullptr);
+               Service::OnNotificationSentToUser(this, GetCheckable(), user, type, cr, author, text, commandName, nullptr);
 
                Log(LogInformation, "Notification")
                        << "Completed sending '" << NotificationTypeToStringInternal(type)
-                       << "' notification '" << GetName()
-                       << "' for checkable '" << GetCheckable()->GetName()
-                       << "' and user '" << user->GetName() << "'.";
+                       << "' notification '" << notificationName
+                       << "' for checkable '" << checkableName
+                       << "' and user '" << userName << "' using command '" << commandName << "'.";
        } catch (const std::exception& ex) {
                Log(LogWarning, "Notification")
-                       << "Exception occurred during notification for checkable '"
-                       << GetCheckable()->GetName() << "': " << DiagnosticInformation(ex);
+                       << "Exception occurred during notification '" << notificationName
+                       << "' for checkable '" << checkableName
+                       << "' and user '" << userName << "' using command '" << commandName << "': "
+                       << DiagnosticInformation(ex, false);
        }
 }
 

diff --git a/lib/notification/notificationcomponent.cpp b/lib/notification/notificationcomponent.cpp
index 4b638c62dd6271ce9cfb54d5838321c933a594f1..04b40274cd3ca654b241f22c1b43cd22b559aec0 100644 (file)
--- a/lib/notification/notificationcomponent.cpp
+++ b/lib/notification/notificationcomponent.cpp
@@ -85,16 +85,24 @@ void NotificationComponent::NotificationTimerHandler()
                if (!notification->IsActive())
                        continue;
 
-               if (notification->IsPaused() && GetEnableHA())
+               String notificationName = notification->GetName();
+
+               if (notification->IsPaused() && GetEnableHA()) {
+                       Log(LogNotice, "NotificationComponent")
+                               << "Reminder notification '" << notificationName << "': HA cluster active, this endpoint does not have the authority (paused=true). Skipping.";
                        continue;
+               }
 
                Checkable::Ptr checkable = notification->GetCheckable();
 
                if (!IcingaApplication::GetInstance()->GetEnableNotifications() || !checkable->GetEnableNotifications())
                        continue;
 
-               if (notification->GetInterval() <= 0 && notification->GetNoMoreNotifications())
+               if (notification->GetInterval() <= 0 && notification->GetNoMoreNotifications()) {
+                       Log(LogNotice, "NotificationComponent")
+                               << "Reminder notification '" << notificationName << "': Notification was sent out once and interval=0 disables reminder notifications.";
                        continue;
+               }
 
                if (notification->GetNextNotification() > now)
                        continue;
@@ -116,22 +124,24 @@ void NotificationComponent::NotificationTimerHandler()
                        if (checkable->GetStateType() == StateTypeSoft)
                                continue;
 
+                       /* Don't send reminder notifications for OK/Up states. */
                        if ((service && service->GetState() == ServiceOK) || (!service && host->GetState() == HostUp))
                                continue;
 
+                       /* Skip in runtime filters. */
                        if (!reachable || checkable->IsInDowntime() || checkable->IsAcknowledged() || checkable->IsFlapping())
                                continue;
                }
 
                try {
                        Log(LogNotice, "NotificationComponent")
-                               << "Attempting to send reminder notification '" << notification->GetName() << "'";
+                               << "Attempting to send reminder notification '" << notificationName << "'.";
 
                        notification->BeginExecuteNotification(NotificationProblem, checkable->GetLastCheckResult(), false, true);
                } catch (const std::exception& ex) {
                        Log(LogWarning, "NotificationComponent")
                                << "Exception occurred during notification for object '"
-                               << GetName() << "': " << DiagnosticInformation(ex);
+                               << notificationName << "': " << DiagnosticInformation(ex, false);
                }
        }
 }