App crash on large number of errors

[DaniilSokolyuk]

When a heavy load and a large number of errors from node.js, the application crashes with an error

Index was outside the bounds of the array.
   at System.String.get_Chars(Int32 index)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.TryCreateMessage(StringBuilder stringBuilder, String data, String& message)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.ErrorDataReceivedHandler(Object sender, DataReceivedEventArgs evt)
   at System.Diagnostics.Process.ErrorReadNotifyUser(String data)
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi)
   at System.Threading.QueueUserWorkItemCallback.<>c.<.cctor>b__6_0(QueueUserWorkItemCallback quwi)
   at System.Threading.ExecutionContext.RunForThreadPoolUnsafe[TState](ExecutionContext executionContext, Action`1 callback, TState& state)
   at System.Threading.QueueUserWorkItemCallback.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

[JeremyTCD]

Do you know what your JS is writing to console?

TryCreateMessage processes stdout, accumulating characters until '\0':

Javascript.NodeJS/src/NodeJS/NodeJSServiceImplementations/OutOfProcess/OutOfProcessNodeJSService.cs

Lines 320 to 339 in fbd57f7

	internal virtual bool TryCreateMessage(StringBuilder stringBuilder, string data, out string message)
	{
	// OutputDataReceived is called everytime a newline character is read. The event data supplied to the callback
	// is a string containing all the characters between the previous newline character and the most recent one.
	// In other words, the stream is read line by line. The last line in each message ends with a null terminating
	// character (see HttpServer).
	if (data[data.Length - 1] != '\0')
	{
	stringBuilder.AppendLine(data);
	message = null;
	return false;
	}
	stringBuilder.Append(data);
	stringBuilder.Length--; // Remove null terminating character
	message = stringBuilder.ToString();
	stringBuilder.Length = 0;
	return true;
	}

Javascript.NodeJS/src/NodeJS/NodeJSServiceImplementations/OutOfProcess/OutOfProcessNodeJSService.cs

Lines 281 to 305 in fbd57f7

	internal void OutputDataReceivedHandler(object _, DataReceivedEventArgs evt, EventWaitHandle waitHandle)
	{
	if (evt.Data == null)
	{
	return;
	}
	if (!_nodeJSProcess.Connected && evt.Data.StartsWith(CONNECTION_ESTABLISHED_MESSAGE_START))
	{
	OnConnectionEstablishedMessageReceived(evt.Data);
	if (_debugLoggingEnabled)
	{
	Logger.LogDebug(string.Format(Strings.LogDebug_OutOfProcessNodeJSService_BeforeSet, Thread.CurrentThread.ManagedThreadId.ToString()));
	}
	waitHandle.Set();
	}
	else if (TryCreateMessage(_outputDataStringBuilder, evt.Data, out string message))
	{
	// Process output is received line by line. The last line of a message ends with a \0 (null character),
	// so we accumulate lines in a StringBuilder till the \0, then log the entire message in one go.
	Logger.LogInformation(message);
	}
	}

Will try to reproduce in unit tests tomorrow, if you know what your applications is writing to stdout (console.log(...)) or you can debug and check what the data argument is on crashes it'll help.

Edit:

Check if data is ever an empty string. Offhand, the only time data[data.Length - 1] might throw an index out of range exception is if data.Length == 0, in which case we'd be passing -1 to the indexer, data[-1].

TODO tomorrow:

• Add condition data.length > 0 to be safe.
• Investigate why OutputDataReceivedHandler is receiving an empty string in the first place, likely has something to do with:

Javascript.NodeJS/src/NodeJS/Javascript/Servers/OutOfProcess/Http/HttpServer.ts

Lines 274 to 288 in fbd57f7

	function demarcateMessageEndings(outputStream: NodeJS.WritableStream) {
	const origWriteFunction = outputStream.write;
	outputStream.write = <any>function (value: any) {
	// Only interfere with the write if it's definitely a string
	if (typeof value === 'string') {
	// Node appends a new line character at the end of the message. This facilitates reading of the stream: the process reading it reads messages line by line -
	// characters stay in its buffer until a new line character is received. This means that the null terminating character must appear before the last
	// new line character of the message. This approach is slightly heavy handed in that it removes all whitespace at the end of the message, generally,
	// such whitespace is pointless.
	arguments[0] = arguments[0].trimRight() + '\0\n';
	}
	origWriteFunction.apply(this, arguments);
	};
	}

value can't be a string when the exception is thrown, because if it is, final length >= 2. Therefore console.log(null) or console.log(undefined) is being called. Check logging of objects too, console.log(obj), do we need to call toString and manually add null terminator?

[JeremyTCD]

I've updated my previous comment, I think calling console.log(undefined) or console.log(null) may cause the error. Need to test and add guards.

[DaniilSokolyuk]

@JeremyTCD
Some error from workerpool library when terminate pool, data is empty

[JeremyTCD]

Thanks for the extra info. #55 handles the case where data is an empty string.

I'd still like to figure out why empty strings are being written to stdout/stderr by Node.js. Turns out console.log(null), console.log(undefined) and console.log(obj) work fine.

Could you share how I can reproduce your situation?

[JeremyTCD]

Turns out data is empty when log messages contain an empty line, e.g console.log('a\n\nb'). TryCreateMessage wasn't handling empty lines properly.

In your case, most probably some library called console.error with a detailed message containing empty lines for formatting.

Thanks for reporting this bug. I've released v4.4.1 with the fix. Feel free to close this issue if it resolves the problem for you.

[DaniilSokolyuk]

@JeremyTCD thank you for fix, issue resolved