Fixed PreBodyTagFilter partial writes handling #555

Merged
merged 2 commits into from Oct 22, 2013

Conversation

Projects
None yet
3 participants
@CGijbels
Collaborator

CGijbels commented Oct 8, 2013

The PreBodyTagFilter filter we assign to the Response.Filter property when Glimpse <script...> tags need to be injected, didn't cope well with partial writes. As it seems, it is quite possible that the PreBodyTagFilter.Write(byte[] buffer, int offset, int count) is called multiple times when streaming the output for one request. There seems to be a buffer size of a little bit less than 16K (16352 bytes), which results in outputs of more than 16K to be written in multiple calls to that method.

Most of the time this wasn't giving any issues, but there are some specific cases that aren't dealt with properly:

  • multiple warnings were being written to the glimpse.log because the </body> tag could not be found in the first chunks, even though the script injection succeeded because it eventually found a </body> tag in the last chunk. This is now fixed and the warning will only be written when there is effectively no </body> tag found
  • If you were very unlucky and the chunks actually split up your </body> tag (chunk1 ends with </bo and chunk2 starts with dy> then Glimpse script tags would not be injected even though the received HTML markup contains a </body> tag. This is now fixed as well

You could simulate the old situation by simply creating the following controller action, you'll see that Glimpse scripts are not being injected, even though there is a </body> tag.

public ActionResult TestFilterIssue()
{
    return new ContentResult
    {
        Content = "<html><body>" + new string('X', 16337) + "</body></html>"
    };
}
@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 8, 2013

Collaborator

I've added tests for most cases, but an additional pair of eyes is welcome to see that I did not miss something

Collaborator

CGijbels commented Oct 8, 2013

I've added tests for most cases, but an additional pair of eyes is welcome to see that I did not miss something

@ghost ghost assigned CGijbels Oct 8, 2013

@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 9, 2013

Collaborator

Just to inform you how I discovered this bug: I added the RawUrl of the request to the warning log when I was investigating some other issue, and after doing that I noticed that I had warning messages for requests for whom Glimpse script tags were injected successfully, which made no sense at all.

Collaborator

CGijbels commented Oct 9, 2013

Just to inform you how I discovered this bug: I added the RawUrl of the request to the warning log when I was investigating some other issue, and after doing that I noticed that I had warning messages for requests for whom Glimpse script tags were injected successfully, which made no sense at all.

CGijbels referenced this pull request Oct 14, 2013

Refactored AppDomain unloading logging
Because currently the logs were not always written due to the
asynchronous way of logging by NLog (the AppDomain got unloaded before
the writes were done)
This also cleans up the HttpModule class for a subsequent PR, because
now the extraction of the shutdown message is refactored into its own
class.
@avanderhoorn

This comment has been minimized.

Show comment
Hide comment
@avanderhoorn

avanderhoorn Oct 14, 2013

Member

Is this ready to go? If so I will get @nikmd23 to do the once over and see if we can get it in for the next release. Also, are there any other issues (as in github issues) that people have raised that this will fix?

Member

avanderhoorn commented Oct 14, 2013

Is this ready to go? If so I will get @nikmd23 to do the once over and see if we can get it in for the next release. Also, are there any other issues (as in github issues) that people have raised that this will fix?

@avanderhoorn

This comment has been minimized.

Show comment
Hide comment
@avanderhoorn

avanderhoorn Oct 14, 2013

Member

Also WOW on finding the issue and working through the various test cases. Great job!

Member

avanderhoorn commented Oct 14, 2013

Also WOW on finding the issue and working through the various test cases. Great job!

@avanderhoorn

This comment has been minimized.

Show comment
Hide comment
@avanderhoorn

avanderhoorn Oct 14, 2013

Member

Lastly just because I know @nikmd23 will ask, why the switchover from the automatic properties to fields? Was it so they could be made readonly?

Member

avanderhoorn commented Oct 14, 2013

Lastly just because I know @nikmd23 will ask, why the switchover from the automatic properties to fields? Was it so they could be made readonly?

@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 14, 2013

Collaborator

No other issue has been reported, I noticed this one myself by looking at the Glimpse log while debugging another issue ;-) I added the RawUrl to the log, because I guessed it could help me resolve why I was getting a WARN with regards to the missing </body> tag and saw RawUrls from pages that rendered the Glimpse client without any issue and after some investigation it seemed that it was not that uncommon for the filter to be called multiple times during the same request.

I think if people would look at the Glimpse logs, they would see those WARN messages popping up, but without a negative impact on the client (especially in webform environments where viewstate might become quiet large)

Anyway, this fix will at least remove some of the false positives we get in other bug reports when we ask for log details... and I will add an issue pointing to this PR so that it gets in the release notes.

Collaborator

CGijbels commented Oct 14, 2013

No other issue has been reported, I noticed this one myself by looking at the Glimpse log while debugging another issue ;-) I added the RawUrl to the log, because I guessed it could help me resolve why I was getting a WARN with regards to the missing </body> tag and saw RawUrls from pages that rendered the Glimpse client without any issue and after some investigation it seemed that it was not that uncommon for the filter to be called multiple times during the same request.

I think if people would look at the Glimpse logs, they would see those WARN messages popping up, but without a negative impact on the client (especially in webform environments where viewstate might become quiet large)

Anyway, this fix will at least remove some of the false positives we get in other bug reports when we ask for log details... and I will add an issue pointing to this PR so that it gets in the release notes.

@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 14, 2013

