search

tjanczuk / iisnode

Hosting node.js applications in IIS on Windows
Other
1.85k stars 588 forks source link

Permission issue #309

Open bkniffler opened 10 years ago

bkniffler commented 10 years ago

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?

tjanczuk commented 10 years ago

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.

bkniffler commented 10 years ago

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.

tjanczuk commented 10 years ago

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.
bkniffler commented 10 years ago

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?

tjanczuk commented 10 years ago

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.

bkniffler commented 10 years ago

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..

sibbl commented 10 years ago

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

danielrobleM commented 8 years ago

@bkniffler any solution ? same issue , please !

bkniffler commented 8 years ago

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.

karun-r commented 7 years ago

@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

danielrobleM commented 7 years ago

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

bkniffler commented 7 years ago

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.

karun-r commented 7 years ago

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.

johndevedu commented 6 years ago

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.