iisnode icon indicating copy to clipboard operation
iisnode copied to clipboard

Published 20 hours ago • verified publisher icon tjanczuk

Permission issue

Open bkniffler opened this issue 11 years ago • 14 comments

Hi, I've setup nodejs and iisnode on my Server 2008 R2. The iis website was automatically setup using Plesk, which means its AppPool identity is set to IWAM_plesk(default). I'm using iisnode 0.2.7 and 10.22 nodejs.

This user I granted read/execute rights on both iisnode folders (program files x86/iisnode and program files/iisnode) and node.exe in my program files (program files x86/node/node.exe). I've granted that user full rights on the website directory.

My web.config looks like so:

<configuration>
  <system.webServer>
    <iisnode loggingEnabled="false"/>
    <handlers>
      <add name="iisnode" path="server.js" verb="*" modules="iisnode" />
    </handlers>
    <rewrite>
           <rules>
                <rule name="StaticContent">
                     <action type="Rewrite" url="public{REQUEST_URI}"/>
                </rule>
                <rule name="DynamicContent">
                     <conditions>
                          <add input="{REQUEST_FILENAME}" matchType="IsFile" negate="True"/>
                     </conditions>
                     <action type="Rewrite" url="server.js"/>
                </rule>
           </rules>
      </rewrite>
     <defaultDocument enabled="true">
      <files>
        <add value="server.js" />
      </files>
    </defaultDocument>
  </system.webServer>
</configuration>

Now, I keep on getting:

iisnode encountered an error when processing the request.

HRESULT: 0x2
HTTP status: 500
HTTP reason: Internal Server Error
You are receiving this HTTP 200 response because system.webServer/iisnode/@devErrorsEnabled configuration setting is 'true'.

In addition to the log of stdout and stderr of the node.exe process, consider using debugging and ETW traces to further diagnose the problem.

You may get additional information about this error condition by logging stdout and stderr of the node.exe process.To enable logging, set the system.webServer/iisnode/@loggingEnabled configuration setting to 'true' (current value is 'false').

As soon as I use LocalSystem for the AppPool, it works fine. I've tried setting on/off logging via web.config, I've tried granting all kinds of rights to the user on all involved folders. I've tried using multiple iisnode versions (0.1.2, 0.2.4, 0.2.6, 0.2.8) and multiple nodejs versions (8.* and 10.*). But I can't get it to work without LocalSystem.

Any ideas?

bkniffler avatar Nov 19 '13 17:11 bkniffler

Did you set the ACLs to propagate to subfolders of wwwroot? See https://github.com/tjanczuk/iisnode/blob/master/src/scripts/setupsamples.bat#L41 for reference.

tjanczuk avatar Nov 19 '13 17:11 tjanczuk

Thanks for your quick response. As far as I can see it, all subfolders and files have inherited the permissions. To make sure everything is ok, I ran

icacls "httpdocs" /grant "IWAM_plesk(default)":(OI)(CI)F

It didn't change anything so far.

bkniffler avatar Nov 19 '13 18:11 bkniffler

I assume you have restarted IIS after setting these permissions?

My next 2 steps to investigate would be:

  1. Use ETW with iisnode to understand at which point the message is failing: http://tomasz.janczuk.org/2011/09/using-event-tracing-for-windows-to.html
  2. Use Process Monitor http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx to see what ACL checks are failing.

tjanczuk avatar Nov 19 '13 18:11 tjanczuk

I've restarted using iisreset.

Here is the Process Monitor output: foto

Here is the ETW:

