Merge pull request #287 from msupply-foundation/286-improve-info-logging

Improve logging, and skip parameter sets with not recipients

backend/scheduled/src/process.rs

@@ -30,11 +30,14 @@ pub fn process_scheduled_notifications(
     let mut errored_notifications = 0;
     let mut skipped_notifications = 0;
     for scheduled_notification in scheduled_notifications {
+        let start_time = Utc::now();
+        let notification_name = scheduled_notification.title.clone();
         log::info!(
             "Processing scheduled notification: {} - {}",
+            scheduled_notification.title,
             scheduled_notification.id,
-            scheduled_notification.title
         );
+
         match try_process_scheduled_notifications(ctx, scheduled_notification, current_time) {
             Err(e) => {
                 log::error!("{:?}", e);
@@ -49,6 +52,12 @@ pub fn process_scheduled_notifications(
                 successful_notifications += 1;
             }
         }
+        let end_time = Utc::now();
+        log::info!(
+            "Processed {} Notification in {}s",
+            notification_name,
+            (end_time - start_time).num_seconds()
+        );
     }
     // Return the number of notifications processed
     log::info!(
@@ -132,26 +141,34 @@ fn try_process_scheduled_notifications(
         let sql_params = serde_json::to_value(&template_params).map_err(|e| {
             NotificationError::InternalError(format!("Failed to parse sql params data: {:?}", e))
         })?;
-        let sql_query_parameters = get_notification_query_results(ctx, sql_params, &config)?;
-
-        // Template data should include the notification config parameters, plus the results of any queries
 
-        template_params.extend(sql_query_parameters);
-
-        let template_data = serde_json::to_value(template_params).map_err(|e| {
-            NotificationError::InternalError(format!("Failed to parse template data: {:?}", e))
-        })?;
+        log::info!("Processing parameter set: {}", sql_params);
 
         // Get the recipients
         let notification_targets = get_notification_targets(
             ctx,
             &scheduled_notification,
-            template_data.clone(),
+            sql_params.clone(),
         )
         .map_err(|e| {
             NotificationError::InternalError(format!("Failed to get notification targets: {:?}", e))
         })?;
 
+        // If there are no recipients, skip this parameter set
+        if notification_targets.is_empty() {
+            log::info!("No notification targets, skipping");
+            continue;
+        }
+
+        let sql_query_parameters = get_notification_query_results(ctx, sql_params, &config)?;
+
+        // Template data should include the notification config parameters, plus the results of any queries
+        template_params.extend(sql_query_parameters);
+
+        let template_data = serde_json::to_value(template_params).map_err(|e| {
+            NotificationError::InternalError(format!("Failed to parse template data: {:?}", e))
+        })?;
+
         // Send the notification
         let notification = NotificationContext {
             title_template: Some(TemplateDefinition::Template(

backend/scheduled/src/query.rs

@@ -1,5 +1,6 @@
 use std::collections::HashMap;
 
+use log::info;
 use repository::{EqualFilter, NotificationQueryFilter, NotificationQueryRepository};
 use serde_json::json;
 use service::service_provider::ServiceContext;
@@ -27,6 +28,7 @@ pub fn get_notification_query_results(
 
     // loop through all the notification query ids, run them, and store the results
     for query in queries {
+        let now = chrono::Utc::now();
         let result = ctx
             .service_provider
             .datasource_service
@@ -45,6 +47,13 @@ pub fn get_notification_query_results(
                 json!([{"error": "error running query", "query": query.query, "parameters": parameters}])
             }
         };
+        let end_time = chrono::Utc::now();
+        info!(
+            "Query {} took {}ms",
+            query.reference_name,
+            (end_time - now).num_milliseconds()
+        );
+
         query_results.insert(query.reference_name, query_json);
     }