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.

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

Fixing Node memory leak (#2313) #2320

Merged
merged 1 commit into from
Jan 17, 2018
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
158 changes: 85 additions & 73 deletions src/WebJobs.Script/Description/Node/NodeFunctionInvoker.cs
Original file line number Diff line number Diff line change
Expand Up @@ -243,24 +243,27 @@ private static async Task ProcessOutputBindingsAsync(Collection<FunctionBinding>
return;
}

var bindings = (Dictionary<string, object>)scriptExecutionContext["bindings"];
var functionResultDictionary = (IDictionary<string, object>)functionResult;
var returnValue = functionResultDictionary["returnValue"];
var bindingValues = (IDictionary<string, object>)functionResultDictionary["bindingValues"];

var returnValueBinding = outputBindings.SingleOrDefault(p => p.Metadata.IsReturn);
if (returnValueBinding != null)
{
// if there is a $return binding, bind the entire function return to it
// if additional output bindings need to be bound, they'll have to use the explicit
// context.bindings mechanism to set values, not return value.
bindings[ScriptConstants.SystemReturnParameterBindingName] = functionResult;
bindingValues[ScriptConstants.SystemReturnParameterBindingName] = returnValue;
}
else
{
// if the function returned binding values via the function result,
// apply them to context.bindings
if (functionResult is IDictionary<string, object> functionOutputs)
if (returnValue is IDictionary<string, object> functionOutputs)
{
foreach (var output in functionOutputs)
{
bindings[output.Key] = output.Value;
bindingValues[output.Key] = output.Value;
}
}
}
Expand All @@ -269,13 +272,13 @@ private static async Task ProcessOutputBindingsAsync(Collection<FunctionBinding>
{
// get the output value from the script
object value = null;
bool haveValue = bindings.TryGetValue(binding.Metadata.Name, out value);
bool haveValue = bindingValues.TryGetValue(binding.Metadata.Name, out value);
if (!haveValue && string.Compare(binding.Metadata.Type, "http", StringComparison.OrdinalIgnoreCase) == 0)
{
// http bindings support a special context.req/context.res programming
// model, so we must map that back to the actual binding name if a value
// wasn't provided using the binding name itself
haveValue = bindings.TryGetValue("res", out value);
haveValue = bindingValues.TryGetValue("res", out value);
}

// apply the value to the binding
Expand Down Expand Up @@ -348,70 +351,14 @@ protected override void Dispose(bool disposing)

private async Task<Dictionary<string, object>> CreateScriptExecutionContextAsync(object input, DataType dataType, TraceWriter traceWriter, FunctionInvocationContext invocationContext)
{
// create a TraceWriter wrapper that can be exposed to Node.js
var log = (ScriptFunc)(p =>
Copy link
Member Author

Choose a reason for hiding this comment

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

The log and metric functions I pushed out into static factory methods, to prevent regressions. The factory functions take WeakReferences, so we won't accidentally regress things going forward.

{
var logData = (IDictionary<string, object>)p;
string message = (string)logData["msg"];
if (message != null)
{
try
{
TraceLevel level = (TraceLevel)logData["lvl"];
var evt = new TraceEvent(level, message);

// Node captures the AsyncLocal value of the first invocation, which means that logs
// are correlated incorrectly. Here we'll overwrite that value with the correct value
// immediately before logging.
using (BeginFunctionScope(invocationContext))
{
// TraceWriter already logs to ILogger
traceWriter.Trace(evt);
}
}
catch (ObjectDisposedException)
{
// if a function attempts to write to a disposed
// TraceWriter. Might happen if a function tries to
// log after calling done()
}
}

return Task.FromResult<object>(null);
});

var metric = (ScriptFunc)(p =>
{
var metricObject = (IDictionary<string, object>)p;
string name = (string)metricObject["name"];
object valueObject = metricObject["value"];

if (name != null && valueObject != null)
{
double value = Convert.ToDouble(valueObject);

// properties are optional
var properties = (IDictionary<string, object>)metricObject["properties"];

using (BeginFunctionScope(invocationContext))
{
invocationContext.Logger.LogMetric(name, value, properties);
}
}

return Task.FromResult<object>(null);
});

var bindings = new Dictionary<string, object>();
var bind = (ScriptFunc)(p =>
{
IDictionary<string, object> bindValues = (IDictionary<string, object>)p;
foreach (var bindValue in bindValues)
{
bindings[bindValue.Key] = bindValue.Value;
}
return Task.FromResult<object>(null);
});
// It's important that we use WeakReferences here for objects captured by
// these function closures. Otherwise, due to the nature of how we're using Edge.js
// we'll get memory leaks (we're establishing bi-directional communication between
// .NET and Node).
var traceWriterReference = new WeakReference<TraceWriter>(traceWriter);
var invocationContextReference = new WeakReference<FunctionInvocationContext>(invocationContext);
var log = CreateLoggerFunc(traceWriterReference, invocationContextReference);
var metric = CreateMetricFunc(invocationContextReference);

var executionContext = new Dictionary<string, object>
{
Expand All @@ -420,14 +367,14 @@ private async Task<Dictionary<string, object>> CreateScriptExecutionContextAsync
["functionDirectory"] = invocationContext.ExecutionContext.FunctionDirectory,
};

var bindings = new Dictionary<string, object>();
var context = new Dictionary<string, object>()
{
{ "invocationId", invocationContext.ExecutionContext.InvocationId },
{ "executionContext", executionContext },
{ "log", log },
{ "_metric", metric },
{ "bindings", bindings },
{ "bind", bind }
{ "log", log },
{ "_metric", metric }
};

if (!string.IsNullOrEmpty(_entryPoint))
Expand Down Expand Up @@ -495,6 +442,71 @@ private async Task<Dictionary<string, object>> CreateScriptExecutionContextAsync
return context;
}

private static ScriptFunc CreateLoggerFunc(WeakReference<TraceWriter> traceWriterReference, WeakReference<FunctionInvocationContext> invocationContextReference)
{
return (ScriptFunc)(p =>
{
var logData = (IDictionary<string, object>)p;
string message = (string)logData["msg"];
if (message != null)
{
try
{
// Node captures the AsyncLocal value of the first invocation, which means that logs
// are correlated incorrectly. Here we'll overwrite that value with the correct value
// immediately before logging.
TraceWriter traceWriter = null;
FunctionInvocationContext invocationContext = null;
if (traceWriterReference.TryGetTarget(out traceWriter) &&
invocationContextReference.TryGetTarget(out invocationContext))
{
using (BeginFunctionScope(invocationContext))
{
// TraceWriter already logs to ILogger
TraceLevel level = (TraceLevel)logData["lvl"];
var evt = new TraceEvent(level, message);
traceWriter.Trace(evt);
}
}
}
catch (ObjectDisposedException)
{
// if a function attempts to write to a disposed
// TraceWriter. Might happen if a function tries to
// log after calling done()
}
}

return Task.FromResult<object>(null);
Copy link
Member

Choose a reason for hiding this comment

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

nit: Use Task.CompletedTask

Copy link
Member Author

@mathewc mathewc Jan 17, 2018

Choose a reason for hiding this comment

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

That doesn't work because this is a Task<object> not Task

Copy link
Member

Choose a reason for hiding this comment

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

👍
Just looked at this line (not the signature) and assumed this was just using an old pattern from the existing code.

});
}

private static ScriptFunc CreateMetricFunc(WeakReference<FunctionInvocationContext> invocationContextReference)
{
return (ScriptFunc)(p =>
{
var metricObject = (IDictionary<string, object>)p;
string name = (string)metricObject["name"];
object valueObject = metricObject["value"];

if (name != null && valueObject != null)
{
double value = Convert.ToDouble(valueObject);
FunctionInvocationContext invocationContext = null;
if (invocationContextReference.TryGetTarget(out invocationContext))
{
using (BeginFunctionScope(invocationContext))
{
var properties = (IDictionary<string, object>)metricObject["properties"];
invocationContext.Logger.LogMetric(name, value, properties);
}
}
}

return Task.FromResult<object>(null);
});
}

private static IDisposable BeginFunctionScope(FunctionInvocationContext context)
{
// Node captures the AsyncLocal value of the first invocation, which means that logs
Expand Down
19 changes: 13 additions & 6 deletions src/WebJobs.Script/azurefunctions/functions.js
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ function createFunction(f) {
origMetric({ name: name, value: value, properties: properties});
};

context.done = function (err, result) {
context.done = function (err, returnValue) {
if (context._done) {
if (context._promise) {
context.log("Error: Choose either to return a promise or call 'done'. Do not use both in your script.");
Expand All @@ -70,16 +70,23 @@ function createFunction(f) {
callback(err);
}
else {
var values = {};
if (context.res && context.bindings.res === undefined) {
context.bindings.res = context.res;
}

// because Edge.JS interop doesn't flow new values added to objects,
// we capture the binding values and pass them back as part of the
// result
var bindingValues = {};
for (var name in context.bindings) {
values[name] = context.bindings[name];
bindingValues[name] = context.bindings[name];
}
context.bind(values, function (err) {
Copy link
Member Author

@mathewc mathewc Jan 17, 2018

Choose a reason for hiding this comment

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

Previously we were calling back into .NET here to allow it to process these binding values. We were doing this to enable us to capture any context.bindings[xxx] values the user code might have set. Edge.JS interop won't capture new properties added to objects/dictionaries.

With my changes, rather than call back into .NET to copy these values into the bindings collection, we just return the values as part of the response.

callback(err, result);
});

var result = {
returnValue: returnValue,
bindingValues: bindingValues
};
callback(null, result);
}
};

Expand Down