Collaborator

With regards to the automatic properties, I was reworking the whole class so I did not paid to much attention to the current uses since I was changing a lot of things. Now on the other hand private automatic properties don't seem to add additional value and you loose indeed something like marking them readonly, which highlights that the fields are really only input and are not supposed to be changed afterwards. But this might lead into some kind of religious debate which has no added value.

Are there specific conventions used? Because not all files are formatted the same or apply the same semantics.

Collaborator

CGijbels commented Oct 14, 2013

With regards to the automatic properties, I was reworking the whole class so I did not paid to much attention to the current uses since I was changing a lot of things. Now on the other hand private automatic properties don't seem to add additional value and you loose indeed something like marking them readonly, which highlights that the fields are really only input and are not supposed to be changed afterwards. But this might lead into some kind of religious debate which has no added value.

Are there specific conventions used? Because not all files are formatted the same or apply the same semantics.

@avanderhoorn

This comment has been minimized.

Show comment
Hide comment
@avanderhoorn

avanderhoorn Oct 14, 2013

Member

Its not documented anywhere but @nikmd23 generally prefers automatic properties and tries not to use the this keyword - he can go into details.

I agree about the logging, but its a pity that the contract needs to be altered to allow the information to be logged. I wonder if there is a better way of allowing cross cutting information to be logged out.

Member

avanderhoorn commented Oct 14, 2013

Its not documented anywhere but @nikmd23 generally prefers automatic properties and tries not to use the this keyword - he can go into details.

I agree about the logging, but its a pity that the contract needs to be altered to allow the information to be logged. I wonder if there is a better way of allowing cross cutting information to be logged out.

@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 15, 2013

Collaborator

Ah, although a little bit religious, I would be glad to here the reasoning behind that 😉

What do you mean with the following, what contract?

a pity that the contract needs to be altered to allow the information to be logged

Collaborator

CGijbels commented Oct 15, 2013

Ah, although a little bit religious, I would be glad to here the reasoning behind that 😉

What do you mean with the following, what contract?

a pity that the contract needs to be altered to allow the information to be logged

@avanderhoorn

This comment has been minimized.

Show comment
Hide comment
@avanderhoorn

avanderhoorn Oct 15, 2013

Member

With the later, you mentioned that you adjusted things to pass through the RawUrls. I was simply commenting on the fact that its a pity that you needed to alter things just to be able to log out useful information like this. Its a pity that getting access to information like this for logging purposes isn't more crosscutting.

Member

avanderhoorn commented Oct 15, 2013

With the later, you mentioned that you adjusted things to pass through the RawUrls. I was simply commenting on the fact that its a pity that you needed to alter things just to be able to log out useful information like this. Its a pity that getting access to information like this for logging purposes isn't more crosscutting.

@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 16, 2013

Collaborator

I agree, we might be missing some internal IoC container or static accessor to the current Factory of Framework provider instance. But I have to say that I rather see an additional parameter in the constructor of a type then a dependency on some static property which is not directly visible for consuming code. It makes testing a lot harder and brittle as well.

Collaborator

CGijbels commented Oct 16, 2013

I agree, we might be missing some internal IoC container or static accessor to the current Factory of Framework provider instance. But I have to say that I rather see an additional parameter in the constructor of a type then a dependency on some static property which is not directly visible for consuming code. It makes testing a lot harder and brittle as well.

@avanderhoorn

This comment has been minimized.

Show comment
Hide comment
@avanderhoorn

avanderhoorn Oct 16, 2013

Member

Agreed.

On Wed, Oct 16, 2013 at 3:37 AM, Christophe Gijbels <
notifications@github.com> wrote:

I agree, we might be missing some internal IoC container or static
accessor to the current Factory of Framework provider instance. But I have
to say that I rather see an additional parameter in the constructor of a
type then a dependency on some static property which is not directly
visible for consuming code. It makes testing a lot harder and brittle as
well.


Reply to this email directly or view it on GitHubhttps://github.com/Glimpse/Glimpse/pull/555#issuecomment-26398205
.

Member

avanderhoorn commented Oct 16, 2013

Agreed.

On Wed, Oct 16, 2013 at 3:37 AM, Christophe Gijbels <
notifications@github.com> wrote:

I agree, we might be missing some internal IoC container or static
accessor to the current Factory of Framework provider instance. But I have
to say that I rather see an additional parameter in the constructor of a
type then a dependency on some static property which is not directly
visible for consuming code. It makes testing a lot harder and brittle as
well.


Reply to this email directly or view it on GitHubhttps://github.com/Glimpse/Glimpse/pull/555#issuecomment-26398205
.

@CGijbels

This comment has been minimized.

Show comment
Hide comment
@CGijbels

CGijbels Oct 16, 2013

Collaborator

Fixes #570

Collaborator

CGijbels commented on 50f2ed9 Oct 16, 2013

Fixes #570

@nikmd23

This comment has been minimized.

Show comment
Hide comment
Member

nikmd23 commented Oct 21, 2013

:shipit:

CGijbels added a commit that referenced this pull request Oct 22, 2013

Merge pull request #555 from Glimpse/PreBodyTagFilter-HandlePartialWr…
…itesCorrectly

Fixed PreBodyTagFilter partial writes handling

@CGijbels CGijbels merged commit 047b692 into master Oct 22, 2013

@CGijbels CGijbels deleted the PreBodyTagFilter-HandlePartialWritesCorrectly branch Dec 3, 2013

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment