Sunday, November 17, 2013

CQ dispatcher vs Apache MultiViews

The short(er) version
The Apache MultiViews option in the <Directory> configuration will cause the request processing to end and return a 404 response instead of letting the request continue on to the remaining Apache modules in the processing chain such as mod_rewrite and mod_dispatcher.

This seems to happen when requesting a document that exists in a directory that is not yet on the filesystem and the MultiViews content negotiation code does not know what to do with the request.

The two instances I found this to occur in were requests for files without an extension, such as j_security_check, and paths that contain non-standard characters like a colon (:) such as those found in requests for CQ content stored beneath a jcr:content node. E.g.:
POST http://local.mysite.dev/content/mysite/en/login/j_security_check
GET http://local.mysite.dev/content/mysite/en/index/jcr:content/left/news.html
Some more background
So I encountered this maddening problem last week with the CQ dispatcher not quite working as it should have without an obvious reason.

The issue I was running into was that certain requests were returning a 404 response when the request passed through the dispatcher while the same request worked just fine when going directly to a publish instance (i.e. direct to the publish port such as 4503).

The problem turned out to be the Apache MultiViews option set on the <Directory> used by the virtualhost that served up my CQ website. I had Apache configured to pass all requests through to mod_dispatcher. In other words, no rewrites or proxies were configured at the Apache level.

For the most part everything worked great, cached as expected and all was well. But there were a handful of requests that were returning a 404 error for no apparent reason.

There were two requests in particular being plagued by these mystery 404's:
  • The website's login request
  • A request for data that was stored in the pages jcr:content
Illustration of the problem

A request that did work
Here's an example of a request that was passing through the dispatcher without problems and caching as expected.
Request URL: GET http://local.mysite.dev/content/mysite/en/login.html
Dispatcher Cache: /www/htdocs/content/mysite/en/login.html
Actual Results: request rendered and cached as expected
This one is a login page. Upon first request, when the dispatcher had not yet created a cached copy, the request passed through to mod_dispatcher, went to publish, rendered and was cached on the file system.

A request that was not working
Ok, so far so good. Everything seems to be working and the dispatcher is doing it's job. But now I submit the form and expect to see a request go to through the dispatcher into the publish instance.

Since it is a POST request I expect to see it go to publish every time.
Request URL: POST http://local.mysite.dev/content/mysite/en/login/j_security_check
Dispatcher Cache: N/A because it is a POST request
Actual Results: request returned 404 instead of passing through to the publish instance
But alas, I was not so fortunate. No traffic was registered in the publish instance and I get a 404 error in my browser. Hell, I get one even when I use cURL. The Apache request log did log the request so I know it go into the web server but the dispacher.log did not show any traffic. Hmmmm...

Of course when I went straight to the publish instance on port 4503 I everything worked just fine. I'm logged in and seeing my site. Something's up with my dispatcher configuration.

Another request that was not working
Thinking maybe something is weird with login requests I decided to try loading a different page in the website through the dispatcher to see if that worked.
Request URL: GET http://local.mysite.dev/content/mysite/en/index/jcr:content/left/news.html
Dispatcher Cache: /www/htdocs/content/mysite/en/lindex/jcr:content/left/news.html
Actual Results: request returned 404 instead of passing through to the publish instance, no file cached
This one had some news content that was a part of a news component on the page which stored its data under the page's node in the JCR. Most of the page loaded and cached just fine but that extra bit of content was also returning a 404.

Weird. This one was for an HTML document and I already had other HTML documents passing through and caching just fine. But this one was not working for some odd ball reason.

Finding the culprit
I spent a fair amount of time performing trial end error with different configurations but was unable to find a consistent rhyme or reason to the 404's I was seeing. Checking all the logs, I couldn't spot anything that was telling me what was wrong.

At least, not at first.

Hell, I could barely find anything in the logs for these requests beyond the Apache access_log registering the request. Nothing in the dispatcher.log, nothing in the publish logs. Weird.

Then I took a look at the Apache error_log and saw a log entry I'd not seen before (or at least never cared about before):
[Thu Nov 14 11:19:30 2013] [error] [client 127.0.0.1] Negotiation: discovered file(s) matching request: /www/htdocs/content/mysite/en/login (None could be negotiated)., referer: http://local.mysite.dev/content/mysite/en/login.html
Huh? Ok, well, maybe Google would have something to say about that error message. And as it turns out, it had a lot to say about it. The very first hit was a blog talking about a very similar problem:

http://www.bennadel.com/blog/2218-Negotiation-Discovered-File-s-Matching-Request-None-Could-Be-Negotiated.htm

Well, whaddya know? MultiViews eh? No idea why I'd need that. Let's see what happens when I remove it. So change this:
<Directory "/www/htdocs">
    Options Indexes FollowSymLinks MultiViews
    AllowOverride all
    Order allow,deny
    Allow from all
</Directory>
To this (MultiViews removed):
<Directory "/www/htdocs">
    Options Indexes FollowSymLinks
    AllowOverride all
    Order allow,deny
    Allow from all
</Directory>
Ah ha!
Of course once I removed that option my logins started working and news started showing up every time. In fact, it's been pretty smooth sailing with the dispatcher ever since.

And now it pretty much makes sense. The content negotiation processing turned on by the MultiViews directive really didn't like that missing directory.

I'm not sure why it didn't care about missing directories for that initial login.html request. Perhaps it understood based on the file extension that eventually one would be there at some point later on in the Apache request process chain. But when that extension does not exist or a funny character is present in the request path it sure looks like the content negotiation just gives up and goes home.

Frankly, I'm not really sure I care about the specifics on when the code that backs the MultiViews when and won't 404 early at this point. I'm just glad taking it out of the equation did the trick in this case (where I really do just want Apache to pass it on to the CQ dispatcher module thank you ;).

Conclusion
So far, I very much enjoy working with the CQ (now called AEM) CMS. I really dig the way it works and the tools it gives developers, authors, businesses and users. It has its moments, such as this, and could use some love in some areas. But overall it's a very cool platform.

This problem however was the kind that drives programmers to drink the hard stuff early in the day!

I'm not sure if I'm just lucky with the version of Apache I'm working with (the stock Apache on OS X 10.8). I'm just glad things are working the way they are supposed to now. Sometimes it just takes enough iterations of slamming your head into a concrete wall before you find and recognize the error message for what it is.

Hope this gives someone a chuckle or even helps save someone a bit of time.

3 comments:

  1. AWESOME POST! Related note - you should also write about the clean vs. dirty way to do ProxyPassReverse. Pretty please? (Scold and direct if you already have...)

    ReplyDelete
  2. Thanks Brandon, you thinking about the trick we've used to proxy app servers behind Apache in general or something specific on the app server-to-browser side of things?

    ReplyDelete
  3. Thanks for this post. Very helpful. Couldn't find any info about it on Adobe site.

    ReplyDelete