Issue in 2.0.0-beta6 - CopyToAsync of InputStream (OWIN)

[jlegan]

Took a bit too much out of the original description:

Moved over to 2.0.0-beta6 and started to receive unsupported_grant_types coming back from my hybrid flow call to request an auth code, mirroring the sample code.

                        // get access and refresh token
                        var tokenClient = new OAuth2Client(
                            new Uri(CloudConfigurationManager.GetSetting("TokenEndpoint")),
                            "test",
                            "test");

                        var response = await tokenClient.RequestAuthorizationCodeAsync(n.Code, n.RedirectUri);

                        claims.Add(new Claim("access_token", response.AccessToken));

I grabbed the source and debugged it and realized that not just the grant type but all params were missing even though they were making it to the identityserver. Below are my findings.

[jlegan]

Going a bit down the rabbit hole... Grab the source again and found where the issue is occurring. Deep inside InternalOwinExtensions.cs in ReadRequestFormAsync, the CopyToAsync is producing an empty memory stream even though the input stream has content.

        if (!context.Request.Body.CanSeek)
        {
            var copy = new MemoryStream();
            await context.Request.Body.CopyToAsync(copy);
            copy.Seek(0L, SeekOrigin.Begin);
            context.Request.Body = copy;
        }

[jlegan]

I confirmed and repro'd it on another workstations. Very odd. Certainly not IdentityServer issue but still very odd.

                var copy = new MemoryStream();
                Debug.Write(string.Format("Body Length: {0}", context.Request.Body.Length)); //115
                await context.Request.Body.CopyToAsync(copy);
                Debug.Write(string.Format("Copy Length: {0}", copy.Length)); //0
                copy.Seek(0L, SeekOrigin.Begin);
                context.Request.Body = copy;

[jlegan]

I put in a patch so that I could keep working. I wrote a small Owin middleware that copies the inputstream to a memorystream and shoves it back into the request body. This memorystream is always seekable and thus bypasses the call to CopyToAsync. I am not sure if this is a framework, Owin or Azure compute emulator issue at this point but I need to move onto other things today and will try and revisit it tomorrow.

UseIdentityServerExtension.cs

            if (options.RequireSsl)
            {
                app.Use<RequireSslMiddleware>();
            }

            app.Use<CopyInputStream>();
            app.ConfigureRequestId();

internal class CopyInputStream
    {
        readonly Func<IDictionary<string, object>, Task> _next;

        public CopyInputStream(Func<IDictionary<string, object>, Task> next)
        {
            _next = next;
        }

        public async Task Invoke(IDictionary<string, object> env)
        {
            var context = new OwinContext(env);


                var body = new StreamReader(context.Request.Body).ReadToEnd();
                var requestData = Encoding.UTF8.GetBytes(body);
                context.Request.Body = new MemoryStream(requestData);



            await _next(env);
        }
    }

[jlegan]

I spent another couple of hours on this and posted it to SO as well. Not entirely sure what is breaking it but it is reproducible even on a clean machine with the source I downloaded yesterday. At this point I need to move onto the problem I was solving at the time I encountered it. I will post here if I make any headway.

[brockallen]

Ok... and just to let you know, we've not been ignoring this -- it's just that I'm not sure what to say. Do the samples from our repo work for you?

[jlegan]

Brock,

I had a couple of other ideas I wanted to try in the morning. Are there
samples for v2 yet? If not I will carve out some time to upgrade the 1.x
sample and give it a shot but with the in-memory stores since I have added
quite a bit to my implementation.

Jim

On Thursday, June 25, 2015, Brock Allen notifications@github.com wrote:

Ok... and just to let you know, we've not been ignoring this -- it's just
that I'm not sure what to say. Do the samples from our repo work for you?

—
Reply to this email directly or view it on GitHub
#1533 (comment)
.

[brockallen]

The dev branch of samples is all up to date with the dev branch of Core (2.0.0)

[jlegan]

Brock,

I tracked it down finally. It is in the logging code. In RequestResponseLogger.cs there is a destructive ReadAsStringAsync() on line 34. The reading of the content consumes the stream and then cannot be read (or copied) later.

var reqLog = new
            {
                Method = request.Method,
                Url = request.RequestUri.AbsoluteUri,
                Headers = request.Headers,
                Body = await request.Content.ReadAsStringAsync()
            };

Turing on/off EnableHttpLogging allows the issue to be reproduced.

[brockallen]

Ah, excellent find -- thanks! We'll get it fixed.

[brockallen]

Ok, I've pushed to the dev branch a potential fix. This will get pushed to myget -- do you mind testing against that build to see if this issue has been resolved?

[jlegan]

Sure thing. I have a couple of things going on first thing in the morning
but then I will hop on it. Thanks for all of your help.

On Sunday, June 28, 2015, Brock Allen notifications@github.com wrote:

Ok, I've pushed to the deb branch a potential fix. This will get pushed to
myget -- do you mind testing against that build to see if this issue has
been resolved?

