Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WebServiceTarget - FlushAsync - Avoid premature flush #1868

Merged
merged 4 commits into from
Jan 11, 2017
Merged

WebServiceTarget - FlushAsync - Avoid premature flush #1868

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
e50ffbb
WebServiceTarget - FlushAsync - Keeps track of pendingRequests to avo…
snakefoot Dec 19, 2016
945a7ca
WebServiceTarget - FlushAsync - Just keep track of pending request count
snakefoot Dec 19, 2016
9b66b6a
Merge https://github.com/NLog/NLog into WebServiceTargetFlush
snakefoot Jan 1, 2017
89a8519
WebServiceTarget - FlushAsync - Just keep track of pending request co…
snakefoot Jan 1, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
229 changes: 193 additions & 36 deletions src/NLog/Targets/WebServiceTarget.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,6 +180,7 @@ public WebServiceTarget(string name) : this()
/// <docgen category='Web Service Options' order='10' />
public string XmlRootNamespace { get; set; }

private readonly Dictionary<HttpWebRequest, KeyValuePair<DateTime,AsyncContinuation>> _pendingRequests = new Dictionary<HttpWebRequest, KeyValuePair<DateTime,AsyncContinuation>>();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

isn't HttpWebRequest an expensive key value?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Another way would be using a linkedlist and send the info with the AsyncContinuation (if possible)?

Copy link
Contributor Author

@snakefoot snakefoot Dec 19, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

isn't HttpWebRequest an expensive key value?

I was hoping it was acting like a normal class, and just used default class-reference-hashcode.

Another way would be using a linkedlist

Yet another option is just to monitor the last written LogEvent.

And yet yet another option is to have a single counter of outstanding requests, and then keep a queue of flush-callbacks. When a flush is requested one caches the pending request count, and when it reaches zero, then it fires the flush-callback. Then it would only be a list of pending flush-callbacks and a pending-counter.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was hoping it was acting like a normal class, and just used default class-reference-hashcode.

yes 're right!

// The default implementation returns the sync block index for this instance.
// Calling it on the same object multiple times will return the same value, so
// it will technically meet the needs of a hash function, but it's less than ideal.
// Objects (& especially value classes) should override this method.

https://referencesource.microsoft.com/#mscorlib/system/object.cs,4de9cf234d0d8b16


/// <summary>
/// Calls the target method. Must be implemented in concrete classes.
Expand Down Expand Up @@ -226,73 +227,229 @@ protected override void DoInvoke(object[] parameters, AsyncContinuation continua
{
if (ex != null)
{
KeyValuePair<DateTime, AsyncContinuation> flushCallback;
lock (this.SyncRoot)
{
if (_pendingRequests.TryGetValue(request, out flushCallback))
_pendingRequests.Remove(request);
}
continuation(ex);
if (flushCallback.Value != null)
flushCallback.Value(ex);
return;
}

request.BeginGetResponse(
r =>
{
try
try
{
request.BeginGetResponse(
r =>
{
using (var response = request.EndGetResponse(r))
try
{
using (var response = request.EndGetResponse(r))
{
}

KeyValuePair<DateTime, AsyncContinuation> flushCallback;
lock (this.SyncRoot)
{
if (_pendingRequests.TryGetValue(request, out flushCallback))
_pendingRequests.Remove(request);
}
continuation(null);
if (flushCallback.Value != null)
flushCallback.Value(null);
}

continuation(null);
}
catch (Exception ex2)
{
InternalLogger.Error(ex2, "Error when sending to Webservice.");

if (ex2.MustBeRethrown())
catch (Exception ex2)
{
throw;
InternalLogger.Error(ex2, "Error when sending to Webservice: {0}", this.Name);
if (ex2.MustBeRethrown())
{
throw;
}

KeyValuePair<DateTime, AsyncContinuation> flushCallback;
lock (this.SyncRoot)
{
if (_pendingRequests.TryGetValue(request, out flushCallback))
_pendingRequests.Remove(request);
}
continuation(ex2);
if (flushCallback.Value != null)
flushCallback.Value(ex2);
}
},
null);
}
catch (Exception ex2)
{
InternalLogger.Error(ex2, "Error when sending to Webservice: {0}", this.Name);
if (ex2.MustBeRethrown())
{
throw;
}

continuation(ex2);
}
},
null);
KeyValuePair<DateTime, AsyncContinuation> flushCallback;
lock (this.SyncRoot)
{
if (_pendingRequests.TryGetValue(request, out flushCallback))
_pendingRequests.Remove(request);
}
continuation(ex2);
if (flushCallback.Value != null)
flushCallback.Value(ex2);
}
};

