public async Task <XDocument> SendAsync(ILogger logger, OutgoingMessage message) { await _core.Send(logger, message, QueueType.Synchronous, _core.Settings.Synchronous.FindReplyQueueForMe()).ConfigureAwait(false); var listener = new SynchronousReplyListener(_core, logger, this); var start = DateTime.UtcNow; var correlationId = message.MessageId; // the name of the game is to get messages off the reply queue as fast as possible since multiple threads may be waiting // therefore all threads take part in the processing. If we read a message from a queue and the process dies, // it's not a big deal since the caller gets an error message; we can then store retrieved messages in an in-memory cache // 1. check if reply message is in in-memory cache // 2. read message and validate it // 3. If nobody is no longer waiting for it, discard it // 4. If message is not the one we are waiting for, place it in the in-memory cache so another thread can read it _pendingSynchronousRequests.TryAdd(correlationId, new MessageEntry() { Payload = null, AddedUtc = DateTime.UtcNow, ToHerId = message.ToHerId, TimedOut = false }); RemoveExpiredSynchronousEntries(logger); while (true) { var payload = CheckPendingEntries(correlationId); if (payload != null) { return(payload); } var incomingMessage = await listener.ReadAndProcessMessage(true).ConfigureAwait(false); if (incomingMessage != null) { // see if this is a message we are waiting for // if that is not the case, the information in incoming message enters the great beyond MessageEntry messageEntry; if (_pendingSynchronousRequests.TryGetValue(incomingMessage.CorrelationId, out messageEntry)) { // if we receive a message a bit late, log it. if (messageEntry.TimedOut) { // enqueue time should be later than when we added it logger.LogWarning(EventIds.SynchronousCallDelayed, "MessageId: {1} was received after {2} seconds from HerId: {3}. Added at {4} Enqueued at: {5}", incomingMessage.CorrelationId, (incomingMessage.EnqueuedTimeUtc - messageEntry.AddedUtc).TotalSeconds, messageEntry.ToHerId, messageEntry.AddedUtc, incomingMessage.EnqueuedTimeUtc); _pendingSynchronousRequests.TryRemove(incomingMessage.CorrelationId, out messageEntry); } else { // update information for existing entry messageEntry.Payload = incomingMessage.Payload; messageEntry.ReplyEnqueuedTimeUtc = incomingMessage.EnqueuedTimeUtc; } } } if (DateTime.UtcNow <= (start + _core.Settings.Synchronous.CallTimeout)) { continue; } // if the request times out, we mark it. That way we can report if the message is received right after a timeout MessageEntry entry; if (_pendingSynchronousRequests.TryGetValue(correlationId, out entry)) { entry.TimedOut = true; } var error = $"Synchronous call {message.MessageId} timed out against HerId: {message.ToHerId}."; logger.LogError(EventIds.SynchronousCallTimeout, error); throw new MessagingException(error) { EventId = EventIds.SynchronousCallTimeout }; } }
public async Task <XDocument> SendAsync(ILogger logger, OutgoingMessage message) { await _core.Send(logger, message, QueueType.Synchronous, _core.Settings.Synchronous.FindReplyQueueForMe()).ConfigureAwait(false); var listener = new SynchronousReplyListener(_core, logger, this); //stopwatch used to measure response time var stopwatch = Stopwatch.StartNew(); var start = DateTime.UtcNow; var correlationId = message.MessageId; // the name of the game is to get messages off the reply queue as fast as possible since multiple threads may be waiting // therefore all threads take part in the processing. If we read a message from a queue and the process dies, // it's not a big deal since the caller gets an error message; we can then store retrieved messages in an in-memory cache // 1. check if reply message is in in-memory cache // 2. read message and validate it // 3. If nobody is no longer waiting for it, discard it // 4. If message is not the one we are waiting for, place it in the in-memory cache so another thread can read it _pendingSynchronousRequests.TryAdd(correlationId, new MessageEntry() { Payload = null, AddedUtc = DateTime.UtcNow, ToHerId = message.ToHerId, TimedOut = false, ScheduledSendTimeUtc = message.ScheduledSendTimeUtc, MessageId = message.MessageId }); RemoveExpiredSynchronousEntries(logger); while (true) { var payload = CheckPendingEntries(correlationId); if (payload != null) { // logs the response time in ms stopwatch.Stop(); logger.LogResponseTime(message.MessageFunction, message.ToHerId, _core.Settings.MyHerId, message.MessageId, stopwatch.ElapsedMilliseconds.ToString()); return(payload); } var incomingMessage = await listener.ReadAndProcessMessage(true).ConfigureAwait(false); if (incomingMessage != null) { // see if this is a message we are waiting for // if that is not the case, the information in incoming message enters the great beyond MessageEntry messageEntry; if (_pendingSynchronousRequests.TryGetValue(incomingMessage.CorrelationId, out messageEntry)) { // if we receive a message a bit late, log it. if (messageEntry.TimedOut) { // enqueue time should be later than when we added it logger.LogWarning(EventIds.SynchronousCallDelayed, $"MessageId: {incomingMessage.CorrelationId} " + $"was received after {(incomingMessage.EnqueuedTimeUtc - messageEntry.AddedUtc).TotalSeconds} seconds " + $"from HerId: {messageEntry.ToHerId}. " + $"Added at {messageEntry.AddedUtc} Enqueued at: {incomingMessage.EnqueuedTimeUtc}. " + $"Sent message Scheduled Send Time at {messageEntry.ScheduledSendTimeUtc}"); _pendingSynchronousRequests.TryRemove(incomingMessage.CorrelationId, out messageEntry); } else { if (messageEntry.ToHerId != incomingMessage.FromHerId) { logger.LogCritical($"HerId of the sender of the reply message differ from the HerId the message was sent to.{Environment.NewLine}" + $"Message sent to HerId {messageEntry.ToHerId}, reply was from {incomingMessage.FromHerId}.{Environment.NewLine}" + $"MessageId, sent: {messageEntry.MessageId} reply: {incomingMessage.MessageId} " + $"CorrelationId: {incomingMessage.CorrelationId}"); } // update information for existing entry messageEntry.Payload = incomingMessage.Payload; messageEntry.ReplyEnqueuedTimeUtc = incomingMessage.EnqueuedTimeUtc; } } } if (DateTime.UtcNow <= (start + _core.Settings.Synchronous.CallTimeout)) { continue; } // if the request times out, we mark it. That way we can report if the message is received right after a timeout MessageEntry entry; if (_pendingSynchronousRequests.TryGetValue(correlationId, out entry)) { entry.TimedOut = true; } var error = $"Synchronous call {message.MessageId} timed out against HerId: {message.ToHerId}."; logger.LogTimeoutError(message.MessageFunction, message.MessageId, message.ToHerId); // logs the response time before throwing exception stopwatch.Stop(); logger.LogResponseTime(message.MessageFunction, message.ToHerId, 0, message.MessageId, stopwatch.ElapsedMilliseconds.ToString()); throw new MessagingException(error) { EventId = EventIds.SynchronousCallTimeout }; } }