Kudu: Duplicate querystring pairs

[jbrantly]

Repro steps.

• Deploy a node-based app to App Services
• Enable web server logging
• Hit a page that contains a querystring variable, such as http://mysite/?foo=bar
• Check the web server logs and notice that the entry for the hit contains duplicated querystring values, eg [date] [servername] GET / foo=bar&foo=bar&X-ARR-LOG-ID=[guid]

Project structures.

I have duplicated this in two different node apps. One app uses a custom iisnode.yml and web.config but they are not too far off from the defaults. The other app does not use a custom iisnode.yml or web.config but instead has them generated by the kudu deployment command. The first app uses node 7.7.4 and the second uses 8.0.0.

I believe the URL logged in the web server logs comes straight from IIS and is not affected at all by the node app itself. Therefore I think the issue is either in the IIS configuration further up the chain or some other process that I'm unaware of.

Mention any other details that might be useful.

I also happen to have a .NET application deployed to App Services as well that does not exhibit the issue.

I discovered this because of an issue with the querystring being too long and hitting requestFiltering limits. Despite the original querystring being under the limit, the duplicated value put it over and triggered IIS filtering those requests into 404.15.

[davidebbo]

@jbrantly this sounds like something happening at runtime, and not related to Kudu (which only takes care of the deployment).

Is the duplication only in the log, or do you actually see it at runtime in your Node app?

[davidebbo]

I tried printing req.url from a trivial Node app, and duplication doesn't happen (though I do see it in the http log).

[davidebbo]

So I found what's causing it, but I don't really understand it. The default web.config we generate has this to allow serving static content from public folder:

        <rule name="StaticContent">
          <action type="Rewrite" url="public{REQUEST_URI}"/>
        </rule>

And somehow it has the side effect of duplicating the query string in the http log. @rramachand21 does that make any sense to you, given that the path does not match this pattern at all?

[jbrantly]

Is the duplication only in the log, or do you actually see it at runtime in your Node app?

I don't see it at runtime in the Node app which is good. However, its more than just showing in the log as it apparently affects IIS request filtering.

[davidebbo]

Ok, I figured it out. Instead of public{REQUEST_URI}, it should be public{PATH_INFO}.

Can you give this a try? Go in Kudu console, and modify web.config in your site\wwwroot folder, then try again.

[jbrantly]

I can confirm that fixes the log file and the request filtering issue. Thanks!

I can't comment on whether or not that breaks the static content stuff 😄

[davidebbo]

I did a basic test and static content still works. However, we've been using this same config for like 5 years, so I'm too scared to make this change given that the issue is harmless and the potential to break things is there. If someone runs into this and is annoyed by it, hopefully they can find this issue and hand fix it.

If we get a ton of feedback, maybe we can reconsider, but for now, let's leave this alone :)

[lionello]

This is still a bug! And the reason is that the StaticContent rule uses REQUEST_URI, which include the query string, but also has AppendQueryString set to true (the default), so after the rewrite rule the URL gets split again between path and query, and now the query is doubled.

This bug effectively halves the maximum URL length, from the usual 2048 bytes to 1024!

[lionello]

@davidebbo There's no reason an app would want all query parameters to be double! If you don't want to change the rule to use PATH_INFO, at least consider setting AppendQueryString to false.

[lionello]

Failed Request Trace Log:

1. | RULE_EVALUATION_START | RuleName="StaticContent", RequestURL="confirmLogin", QueryString="key=value", PatternSyntax="Regex", StopProcessing="false", RelativePath="/" | 06:32:51.740
2. | PATTERN_MATCH | Pattern="", Input="confirmLogin", Negate="false", Matched="true" | 06:32:51.740
3. | REWRITE_ACTION | Substitution="public{REQUEST_URI}", RewriteURL="/public/confirmLogin?key=value", AppendQueryString="true", LogRewrittenURL="false" | 06:32:51.740
4. | RULE_EVALUATION_END | RuleName="StaticContent", RequestURL="public/confirmLogin", QueryString="?key=value&key=value", StopProcessing="false", Succeeded="true" | 06:32:51.740

[lionello]

For the record, this is the faulty line in the template:

https://github.com/projectkudu/kudu/blob/2ea953e532d0a44afe291dc4b9e370df9fc51686/Kudu.Core/Scripts/iisnode.config.template#L26

[davidebbo]

Changing it to PATH_INFO. Based on some more testing, it doesn't seem to break anything. Though it still comes with a risk since it's been like that for years. We'll see.

[davidebbo]

Note that this change is now fully deployed. Please verify that it all works with no workarounds now.

[lionello]

Works!