Javascript.NodeJS icon indicating copy to clipboard operation
Javascript.NodeJS copied to clipboard

ConnectionException: Process with ID 83312 exited before connecting.

Open CallumVass opened this issue 1 year ago • 28 comments

Hi,

I'm trying to use this library but I keep facing this exception when using version 7 of this library, if I downgrade to 6.3.1 it works fine?

For the avoidance of doubt, I can run node just fine from command line so its definitely on my PATH. I am using .NET 8 (I've tried in .NET 6 and 7 too) and Node 20:

node -v
v20.5.1

dotnet --version
8.0.100

Here is my log output from a small repro:

using Jering.Javascript.NodeJS;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

var services = new ServiceCollection();
services.AddLogging(loggingBuilder =>
{
    loggingBuilder.SetMinimumLevel(LogLevel.Debug);
    loggingBuilder.AddConsole();
});
services.AddNodeJS();
StaticNodeJSService.SetServices(services);

// Invoke
string javascriptModule = @"
module.exports = (callback, x, y) => {  // Module must export a function that takes a callback as its first parameter
    var result = x + y; // Your javascript logic
    callback(null /* If an error occurred, provide an error object or message */, result); // Call the callback when you're done.
}";
int result = await StaticNodeJSService.InvokeFromStringAsync<int>(javascriptModule, args: new object[] { 3, 5 });
Console.WriteLine(result); // 8

Log:

dbug: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      Waiting on process connection semaphore, processID: 81620, thread ID: 1, thread is ThreadPool thread : False.
fail: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      The command line is too long.

warn: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      An attempt to connect to NodeJS failed. Retries remaining: 2.
      Exception:
        Jering.Javascript.NodeJS.ConnectionException: Process with ID 81620 exited before connecting.
         at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.CreateNewProcessAndConnectAsync()
dbug: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      Waiting on process connection semaphore, processID: 74272, thread ID: 11, thread is ThreadPool thread : True.
fail: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      The command line is too long.

warn: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      An attempt to connect to NodeJS failed. Retries remaining: 1.
      Exception:
        Jering.Javascript.NodeJS.ConnectionException: Process with ID 74272 exited before connecting.
         at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.CreateNewProcessAndConnectAsync()
dbug: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      Waiting on process connection semaphore, processID: 83312, thread ID: 11, thread is ThreadPool thread : True.
fail: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      The command line is too long.

Unhandled exception. Jering.Javascript.NodeJS.ConnectionException: Process with ID 83312 exited before connecting.
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.CreateNewProcessAndConnectAsync()
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.ConnectIfNotConnectedAsync(CancellationToken cancellationToken)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.TryInvokeCoreAsync[T](InvocationRequest invocationRequest, CancellationToken cancellationToken)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.InvokeFromStringAsync[T](String moduleString, String cacheIdentifier, String exportName, Object[] args, CancellationToken cancellationToken)

CallumVass avatar Nov 30 '23 19:11 CallumVass

I think the real error is "The command line is too long." which is printed before the process exits (or never even starts). Since the library passes an internal script on the command line, the command line will be quite long already, maybe on your system it gets too long

What OS are you running on? Is the path name to your application and to the node executable very long?

aKzenT avatar Nov 30 '23 20:11 aKzenT

Hiya, thanks for the reply - I'm on Windows 11 and the project isn't nested very deep: C:\Dev\JsSample\JsSample.csproj

But it works fine with 6.3.1, as soon as I upgrade to version 7 thats when the error occurs

CallumVass avatar Dec 01 '23 06:12 CallumVass

I am on MacOS and I am also experiencing this. Tested both static and DI-approach, which not surprisingly, fails in the same way.

ZeldaIV avatar Dec 01 '23 06:12 ZeldaIV

@CallumVass what about the path to the node executable?

@ZeldaIV do you also see the "command line too long" error in the log output?

aKzenT avatar Dec 01 '23 16:12 aKzenT

@aKzenT Likewise, my node executable isn't very deep either: C:\Program Files\nodejs\node.exe

CallumVass avatar Dec 01 '23 17:12 CallumVass

Something happened between 7.0.0-beta.4 and 7.0.0-beta.5 which is causing the issue. It works all the way up to installing beta 5, then I get that error. If I go back to beta 4 it works fine.

CallumVass avatar Dec 01 '23 19:12 CallumVass

@CallumVass Thanks for the details. We did make changes from beta 4 to 5 that affected script length:

  • Moved from webpack to vite. Webpack was minifying the script, vite should be as well?
  • Changed script from cjs to esm

PR: https://github.com/JeringTech/Javascript.NodeJS/pull/173

We need to check how the length of the script changed after these changes.

If it got longer we should shorten it to no longer than before, perhaps more aggressive minification with Vite (if possible) or manual code simplification.

@aKzenT would you like to handle this issue?

JeremyTCD avatar Dec 01 '23 23:12 JeremyTCD

In beta 4 we were passing the configuration to the webpack script. Webpack was automatically minifying when mode was "release":

https://github.com/JeringTech/Javascript.NodeJS/blob/41f70f4894379afc07e16edac370f4b8ea9f1a57/src/NodeJS/Jering.Javascript.NodeJS.csproj#L100-L101

https://github.com/JeringTech/Javascript.NodeJS/blob/41f70f4894379afc07e16edac370f4b8ea9f1a57/src/NodeJS/Javascript/webpack.config.js#L1-L27

In beta 5 we are no longer minifying:

https://github.com/JeringTech/Javascript.NodeJS/blob/5999180f381cb41405f47eb31015be27dfb7facb/src/NodeJS/Jering.Javascript.NodeJS.csproj#L99-L100

https://github.com/JeringTech/Javascript.NodeJS/blob/5999180f381cb41405f47eb31015be27dfb7facb/src/NodeJS/Javascript/vite.config.ts#L1-L8

I've verified that:

import { defineConfig } from "vite";

export default defineConfig({
    build: {
        minify: true,
        emptyOutDir: false,
        ssr: true,
    },
});

as suggested by @CallumVass minifies adequately:

  • Vite minified bundle: 4515 characters
  • Webpack minified bundle: 4717 characters

We just need to pass the configuration to vite.config. I'm not familiar with Vite though, @CallumVass would you like to create a pull request with the necessary changes?

JeremyTCD avatar Dec 02 '23 12:12 JeremyTCD

I've minified it locally using minify: true but it still doesn't work, here is what I see in the console:

dbug: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      Waiting on process connection semaphore, processID: 112264, thread ID: 9, thread is ThreadPool thread : True.
fail: Jering.Javascript.NodeJS.HttpNodeJSService[0]
      Starting inspector on 127.0.0.1:9229 failed: address already in use
      file:///C:/Dev/csharp/JavascriptTest/JavascriptTest/[eval1]:1
      import T from"module";import*as E from"http2";import*as d from"path";import*as I from"stream";var f=(e=>(e[e.Cache=0]="Cache",e[e.File=1]="File",e[e.String=2]="String",e[e.Stream=3]="Stream",e))(f||{});function N(){co
nst e=P(process.argv);S(process.stdout),S(process.stderr),k(parseInt(e.parentPid),!0,1e3);const t=process.cwd(),o=b(t);return O(t),[e,t,o]}function a(e,t){const o=typeof t=="string";e.statusCode=500,e.end(JSON.stringify({er
rorMessage:o?t:t.message,errorStack:o?null:t.stack}))}function p(e){return e.cacheIdentifier==null?`"${e.moduleSource.substring(0,25)}..."`:e.cacheIdentifier}function b(e){const t=[d.join(e,"node_modules")];let o=e,i;for(;(
o=d.dirname(o))!==i;)t.push(d.join(o,"node_modules")),i=o;return t}function P(e){let t=null;const o={};return e.forEach(i=>{if(i.indexOf("--")===0){const c=i.substring(2);o[c]=void 0,t=c}else t!==null&&(o[t]=i,t=null)}),o}f
unction k(e,t,o){setInterval(()=>{w(e)||(console.log(`[Node.js HTTP server] Parent process (pid: ${e}) exited. Exiting this process...`),process.exit())},o),t&&process.on("SIGINT",()=>{console.log("[Node.js HTTP server] Rec
eived SIGINT. Waiting for .NET process to exit...")})}function w(e){try{return process.kill(e,0),!0}catch(t){if(t.code==="EPERM")throw new Error(`Attempted to check whether process ${e} was running, but got a permissions er
ror.`);return!1}}function O(e){function t(c,n){try{return i.apply(this,arguments)}catch(s){if(s.message.startsWith("EPERM")&&typeof o=="string"&&o.startsWith(c)&&s.stack.indexOf("Object.realpathSync ")>=0)return i.call(this
,e,n);throw s}}let o=null,i=null;if(/^win/.test(process.platform))try{o=d._makeLong(e);const c=process.binding("fs");i=c.lstat,typeof i=="function"&&(c.lstat=t)}catch{}}function S(e){const t=e.write;e.write=function(o){typeof o=="string"&&(arguments[0]=o.slice(0,o.length-1)+`\0
                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                          
      SyntaxError: Unexpected end of input
          at DefaultModuleLoader.evalInstance (node:internal/modules/esm/loader:104:22)
          at new ModuleJob (node:internal/modules/esm/module_job:63:26)
          at DefaultModuleLoader.eval (node:internal/modules/esm/loader:115:17)
          at node:internal/process/execution:51:55
          at loadESM (node:internal/process/esm_loader:40:13)
          at evalModule (node:internal/process/execution:51:28)
          at node:internal/main/eval_string:29:3

      Node.js v20.5.1

Looking at the generated script, it doesnt match what is being passed above, the last few characters: +`\0 Are at the end of the first line in the minified script, so it seems to be missing the rest of it?

CallumVass avatar Dec 02 '23 18:12 CallumVass

Odd that it is getting truncated. After changing minify to true, how are you running it locally?

Could you try running the test suite? It passes on my windows 11 machine with minify set to true.

JeremyTCD avatar Dec 03 '23 01:12 JeremyTCD

@JeremyTCD - Yeah I get the same error in tests, using Windows 11 also:

[xUnit.net 00:00:00.92]         SyntaxError: Unexpected end of input

Its the same as above, the script seems truncated. It looks like vite isnt minifying across a single line like the webpack one was doing and that is causing an issue somewhere

CallumVass avatar Dec 03 '23 08:12 CallumVass

The library escapes the script before starting the node process:

https://github.com/JeringTech/Javascript.NodeJS/blob/5999180f381cb41405f47eb31015be27dfb7facb/src/NodeJS/NodeJSServiceImplementations/OutOfProcess/NodeJSProcessFactory.cs#L105-L158

This is where the process start info is created:

https://github.com/JeringTech/Javascript.NodeJS/blob/5999180f381cb41405f47eb31015be27dfb7facb/src/NodeJS/NodeJSServiceImplementations/OutOfProcess/NodeJSProcessFactory.cs#L49-L59

Could you place breakpoints and take a closer look at nodeServerScript?

I can't reproduce the issue on my machine so it's definitely a system-specific problem:

https://github.com/JeringTech/Javascript.NodeJS/assets/11733898/8dc729d2-5297-4767-a740-3d3497b28086

JeremyTCD avatar Dec 03 '23 09:12 JeremyTCD

This is what is passed as arguments to the process via startInfo:

--inspect-brk --input-type=module -e "import T from\"module\";import*as I from\"http\";import*as d from\"path\";import*as E from\"stream\";var f=(e=>(e[e.Cache=0]=\"Cache\",e[e.File=1]=\"File\",e[e.String=2]=\"String\",e[e.Stream=3]=\"Stream\",e))(f||{});function b(){const e=P(process.argv);S(process.stdout),S(process.stderr),$(parseInt(e.parentPid),!0,1e3);const t=process.cwd(),n=N(t);return w(t),[e,t,n]}function c(e,t){const n=typeof t==\"string\";e.statusCode=500,e.end(JSON.stringify({errorMessage:n?t:t.message,errorStack:n?null:t.stack}))}function p(e){return e.cacheIdentifier==null?`\"${e.moduleSource.substring(0,25)}...\"`:e.cacheIdentifier}function N(e){const t=[d.join(e,\"node_modules\")];let n=e,i;for(;(n=d.dirname(n))!==i;)t.push(d.join(n,\"node_modules\")),i=n;return t}function P(e){let t=null;const n={};return e.forEach(i=>{if(i.indexOf(\"--\")===0){const l=i.substring(2);n[l]=void 0,t=l}else t!==null&&(n[t]=i,t=null)}),n}function $(e,t,n){setInterval(()=>{k(e)||(console.log(`[Node.js HTTP server] Parent process (pid: ${e}) exited. Exiting this process...`),process.exit())},n),t&&process.on(\"SIGINT\",()=>{console.log(\"[Node.js HTTP server] Received SIGINT. Waiting for .NET process to exit...\")})}function k(e){try{return process.kill(e,0),!0}catch(t){if(t.code===\"EPERM\")throw new Error(`Attempted to check whether process ${e} was running, but got a permissions error.`);return!1}}function w(e){function t(l,r){try{return i.apply(this,arguments)}catch(s){if(s.message.startsWith(\"EPERM\")&&typeof n==\"string\"&&n.startsWith(l)&&s.stack.indexOf(\"Object.realpathSync \")>=0)return i.call(this,e,r);throw s}}let n=null,i=null;if(/^win/.test(process.platform))try{n=d._makeLong(e);const l=process.binding(\"fs\");i=l.lstat,typeof i==\"function\"&&(l.lstat=t)}catch{}}function S(e){const t=e.write;e.write=function(n){typeof n==\"string\"&&(arguments[0]=n.slice(0,n.length-1)+`\0
`),t.apply(this,arguments)}}const m=T,[O,j,C]=b();J();function J(){const e=I.createServer(L);e.setTimeout(0),e.keepAliveTimeout=0,e.headersTimeout=2147483647,e.on(\"timeout\",_),e.on(\"clientError\",R),e.listen(parseInt(O.port),\"localhost\",()=>{let t=e.address();console.log(`[Jering.Javascript.NodeJS: HttpVersion - HTTP/1.1 Listening on IP - ${t.address} Port - ${t.port}]`)})}function L(e,t){const n=[];e.on(\"data\",i=>n.push(i)).on(\"end\",async()=>{var i;try{const l=Buffer.concat(n).toString();let r;if(e.headers[\"content-type\"]===\"multipart/mixed\"){const o=l.split(\"--Uiw6+hXl3k+5ia0cUYGhjA==\");r=JSON.parse(o[0]),r.moduleSource=o[1]}else r=JSON.parse(l);let s;if(r.moduleSourceType===f.Cache){const o=m._cache[r.moduleSource];if(o==null){t.statusCode=404,t.end();return}s=o.exports}else if(r.moduleSourceType===f.Stream||r.moduleSourceType===f.String){if(r.cacheIdentifier!=null){const o=m._cache[r.cacheIdentifier];o!=null&&(s=o.exports)}if(s==null){const o=new m(\"\",null);o.paths=C,o._compile(r.moduleSource,\"anonymous\"),r.cacheIdentifier!=null&&(m._cache[r.cacheIdentifier]=o),s=o.exports}}else if(r.moduleSourceType===f.File)s=await import(\"file:///\"+d.resolve(j,r.moduleSource).replaceAll(\"\\\\\",\"/\"));else{c(t,`Invalid module source type: ${r.moduleSourceType}.`);return}if(s==null||typeof s==\"object\"&&Object.keys(s).length===0){c(t,`The module ${p(r)} has no exports. Ensure that the module assigns a function or an object containing functions to module.exports.`);return}let a;if(r.exportName!=null){if(a=s[r.exportName]??((i=s.default)==null?void 0:i[r.exportName]),a==null){let o=Object.keys(s).join(\", \");c(t,`The module ${p(r)} has no export named ${r.exportName}. Available exports are: ${o}`);return}if(typeof a!=\"function\"){c(t,`The export named ${r.exportName} from module ${p(r)} is not a function.`);return}}else if(typeof s==\"function\")a=s;else if(typeof s.default==\"function\")a=s.default;else{c(t,`The module ${p(r)} does not export a function.`);return}let g=!1;const y=(o,u,h)=>{if(!g&&(g=!0,o!=null&&c(t,o),!(h!=null&&h(t))))if(u instanceof E.Readable)u.pipe(t);else if(typeof u==\"string\")t.end(u);else{let x;try{x=JSON.stringify(u)}catch(v){c(t,v);return}t.end(x)}};if(a.constructor.name===\"AsyncFunction\")y(null,await a.apply(null,r.args));else{const o=[y];a.apply(null,o.concat(r.args))}}catch(l){c(t,l)}})}function R(e,t){let n=JSON.stringify({errorMessage:e.message,errorStack:e.stack}),i=`HTTP/1.1 500 Internal Server Error\r
Content-Length: ${Buffer.byteLength(n,\"utf8\")}\r
Content-Type: text/html\r
\r
${n}`;t.end(i)}function _(e){console.log(`[Node.js HTTP server] Ignoring unexpected socket timeout for address ${e.remoteAddress}, port ${e.remotePort}`)}
" -- --parentPid 132476 --port 0

It looks like its going over multiple lines so I suspect thats the issue? The \r seems to be causing issues I think

CallumVass avatar Dec 03 '23 20:12 CallumVass

Yes it looks like line endings are the issue. Managed to repro with the script you pasted:

VM88 [eval1]:1 Uncaught SyntaxError: Unexpected end of input
    at ModuleLoader.evalInstance (VM83 loader:203:22)
    at new ModuleJob (VM87 module_job:65:26)
    at ModuleLoader.eval (VM83 loader:215:17)
    at node:internal/process/execution:56:55
    at loadESM (VM82 esm_loader:34:13)
    at evalModule (node:internal/process/execution:56:28)
    at VM80 eval_string:30:3

When you open Http11Server.js, are your line endings crlf or lf?

Untitled

JeremyTCD avatar Dec 04 '23 02:12 JeremyTCD

@CallumVass good catch, I've checked on my machine, the script you pasted has "\r\r\n" line endings.

The original (pre-Vite minification) line:

https://github.com/JeringTech/Javascript.NodeJS/blob/5999180f381cb41405f47eb31015be27dfb7facb/src/NodeJS/Javascript/Servers/OutOfProcess/Http/Http11Server.ts#L211

Not sure what is causing "\r\n"s to become "\r\r\n"s. I can't look too deeply into this right now, but at first glance I think we can just remove the carriage return characters from that string literal.

JeremyTCD avatar Dec 04 '23 02:12 JeremyTCD

@CallumVass what about the path to the node executable?

@ZeldaIV do you also see the "command line too long" error in the log output?

No it just throws ConnectionException on line 445, doesn't really have any details about path in it.

ZeldaIV avatar Dec 04 '23 04:12 ZeldaIV

Yes it looks like line endings are the issue. Managed to repro with the script you pasted:

VM88 [eval1]:1 Uncaught SyntaxError: Unexpected end of input
    at ModuleLoader.evalInstance (VM83 loader:203:22)
    at new ModuleJob (VM87 module_job:65:26)
    at ModuleLoader.eval (VM83 loader:215:17)
    at node:internal/process/execution:56:55
    at loadESM (VM82 esm_loader:34:13)
    at evalModule (node:internal/process/execution:56:28)
    at VM80 eval_string:30:3

When you open Http11Server.js, are your line endings crlf or lf?

Untitled

It says LF: image

CallumVass avatar Dec 04 '23 07:12 CallumVass

@CallumVass good catch, I've checked on my machine, the script you pasted has "\r\r\n" line endings.

The original (pre-Vite minification) line:

https://github.com/JeringTech/Javascript.NodeJS/blob/5999180f381cb41405f47eb31015be27dfb7facb/src/NodeJS/Javascript/Servers/OutOfProcess/Http/Http11Server.ts#L211

Not sure what is causing "\r\n"s to become "\r\r\n"s. I can't look too deeply into this right now, but at first glance I think we can just remove the carriage return characters from that string literal.

Remove the "\r"s and run the tests

JeremyTCD avatar Dec 04 '23 08:12 JeremyTCD

Its still not working, the Http11Server.js is still not on a single line

CallumVass avatar Dec 04 '23 09:12 CallumVass

It works fine on my machine even though it's not on a single line. It's some other problem. If it's not the extra '\r's, I'm not sure what it is.

Can you try Node 20.10.0?

JeremyTCD avatar Dec 04 '23 09:12 JeremyTCD

To add to @JeremyTCD comment, some programs like Visual Studio like to install their own node versions, which might have precedence over the installed version. The library has an option to specify the path to the executable. You could try to set that to your installed Node 20 version just to make sure it is executing the correct one.

aKzenT avatar Dec 04 '23 09:12 aKzenT

Thanks guys for your help but I'm unable to resolve it, the version of Node I'm using is 20.5.1 as seen by one of the errors above.

I've decided to implement my own hosted node server within my .NET app to perform my JS function instead which is working fine, feel free to close this.

CallumVass avatar Dec 04 '23 09:12 CallumVass

@CallumVass

\0

I noticed that in the script you pasted, the line actually ends with \0 which in Windows often indicates the end of a string. So I suspsect that this is the real problem rather than the new lines. @JeremyTCD do you also have the \0 present locally?

aKzenT avatar Dec 04 '23 09:12 aKzenT

@CallumVass apologies on not having a solution.

@aKzenT Yes I do. In the script the \0 is used to demarcate the end of log messages. Agree that it's suspicious his script ends there.

On Mon, 4 Dec 2023, 17:53 aKzenT, @.***> wrote:

@CallumVass https://github.com/CallumVass

\0

I noticed that in the script you pasted, the line actually ends with \0 which in Windows often indicates the end of a string. So I suspsect that this is the real problem rather than the new lines. @JeremyTCD https://github.com/JeremyTCD do you also have the \0 present locally?

— Reply to this email directly, view it on GitHub https://github.com/JeringTech/Javascript.NodeJS/issues/186#issuecomment-1838192444, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACZQXCVFJUOEGU577EHNPULYHWMQ7AVCNFSM6AAAAABABXVOXSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQMZYGE4TENBUGQ . You are receiving this because you were mentioned.Message ID: @.***>

JeremyTCD avatar Dec 04 '23 10:12 JeremyTCD

@CallumVass apologies on not having a solution. @aKzenT Yes I do. In the script the \0 is used to demarcate the end of log messages. Agree that it's suspicious his script ends there. On Mon, 4 Dec 2023, 17:53 aKzenT, @.> wrote: @CallumVass https://github.com/CallumVass \0 I noticed that in the script you pasted, the line actually ends with \0 which in Windows often indicates the end of a string. So I suspsect that this is the real problem rather than the new lines. @JeremyTCD https://github.com/JeremyTCD do you also have the \0 present locally? — Reply to this email directly, view it on GitHub <#186 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACZQXCVFJUOEGU577EHNPULYHWMQ7AVCNFSM6AAAAABABXVOXSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQMZYGE4TENBUGQ . You are receiving this because you were mentioned.Message ID: @.>

No worries, thanks for your help. It looks like a great library but unfortunately it wasn't working for me, and my need is quite simple so it wasn't too difficult to implement, thanks again.

CallumVass avatar Dec 04 '23 10:12 CallumVass