Merge pull request #6935 from Icinga/feature/enhance-notification-logging

Enhance notification logging

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")
-		Log(LogInformation, "Checkable")
+		<< "Checkable '" << checkableName << "' has " << notifications.size() << " notification(s). Proceeding with filters, successful sends will be logged.";
-			<< "Checkable '" << GetName() << "' does not have any notifications.";
 
-	Log(LogDebug, "Checkable")
+	if (notifications.empty())
-		<< "Checkable '" << GetName() << "' has " << notifications.size() << " notification(s).";
+		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 '"
+				<< "Exception occurred during notification '" << notification->GetName() << "' for checkable '"
-				<< GetName() << "': " << DiagnosticInformation(ex);
+				<< GetName() << "': " << DiagnosticInformation(ex, false);
 		}
 	}
 }

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()
+					<< "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
-					<< "': before specified begin time (" << Utility::FormatDuration(timesBegin) << ")";
+					<< 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()
+					<< "Not sending " << (reminder ? "reminder " : " ") << "notifications for notification object '"
-					<< "': after specified end time (" << Utility::FormatDuration(timesEnd) << ")";
+					<< 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
+					<< "Notification object '" << notificationName << "': We did not notify user '" << userName
-					<< "' (Problem types enabled) for a problem before. Not sending recovery notification.";
+					<< "' (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)
 {
+	String notificationName = GetName();
+	String userName = user->GetName();
+	String checkableName = GetCheckable()->GetName();
+
+	NotificationCommand::Ptr command = GetCommand();
+
+	if (!command) {
+		Log(LogDebug, "Notification")
+			<< "No command found for notification '" << notificationName << "'. Skipping execution.";
+		return;
+	}
+
+	String commandName = command->GetName();
+
 	try {
-		NotificationCommand::Ptr command = GetCommand();
-
-		if (!command) {
-			Log(LogDebug, "Notification")
-				<< "No command found for notification '" << GetName() << "'. Skipping execution.";
-			return;
-		}
-
 		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()
+			<< "' notification '" << notificationName
-			<< "' for checkable '" << GetCheckable()->GetName()
+			<< "' for checkable '" << checkableName
-			<< "' and user '" << user->GetName() << "'.";
+			<< "' and user '" << userName << "' using command '" << commandName << "'.";
 	} catch (const std::exception& ex) {
 		Log(LogWarning, "Notification")
-			<< "Exception occurred during notification for checkable '"
+			<< "Exception occurred during notification '" << notificationName
-			<< GetCheckable()->GetName() << "': " << DiagnosticInformation(ex);
+			<< "' for checkable '" << checkableName
+			<< "' and user '" << userName << "' using command '" << commandName << "': "
+			<< DiagnosticInformation(ex, false);
 	}
 }
 

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);
 		}
 	}
 }