Skip to content

Commit

Permalink
Merge pull request #11 from microsoft/al/logging
Browse files Browse the repository at this point in the history 
updated loggging to include status for responses
  • Loading branch information
@bradarm
bradarm authored Jul 23, 2024
2 parents dcaf7a1 + ff1a1a0 commit 6757447
Show file tree
Hide file tree
Showing 5 changed files with 24 additions and 24 deletions.
6 changes: 3 additions & 3 deletions src/MessageHandlers/MessageHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,7 @@ public void MessageReceived(T message, MessageFormats.Common.DirectToApp fullMes
case string messageType when messageType.Equals(typeof(MessageFormats.HostServices.Sensor.SensorsAvailableResponse).Name, StringComparison.CurrentCultureIgnoreCase):
if (message == null) return;
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, fullMessage.SourceAppId, (message as MessageFormats.HostServices.Sensor.SensorsAvailableResponse)?.ResponseHeader.TrackingId, (message as MessageFormats.HostServices.Sensor.SensorsAvailableResponse)?.ResponseHeader.CorrelationId);
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, fullMessage.SourceAppId, (message as MessageFormats.HostServices.Sensor.SensorsAvailableResponse)?.ResponseHeader.TrackingId, (message as MessageFormats.HostServices.Sensor.SensorsAvailableResponse)?.ResponseHeader.CorrelationId, (message as MessageFormats.HostServices.Sensor.SensorsAvailableResponse)?.ResponseHeader.Status);
if (MessageReceivedEvent == null) break;
Expand All @@ -51,7 +51,7 @@ public void MessageReceived(T message, MessageFormats.Common.DirectToApp fullMes
TaskingPreCheckRequestHandler(message: message as MessageFormats.HostServices.Sensor.TaskingPreCheckRequest, fullMessage: fullMessage);
break;
case string messageType when messageType.Equals(typeof(MessageFormats.HostServices.Sensor.TaskingPreCheckResponse).Name, StringComparison.CurrentCultureIgnoreCase):
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, fullMessage.SourceAppId, (message as MessageFormats.HostServices.Sensor.TaskingPreCheckResponse)?.ResponseHeader.TrackingId, (message as MessageFormats.HostServices.Sensor.TaskingPreCheckResponse)?.ResponseHeader.CorrelationId);
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, fullMessage.SourceAppId, (message as MessageFormats.HostServices.Sensor.TaskingPreCheckResponse)?.ResponseHeader.TrackingId, (message as MessageFormats.HostServices.Sensor.TaskingPreCheckResponse)?.ResponseHeader.CorrelationId, (message as MessageFormats.HostServices.Sensor.TaskingPreCheckResponse)?.ResponseHeader.Status);
if (MessageReceivedEvent == null) break;
Expand All @@ -64,7 +64,7 @@ public void MessageReceived(T message, MessageFormats.Common.DirectToApp fullMes
TaskingRequestHandler(message: message as MessageFormats.HostServices.Sensor.TaskingRequest, fullMessage: fullMessage);
break;
case string messageType when messageType.Equals(typeof(MessageFormats.HostServices.Sensor.TaskingResponse).Name, StringComparison.CurrentCultureIgnoreCase):
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, fullMessage.SourceAppId, (message as MessageFormats.HostServices.Sensor.TaskingResponse)?.ResponseHeader.TrackingId, (message as MessageFormats.HostServices.Sensor.TaskingResponse)?.ResponseHeader.CorrelationId);
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, fullMessage.SourceAppId, (message as MessageFormats.HostServices.Sensor.TaskingResponse)?.ResponseHeader.TrackingId, (message as MessageFormats.HostServices.Sensor.TaskingResponse)?.ResponseHeader.CorrelationId, (message as MessageFormats.HostServices.Sensor.TaskingResponse)?.ResponseHeader.Status);
if (MessageReceivedEvent == null) break;
Expand Down
24 changes: 12 additions & 12 deletions src/MessageHandlers/SensorDataHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,44 +8,44 @@ private void SensorDataHandler(MessageFormats.HostServices.Sensor.SensorData? me
using (var scope = _serviceProvider.CreateScope()) {
DateTime maxTimeToWait = DateTime.Now.Add(TimeSpan.FromMilliseconds(_appConfig.MESSAGE_RESPONSE_TIMEOUT_MS));

_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, fullMessage.SourceAppId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogInformation("Processing message type '{messageType}' from '{sourceApp}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, fullMessage.SourceAppId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);

_logger.LogDebug("Passing message '{messageType}' to plugins (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogDebug("Passing message '{messageType}' to plugins (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);

MessageFormats.HostServices.Sensor.SensorData? pluginResult =
_pluginLoader.CallPlugins<MessageFormats.HostServices.Sensor.SensorData?, Plugins.PluginBase>(
orig_request: message,
pluginDelegate: _pluginDelegates.SensorData);

_logger.LogDebug("Plugins finished processing '{messageType}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogDebug("Plugins finished processing '{messageType}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);

// Update the request if our plugins changed it
if (pluginResult == null) {
_logger.LogInformation("Plugins nullified '{messageType}'. Dropping Message (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogInformation("Plugins nullified '{messageType}'. Dropping Message (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);
return;
}

message = pluginResult;

// Message is populated with the origin Tasking Tracking Id. Pull it to calculate the destination app Id
if (!string.IsNullOrWhiteSpace(message.TaskingTrackingId)) {
_logger.LogDebug("Message '{messageType}' has TaskingTrackingId '{taskingTrackingId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.TaskingTrackingId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogDebug("Message '{messageType}' has TaskingTrackingId '{taskingTrackingId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.TaskingTrackingId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);

TaskingRequest? orig_request = _client.GetCacheItem<TaskingRequest>(cacheItemName: message.TaskingTrackingId).Result;

if (orig_request == null) {
_logger.LogError("No TaskingTrackingId of '{taskingTrackingId}' found in cache. Unable to route message. Dropping message. (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.TaskingTrackingId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogError("No TaskingTrackingId of '{taskingTrackingId}' found in cache. Unable to route message. Dropping message. (trackingId: '{trackingId}' / correlationId: '{correlationId}'/ status: '{status}')", message.TaskingTrackingId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);
return;
}

message.DestinationAppId = orig_request.RequestHeader.AppId;
_logger.LogDebug("Found app '{original_app_id}' for TaskingTrackingId '{taskingTrackingId}'. (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.DestinationAppId, message.TaskingTrackingId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogDebug("Found app '{original_app_id}' for TaskingTrackingId '{taskingTrackingId}'. (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.DestinationAppId, message.TaskingTrackingId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);
}


// No destination App ID, and no tracking ID specified. Route the message to any subscribers
if (string.IsNullOrWhiteSpace(message.DestinationAppId)) {
_logger.LogTrace("Message '{messageType}' is a broadcast (message has no DestinationAppId) (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogTrace("Message '{messageType}' is a broadcast (message has no DestinationAppId) (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);


// Retrieve the items from cache
Expand All @@ -56,22 +56,22 @@ private void SensorDataHandler(MessageFormats.HostServices.Sensor.SensorData? me
foreach (Google.Protobuf.WellKnownTypes.Value sensor_subscription in sensor_subscriptions.Values) {
var list = Core.ServicesOnline();
if (Core.ServicesOnline().Any(heartbeat_pulse => heartbeat_pulse.AppId.Equals(sensor_subscription.StringValue, StringComparison.InvariantCultureIgnoreCase))) {
_logger.LogInformation("Sending message '{messageType}' to '{appId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, sensor_subscription.StringValue, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogInformation("Sending message '{messageType}' to '{appId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, sensor_subscription.StringValue, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);
_client.DirectToApp(appId: sensor_subscription.StringValue, message: message).Wait();
} else {
_logger.LogError("Unable to route message '{messageType}'. '{appId}' is not online. (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, sensor_subscription.StringValue, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogError("Unable to route message '{messageType}'. '{appId}' is not online. (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, sensor_subscription.StringValue, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);
}
}
}
} else {
// Original app ID is online. Send the message and then end cleanly
if (Core.ServicesOnline().Any(heartbeat_pulse => heartbeat_pulse.AppId.Equals(message.DestinationAppId, StringComparison.InvariantCultureIgnoreCase))) {
_logger.LogInformation("Sending message '{messageType}' to '{appId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.DestinationAppId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogInformation("Sending message '{messageType}' to '{appId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.DestinationAppId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);

// Append the sensor ID for topic suffix so we can authZ the response going back to the app
_client.DirectToApp(appId: message.DestinationAppId, message: message).Wait();
} else {
_logger.LogError("Unable to route message '{messageType}'. '{appId}' is not online. (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.DestinationAppId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId);
_logger.LogError("Unable to route message '{messageType}'. '{appId}' is not online. (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, message.DestinationAppId, message.ResponseHeader.TrackingId, message.ResponseHeader.CorrelationId, message.ResponseHeader.Status);
}
}
};
Expand Down
6 changes: 3 additions & 3 deletions src/MessageHandlers/SensorsAvailableRequestHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -87,20 +87,20 @@ void SensorsAvailableResponseCallback(object? sender, MessageFormats.HostService
return;
}

_logger.LogInformation("Response to request message type '{messageType}' is '{returnResponseStatus}' (Response Message is '{returnResponseMessage}') (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, returnResponse.ResponseHeader.Status, returnResponse.ResponseHeader.Message, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId);
_logger.LogInformation("Response to request message type '{messageType}' is '{returnResponseStatus}' (Response Message is '{returnResponseMessage}') (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, returnResponse.ResponseHeader.Status, returnResponse.ResponseHeader.Message, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId, returnResponse.ResponseHeader.Status);


if (returnResponse.ResponseHeader.Status == MessageFormats.Common.StatusCodes.Successful) {
_logger.LogTrace("Caching '{messageType}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId);
_client.SaveCacheItem(cacheItem: message, cacheItemName: message.RequestHeader.TrackingId, expiration: DateTime.UtcNow.AddMinutes(15)).Wait();
} else {
_logger.LogWarning("Unable to process '{messageType}'. Response Status is '{returnResponseStatus}'. Response Message is '{returnResponseMessage}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", message.GetType().Name, returnResponse.ResponseHeader.Status, returnResponse.ResponseHeader.Message, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId);
_logger.LogWarning("Unable to process '{messageType}'. Response Status is '{returnResponseStatus}'. Response Message is '{returnResponseMessage}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", message.GetType().Name, returnResponse.ResponseHeader.Status, returnResponse.ResponseHeader.Message, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId, returnResponse.ResponseHeader.Status);
}

returnResponse = output_response;
message = output_request;

_logger.LogInformation("Routing message type '{messageType}' to '{appId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}')", returnResponse.GetType().Name, fullMessage.SourceAppId, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId);
_logger.LogInformation("Routing message type '{messageType}' to '{appId}' (trackingId: '{trackingId}' / correlationId: '{correlationId}' / status: '{status}')", returnResponse.GetType().Name, fullMessage.SourceAppId, message.RequestHeader.TrackingId, message.RequestHeader.CorrelationId, returnResponse.ResponseHeader.Status);
_client.DirectToApp(appId: fullMessage.SourceAppId, message: returnResponse);
};
}
Expand Down
Loading

0 comments on commit 6757447

Please sign in to comment.