<Events>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{9e814aad-3204-11d2-9a82-006008a86939}" />
        <EventID>0</EventID>
        <Version>2</Version>
        <Level>0</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:12.095204100Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="4380" ThreadID="2216" ProcessorID="0" KernelTime="0" UserTime="15" />
        <Channel />
        <Computer />
    </System>
    <EventData>
        <Data Name="BufferSize">    8192</Data>
        <Data Name="Version">83951878</Data>
        <Data Name="ProviderVersion">    7601</Data>
        <Data Name="NumberOfProcessors">       4</Data>
        <Data Name="EndTime">130293799988295791</Data>
        <Data Name="TimerResolution">  156250</Data>
        <Data Name="MaxFileSize">       0</Data>
        <Data Name="LogFileMode">0x0</Data>
        <Data Name="BuffersWritten">       4</Data>
        <Data Name="StartBuffers">       1</Data>
        <Data Name="PointerSize">       8</Data>
        <Data Name="EventsLost">       0</Data>
        <Data Name="CPUSpeed">    2534</Data>
        <Data Name="LoggerName">0x2</Data>
        <Data Name="LogFileName">0x7</Data>
        <Data Name="BootTime">130293508861250000</Data>
        <Data Name="PerfFreq">10000000</Data>
        <Data Name="StartTime">130293799920952041</Data>
        <Data Name="ReservedFlags">0x1</Data>
        <Data Name="BuffersLost">       0</Data>
        <Data Name="SessionNameString">iisnode</Data>
        <Data Name="LogFileNameString">C:\Users\ADMINI~1\AppData\Local\Temp\2\iisnode.etl</Data>
    </EventData>
    <RenderingInfo Culture="de-DE">
        <Opcode>Header</Opcode>
        <Provider>MSNT_SystemTrace</Provider>
        <EventName xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">EventTrace</EventName>
    </RenderingInfo>
    <ExtendedTracingInfo xmlns="http://schemas.microsoft.com/win/2004/08/events/trace">
        <EventGuid>{68fdd900-4a3e-11d1-84f4-0000f80464e3}</EventGuid>
    </ExtendedTracingInfo>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.610679900Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>iisnode initialized the application manager</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.610681900Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>iisnode received a new http request</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.615739400Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>iisnode initialized a new node.exe process</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.616180300Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>iisnode initialized a new node.js application</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.616204800Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode increases pending async operation count</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.616240900Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode scheduled a retry of a named pipe connection to the node.exe process </Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>4</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.616263200Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode dispatched new http request</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.616264600Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode decreases pending async operation count</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.616265900Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode leaves CNodeHttpModule::OnExecuteRequestHandler with RQ_NOTIFICATION_PENDING</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>2</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.663012900Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="6052" ProcessorID="2" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>iisnode detected termination of node.exe process</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>2</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858486300Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7660" ProcessorID="0" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode was unable to establish named pipe connection to the node.exe process before the process terminated</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858499500Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7660" ProcessorID="0" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode request processing failed for reasons unrecognized by iisnode</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858695200Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7660" ProcessorID="1" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode decreases pending async operation count</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858697800Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7660" ProcessorID="1" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode posts completion from SendEmtpyResponse</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858740200Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="1" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode increases pending async operation count</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858742200Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="1" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode enters CNodeHttpModule::OnAsyncCompletion callback</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858744000Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="1" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode decreases pending async operation count</Data>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
    <System>
        <Provider Guid="{1040dfc4-61db-484a-9530-584b2735f7f7}" />
        <EventID>0</EventID>
        <Version>0</Version>
        <Level>5</Level>
        <Task>0</Task>
        <Opcode>0</Opcode>
        <Keywords>0x0</Keywords>
        <TimeCreated SystemTime="2013-11-20T01:13:16.858746000Z" />
        <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
        <Execution ProcessID="9064" ThreadID="7856" ProcessorID="1" KernelTime="0" UserTime="0" />
        <Channel />
        <Computer />
    </System>
        <Data>{9847492A-870E-4E06-9512-8C9C10355843}: iisnode leaves CNodeHttpModule::OnAsyncCompletion with RQ_NOTIFICATION_FINISH_REQUEST</Data>
</Event>
</Events>

I guess this one is the important info:

iisnode detected termination of node.exe process

But I can't read any hint for the course. Any idea?

bkniffler avatar Nov 20 '13 00:11 bkniffler

From iisnode's perspective the node.exe is started successfuly, but then it unexpectedly terminates before it has a chance to establish a listener. Are you doing anything ACL sensitive within your node app itself? Can you try running a simple hello.world node.js app under the same credentials and see if that works? Perhaps you should run the process monitor on node.exe now to see if it fails any ACL checks.

tjanczuk avatar Nov 21 '13 17:11 tjanczuk

Okay, I've setup the hello world example, no success. Next, I've taken a look at node.exe process info through process monitor: proc

Seems like interceptor.js is responsible by getting a buffer overflow. Then node wants to create a file on C: drive, which doesnt work as its not permitted. I just have no idea why a buffer overlow might occur and what file node wants to create on my C: drive..

bkniffler avatar Nov 21 '13 23:11 bkniffler

@bkniffler did you find any solution in the meantime? I'm having the same issues now...

sibbl avatar Sep 22 '14 15:09 sibbl

@bkniffler any solution ? same issue , please !

danielrobleM avatar Feb 05 '16 08:02 danielrobleM

Hi, I gave up using iisnode after these issues appeared, as I wasn't able to resolve them. I switched to using NSSM to keep my apps running while IIS serverfarm and url-redirect would redirect my domains/subdomains to the nodeJS ports. Checkout https://github.com/bkniffler/node-nssm-iis/blob/master/README.md for helper scripts.

Or just set up everything manually. NSSM should be straightforward, IIS serverfarm + url-redirect like here, just ignore the whole teamcity installation stuff and jump down to the serverfarm setup: https://blogs.endjin.com/2010/11/a-step-by-step-guide-to-hosting-teamcity-in-iis-7/

ps. Even though I managed to get everything running with these methods, I would recommend using Ubuntu or any other Linux to run your nodeJS apps, checkout digitalocean.com with dokku for easy git push deploys. Heroku works fine too.

bkniffler avatar Feb 05 '16 10:02 bkniffler

@danielrobleM and @sibbl did you guys find anything? I am also having the same issue and almost at the brink of giving up on iisnode

karun-r avatar Sep 25 '17 04:09 karun-r

Hi @karun-r, same answer that @bkniffler , I gave up using iisnode.

danielrobleM avatar Sep 26 '17 12:09 danielrobleM

I don't ever regret having entered the world of docker and heroku. Might not be applicable if you really need to run on windows for native windows stuff though.

bkniffler avatar Sep 26 '17 12:09 bkniffler

Looks like I have no other viable option. Already wasted two days trying to troubleshoot this issue. My app is just a single page application with not so heavy traffic so maybe I will just leave it running in the background and let it host itself.

karun-r avatar Sep 26 '17 17:09 karun-r

I know this is not totally related, but since this post helped me I wanted to help others that might stumble on here. My case was a isolated one in which I was using nvm to manage my node versions, and so I was getting access denied (looking through procmon) on the nvm folder where node resided. So I gave IIS_IUSRS access to that folder, and everything started to work.

johndevedu avatar Aug 23 '18 21:08 johndevedu