—
Reply to this email directly or view it on GitHub
#1533 (comment)
.

[jlegan]

Brock,

Everything is testing out well. I ran into an issue with the changes in the logging but I believe that is on my end at this point. I have to pull out my usage of the Diagnostic Trace Provider and rewire up my nLog implementation in order to get the verbose output I was seeing before but tokens are being generated. Thanks for all of your help.

Jim

[jlegan]

Spoke too soon. If EnableHttpLogging is enabled it throws still. I did not catch it at first because it only occurs during an interactive login (I test client credentials). It might be in the validation code I mentioned in my email the other day. The MyGet package changed the way that I was logging and testing (BearTail). I am happy to grab the latest source and narrow this down as well if you wouldn't mind giving me a snippet to get my trace logging running again.

[brockallen]

Check the latest host on dev to see how tracing has changed in 2.0.0

[brockallen]

So you're still having this issue?

[jlegan]

Yes, with the MyGet you asked me to test it did however I suspect not in
the same spot. When I saw that the diagnostictracelistener was removed and
a copy/paste of the seri log from the sample didn't work, I went back to
using the source I had working. On Monday I will figure out the tracing and
grab the latest source to try and track it down.

On Sunday, July 5, 2015, Brock Allen notifications@github.com wrote:

So you're still having this issue?

—
Reply to this email directly or view it on GitHub
#1533 (comment)
.

[jlegan]

I saw that it was removed but the entire LoggingProviders namespace is missing from the MyGet package. Do I have to roll my own or is there an example of Seri working? I see in the dev samples that there is a SeriLogProvider but the namespace does not exist in the package.

[leastprivilege]

just add SeriLog to the host - liblog picks that up automatically

https://github.com/IdentityServer/IdentityServer3/blob/dev/source/Host/Startup.cs#L39

[jlegan]

Thanks Dominick, that got me up and running. There was a conflict with how I had nLog implemented that was the root of the logging issue.

With trace working I can see that with the latest MyGet package the error I am now encountering is with the validation of the AntiForgery token, not necessarily related to the initial problem though if the stream is being corrupted still it could be. Give me a few minutes to track down what changed in the AF code to see if it is related or if this issue can be closed out.

[jlegan]

I just grabbed the latest dev source. I realize I sound like a broken record however

var bytes = await actionContext.Request.Content.ReadAsByteArrayAsync();

on line 66 of ValidateAntiForgeryTokenAttribute.cs returns an empty byte array with HttpLogging enabled. I will see if I can find what is destructively reading the stream.

[jlegan]

It is a very similar issue to the one that kicked off this whole thread.

I can see that you ran into a problem initially, the comment above the line of code that is failing says:

// ReadAsByteArrayAsync buffers the request body stream
                // we then put the buffered copy into the owin context
                // so we can read it in the IsTokenValid API without 
                // disturbing the actual stream in the HttpRequestMessage
                // that WebAPI uses it later for model binding. #lame

I went the route of pulling the body from the Owin context and while newing up the context works with the stream it produces, it likewise destroys the stream for the binding and therefore returns an invalid user/pass since the stream has been consumed. I am reproing this with the zip currently in the dev branch and will keep poking at it as time allows later today but I can confirm that I have a content length of 154 in my test setup and the call to ReadAsByteArrayAsync with HttpLogging enabled yields an empty byte array and subsequent failure to validate the anti-forgery token.

[brockallen]

Ok, perhaps MSFT changed something in Web API so that API no longer buffers? I'll see if I can change it to another OWIN abstraction.

[brockallen]

Actually, this shouldn't affect downstream copies of Web API. So yea, something's quite broken. It's upsetting that working purely at the OWIN level can't function across middlewares.

I think this has something to do with 2 copies of Web API in the same pipeline -- the first one is draining the buffer at the host level. Not sure this will be something we can fix in IdSvr -- it's more of a Web API problem. I'll keep digging, though.

[brockallen]

Were you ever able to put a middleware in front of both that loaded the stream into a buffered stream at the OWIN layer? Then, in theory, all downstream consumption of that OWIN body stream will be from the buffered one.

[jlegan]

Yes, it is how I fixed it initially before I found the destructive stream
reading in the logging code.

On Monday, July 13, 2015, Brock Allen notifications@github.com wrote:

Were you ever able to put a middleware in front of both that loaded the
stream into a buffered stream at the OWIN layer? Then, in theory, all
downstream consumption of that OWIN body stream will be from the buffered
one.

—
Reply to this email directly or view it on GitHub
#1533 (comment)
.

[brockallen]

So I'd suggest going back to that -- that's cross middleware coordination that needs to happen and I'm not sure IdSvr should have then inside of its code (as it shouldn't have to be aware of other middleware). Again, this is fundamentally down to Web API as the issue.

Also, I wonder why you're not using something more dynamic in each request to distinguish each copy of IdSvr? Like a Map or something else... IOW, should each one be looking at every request?

[jlegan]