if (postPayload != null && postPayload.Length > 0)
{
postPayload.Position = 0;
beginFunc(
result =>
try
{
lock (this.SyncRoot)
{
try
lock (this.SyncRoot)
_pendingRequests.Add(request, new KeyValuePair<DateTime, AsyncContinuation>(DateTime.UtcNow, null));
}
beginFunc(
result =>
{
using (Stream stream = getStreamFunc(result))
try
{
WriteStreamAndFixPreamble(postPayload, stream, this.IncludeBOM, this.Encoding);
using (Stream stream = getStreamFunc(result))
{
WriteStreamAndFixPreamble(postPayload, stream, this.IncludeBOM, this.Encoding);

postPayload.Dispose();
postPayload.Dispose();
}

sendContinuation(null);
}
catch (Exception ex)
{
InternalLogger.Error(ex, "Error when sending to Webservice: {0}", this.Name);
if (ex.MustBeRethrown())
{
throw;
}

sendContinuation(null);
}
catch (Exception ex)
{
postPayload.Dispose();
InternalLogger.Error(ex, "Error when sending to Webservice.");
KeyValuePair<DateTime, AsyncContinuation> flushCallback;
lock (this.SyncRoot)
{
if (_pendingRequests.TryGetValue(request, out flushCallback))
_pendingRequests.Remove(request);
}

if (ex.MustBeRethrown())
{
throw;
postPayload.Dispose();

continuation(ex);
if (flushCallback.Value != null)
flushCallback.Value(ex);
}
});
}
catch (Exception ex)
{
InternalLogger.Error(ex, "Error when sending to Webservice: {0}", this.Name);
if (ex.MustBeRethrown())
{
throw;
}

continuation(ex);
}
});
KeyValuePair<DateTime, AsyncContinuation> flushCallback;
lock (this.SyncRoot)
{
if (_pendingRequests.TryGetValue(request, out flushCallback))
_pendingRequests.Remove(request);
}
continuation(ex);
if (flushCallback.Value != null)
flushCallback.Value(ex);
}
}
else
{
lock (this.SyncRoot)
_pendingRequests.Add(request, new KeyValuePair<DateTime, AsyncContinuation>(DateTime.UtcNow, null));
sendContinuation(null);
}
}

/// <summary>
/// Flush any pending log messages asynchronously (in case of asynchronous targets).
/// </summary>
/// <param name="asyncContinuation">The asynchronous continuation.</param>
protected override void FlushAsync(AsyncContinuation asyncContinuation)
{
// We want to be notified when, all pending requests have completed
if (_pendingRequests.Count == 0)
{
asyncContinuation(null);
}
else
{
int remainingCount = _pendingRequests.Count;
AsyncContinuation continuation =
ex =>
{
// ignore exception
if (System.Threading.Interlocked.Decrement(ref remainingCount) == 0)
{
asyncContinuation(null);
}
};

DateTime utcNowTimeout = DateTime.UtcNow.AddSeconds(-120); // Default HttpWebRequest.Timeout = 100 secs

bool foundOldWebRequest = false;

foreach (var key in new List<HttpWebRequest>(_pendingRequests.Keys))
{
KeyValuePair<DateTime, AsyncContinuation> flushCallback;
if (_pendingRequests.TryGetValue(key, out flushCallback))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

don't we need a lock here?

Copy link
Contributor Author

@snakefoot snakefoot Dec 19, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FlushAsync is already protected by this.SyncRoot. Same lock-object is used for the other manipulations. But I can add an explicit lock, so it will not confuse.

Copy link
Member

@304NotModified 304NotModified Dec 19, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Missed that, thx! No need to add it IMO then

{
AsyncContinuation oldFlushCallback = flushCallback.Value;
if (flushCallback.Key < utcNowTimeout)
{
try
{
_pendingRequests.Remove(key);
if (!foundOldWebRequest)
{
foundOldWebRequest = true;
InternalLogger.Warn("Failed to get reply from one (or more) requests to Webservice: {0}", this.Name);
}
if (oldFlushCallback != null)
oldFlushCallback(null);
continuation(null);
}
catch (Exception ex)
{
if (ex.MustBeRethrown())
throw;
}
}
else
{
if (oldFlushCallback == null)
_pendingRequests[key] = new KeyValuePair<DateTime, AsyncContinuation>(flushCallback.Key, continuation);
else
_pendingRequests[key] = new KeyValuePair<DateTime, AsyncContinuation>(flushCallback.Key, ex => { oldFlushCallback(ex); continuation(ex); });
}
}
}
}
}

/// <summary>
/// Closes the target.
/// </summary>
protected override void CloseTarget()
{
_pendingRequests.Clear(); // Maybe consider to wait a short while if pending requests?
base.CloseTarget();
}

/// <summary>
/// Builds the URL to use when calling the web service for a message, depending on the WebServiceProtocol.
/// </summary>
Expand Down
9 changes: 9 additions & 0 deletions tests/NLog.UnitTests/Targets/WebServiceTargetTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -454,6 +454,15 @@ public void WebserviceTest_restapi_httppost_checkingLost()
logger.Info(createdMessage);
}

// Make triple-flush to fully exercise the async flushing logic
try
{
LogManager.Flush(0);
}
catch (NLog.NLogRuntimeException)
{ }
LogManager.Flush(); // Waits for flush (Scheduled on top of the previous flush)
LogManager.Flush(); // Nothing to flush
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should users also do a triple-flush?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No triple flush is only for code-coverage :)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sounds we should have split those tests.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

});


Expand Down