IIS Dispatcher not caching:Unable to open temporary file

[kevinx18367959]

Good Morning,

I installed dispatcher-iis-windows-x64-4.3.2 and AEM 6.2 SP1 on my win10 laptop following Installing Dispatcher .

I'm able to access page http://localhost:8000/content/we-retail.html normally. But the problem is that none file is cached.

I'm sure I have given write access to  Application Pool User (AEM in my case) for docroot.

Based on the log, error is "Unable to open temporary file C:\inetpub\wwwroot\aem\content\we-retail.html_PJNAa21612: Permission denied" . Cannot understand what happened to my server. Any idea?

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] HTTP keepalive is enabled, timeout is 60 seconds.

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] Dispatcher initializing (build 4.3.2/iis-windows-x64)

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] farms[publish].cache.docroot = C:\inetpub\wwwroot\aem

[Fri May 03 21:54:08 2019] [I] [pid 8872 (tid 21612)] Dispatcher initialized (build 4.3.2/iis-windows-x64)

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] Initializing PRNG with seed: 581453824

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] Found farm publish for localhost

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] checking [/content/we-retail.html]

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] Cache rule entry /0000 allowed '/content/we-retail.html'

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] cachefile does not exist: C:\inetpub\wwwroot\aem\content\we-retail.html

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] try to create new cachefile: C:\inetpub\wwwroot\aem\content\we-retail.html

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] cache-action for [/content/we-retail.html]: CREATE

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] Filter rule entry /0023 allowed 'GET /content/we-retail.html HTTP/1.1'

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] Creating new socket: 127.0.0.1:4503

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] Connected to backend rend01 (127.0.0.1:4503)

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.uri = "/content/we-retail.html"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Cache-Control] = "max-age=0"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Accept] = "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Accept-Encoding] = "gzip, deflate, br"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Accept-Language] = "zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Cookie] = "_ga= xxx] request.headers[Host] = "localhost:8000"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[User-Agent] = "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.108 Safari/537.36"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Upgrade-Insecure-Requests] = "1"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Via] = "1.1 localhost (dispatcher)"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[X-Forwarded-For] = "::1"

[Fri May 03 21:54:08 2019] [T] [pid 8872 (tid 21612)] request.headers[Server-Agent] = "Communique-Dispatcher"

[Fri May 03 21:54:08 2019] [E] [pid 8872 (tid 21612)] Unable to open temporary file C:\inetpub\wwwroot\aem\content\we-retail.html_PJNAa21612: Permission denied

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] response.status = 200

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] response.headers[Date] = "Fri, 03 May 2019 13:54:08 GMT"

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] response.headers[X-Content-Type-Options] = "nosniff"

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] response.headers[X-Frame-Options] = "SAMEORIGIN"

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] response.headers[Content-Type] = "text/html; charset=UTF-8"

[Fri May 03 21:54:08 2019] [D] [pid 8872 (tid 21612)] Storing socket for later reuse: 127.0.0.1:4503

[Fri May 03 21:54:08 2019] [I] [pid 8872 (tid 21612)] "GET /content/we-retail.html" 200 2951 66ms [publish/rend01]

[Jaideep_Brar]

Looks like a permissions issue. Can you check the if the user running the dispatcher process has full rights on the "C:\inetpub\wwwroot\aem\" folder.

If this is still an issue, try deleting everything under "C:\inetpub\wwwroot\aem\" and try again.

[kevinx18367959]

Hi JaideepBrar,

Thanks for your update!

I can see the process w3wp.exe is running with user AEM. and the pid is the same with pid in log.

By reviewing folder property of "C:\inetpub\wwwroot\aem", I can see user AEM already has full access to it.

After clearing the folder, even restarted by system. I still has the same issue, error is in below:

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] Found farm publish for localhost

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] checking [/content/we-retail.html]

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] Cache rule entry /0000 allowed '/content/we-retail.html'

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] cachefile does not exist: C:\inetpub\wwwroot\aem\content\we-retail.html

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] try to create new cachefile: C:\inetpub\wwwroot\aem\content\we-retail.html

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] cache-action for [/content/we-retail.html]: CREATE

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] Filter rule entry /0023 allowed 'GET /content/we-retail.html HTTP/1.1'

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] Dropping socket after 246 seconds of inactivity: 127.0.0.1:4503

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] Creating new socket: 127.0.0.1:4503

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] Connected to backend rend01 (127.0.0.1:4503)

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.uri = "/content/we-retail.html"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Cache-Control] = "max-age=0"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Accept] = "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Accept-Encoding] = "gzip, deflate, br"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Accept-Language] = "zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Cookie] = "_ga=GA1.1.1290135572.1552898230; login-  [Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Host] = "localhost:8000"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[User-Agent] = "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Upgrade-Insecure-Requests] = "1"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Via] = "1.1 localhost (dispatcher)"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[X-Forwarded-For] = "::1"

[Sat May 04 14:49:21 2019] [T] [pid 12444 (tid 12548)] request.headers[Server-Agent] = "Communique-Dispatcher"

[Sat May 04 14:49:21 2019] [E] [pid 12444 (tid 12548)] Unable to create parent directory C:\inetpub\wwwroot\aem\content: Permission denied

[Sat May 04 14:49:21 2019] [D] [pid 12444 (tid 12548)] response.status = 200

[Sat May 04 15:09:07 2019] [D] [pid 12444 (tid 12552)] Found farm publish for localhost

[Sat May 04 15:09:07 2019] [D] [pid 12444 (tid 12552)] checking [/dispatcher/invalidate.cache]

[Sat May 04 15:09:07 2019] [I] [pid 12444 (tid 12552)] Activation detected: action=Activate [/content/we-retail]

[Sat May 04 15:09:07 2019] [W] [pid 12444 (tid 12552)] Unable to create file C:\inetpub\wwwroot\aem\.stat: Permission denied

[Sat May 04 15:09:07 2019] [D] [pid 12444 (tid 12552)] response.status = 200

[Sat May 04 15:09:07 2019] [D] [pid 12444 (tid 12552)] response.headers[Server] = "Communique/2.6.3 (build 5221)"

[Sat May 04 15:09:07 2019] [D] [pid 12444 (tid 12552)] response.headers[Content-Type] = "text/html"

[Sat May 04 15:09:07 2019] [D] [pid 12444 (tid 12552)] cache flushed

[Sat May 04 15:09:07 2019] [I] [pid 12444 (tid 12552)] "GET /dispatcher/invalidate.cache" 200 13 0ms [publish/-]

[kevinx18367959 · Accepted solution]

This permission issue is resolved by granting write permission to IUSR by referring to AEM Dispatcher config for IIS missing IUSR permission

Shouldn't the documentation be updated accordingly as the user Brent Landry mentioned?  It cost us much time debugging this issue.