I am only using one instance now and have been since you suggested it.

On Monday, July 13, 2015, Brock Allen notifications@github.com wrote:

So I'd suggest going back to that -- that's cross middleware coordination
that needs to happen and I'm not sure IdSvr should have then inside of its
code (as it shouldn't have to be aware of other middleware). Again, this is
fundamentally down to Web API as the issue.

Also, I wonder why you're not using something more dynamic in each request
to distinguish each copy of IdSvr? Like a Map or something else... IOW,
should each one be looking at every request?

—
Reply to this email directly or view it on GitHub
#1533 (comment)
.

[jlegan]

Is it possible that the issue is being caused by the web API I am hosting
along side of Idv3 that exposes controllers for user management (for
membership reboot)? I am happy to send you my startup.cs, there is only one
instance hosted off of /core like the samples.

On Monday, July 13, 2015, James D. Legan jim@logicalnotion.com wrote:

I am only using one instance now and have been since you suggested it.

On Monday, July 13, 2015, Brock Allen <notifications@github.com
javascript:_e(%7B%7D,'cvml','notifications@github.com');> wrote:

So I'd suggest going back to that -- that's cross middleware coordination
that needs to happen and I'm not sure IdSvr should have then inside of its
code (as it shouldn't have to be aware of other middleware). Again, this is
fundamentally down to Web API as the issue.

Also, I wonder why you're not using something more dynamic in each
request to distinguish each copy of IdSvr? Like a Map or something else...
IOW, should each one be looking at every request?

—
Reply to this email directly or view it on GitHub
#1533 (comment)
.

[brockallen]

Well, if they are all Mapped to different paths, then they should not step on each other. But sure, it might be nice to see the smallest sample project that repros the problem.

[brockallen]

So I think we know the workaround -- the host would need middleware to buffer the OWIN request body stream. Thanks.

[jlegan]

Brock,

I am okay with the solution I would just like to understand it a little bit. I am fairly certain I can repro this with a very simple implementation and if that is the case wouldn't it make more sense to have the buffering occur in the middleware of Idv3? My original middleware "fix" looked like this and I had put it in the Idv3 UseIdentityServerExtensions.cs

internal class CopyInputStream
    {
        readonly Func<IDictionary<string, object>, Task> _next;

        public CopyInputStream(Func<IDictionary<string, object>, Task> next)
        {
            _next = next;
        }

        public async Task Invoke(IDictionary<string, object> env)
        {
            var context = new OwinContext(env);


                var body = new StreamReader(context.Request.Body).ReadToEnd();
                var requestData = Encoding.UTF8.GetBytes(body);
                context.Request.Body = new MemoryStream(requestData);



            await _next(env);
        }
    }

[brockallen]

I'm not 100% sure really what the issue is either -- it's something between OWIN and Web API and multiple versions of Web API in the pipeline.

As for the fix, we're sort of doing this in our internal APIs that read from the OWIN body. I guess it's Web API that's getting in the way. Perhaps our invocation of the Web API ReadBuffer is really the issue.

Send me your repro and I'll see if I can figure it out.

[jlegan]

Brock,

I have been engaged in a couple of projects but I have set a side a couple of hours tomorrow morning to make you as trim as possible of a solution starting with the current samples for 2.x. Sorry it is taking so long.

Jim

[brockallen]

No worries -- I'm also quite busy myself.

[jlegan]

Brock,

At the dropbox link below you will find a zip file. In it you have the following:

1. Web API project which is the current 2.x WebHost (minimal) solution with my changes to enable logging as well as the introduction of a separate web API (UseWebApi).
2. MVC client app that simply wires up project Implement protocol between endpoints and login page using JWTs #1 as its IdP.

https://www.dropbox.com/sh/b33qihqborgvadg/AAABSRiBn96fosefgTea2A1Na?dl=0

A couple of things to note. I did not want to mess around with IIS Express and SSL so I used IIS on my end, you will likely want to switch that back on the Idv3 project. I also hard coded the URLs in the MVC project.

To reproduce:

Scenario 1: Leave "EnableHttpLogging" set to false, hit the "About" controller in the MVC app which has the authorize attribute. You will be redirected to Idv3, log in with the in-memory user "bob","bob". If you hit the consent screen you are good to go.

Scenario 2: Turn on HttpLogging and once again hit the About controller. When you enter bob, bob you will immediately throw and arrive and the "unexpected error occurred" dialog in Idv3.

To make it a bit easier for you I did not use the Idv3 nuget package in project 1 but rather included the latest Core project on dev so you can jump right into debugging it. The details below should illustrate where it gets pinched and even a possible solution in the middleware within Idv3 should you so choose to pursue it.

Thanks for all of your help.

Jim

[brockallen]

I never found time to look at your code, but I did make some related changes due to this thread: #1672. I'm hoping this will address your issue as well.

[jlegan]

It did not (2.0.0 RTM)

[leastprivilege]

that should be fixed now with 2.0.1