Large, rapid sequence of operations generates 401 exception

[Kyle Levien]

Starting this discussion mostly to log an issue we're seeing with fairly reliable repetitiveness and to see if there is any good approach we should take to debug it.

Our product involves large document copy, update and publishing operations and we are seeing mysterious 401 exceptions come back during these actions. The specific request url is not reliably the same though it does seem to always be on a GET for an arbitrary document id.

The 401 is accompanied with the following stack trace:

at Raven.Client.Connection.Implementation.HttpJsonRequest.<RunWithAuthRetry>d38`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.Implementation.HttpJsonRequest.<ReadResponseJsonAsync>d35.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.Async.AsyncServerClient.<DirectGetAsync>d71.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.ReplicationInformerBase`1.<TryOperationAsync>d34`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.ReplicationInformerBase`1.<ExecuteWithReplicationAsync>d33`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.Async.AsyncServerClient.<ExecuteWithReplication>d164`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Abstractions.Util.AsyncHelpers.<>c__DisplayClass1_1`1.<<RunSync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Raven.Abstractions.Util.AsyncHelpers.RunSync[T](Func`1 task)
   at Raven.Client.Document.DocumentSession.Load[T](String id)
   at Ingeniux.CMS.UserSession.GetEntity[T,TManager](String id, TManager manager)

We are using windows auth, running the client product as NetworkService in IIS and hitting a localhost ravendb server.

We didn't see any errors in the ravendb logs. Is there a good direction for us to proceed in identifying the cause of this issue? We have attempted to throttle the reads and writes we are committing during these large operations which seems to help somewhat, but we still get a 401 on occasion.

Thanks,

Kyle

[Oren Eini (Ayende Rahien)]

401 is part of the process of authenticating via window auth.

You do a three way roundtrip with 401 on two of them.

The only way this should surface upward if the authentication failed.

See details on how to get more info here:

https://blogs.msdn.microsoft.com/david.wang/2005/07/15/howto-diagnose-401-x-http-errors-on-iis/

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Samson Lee]

I've been assisting Kyle in digging into this, and we were able to get some request trace details from these random 401.1 errors (same stack trace at Raven.Client.Connection.Implementation.HttpJsonRequest that Kyle previously noted) coming from an instance of our app.

Attached is a ZIP with these request trace logs. We are wondering if there is a possibility of issues regardgin NTLM provider for Windows Authentication with RavenDB. Of note is that one of the trace logs show a error on a GET request for /singleAuthToken Our application is configured for NetworkService, for both the client and server running in the same IIS instance. 

Any assistance would be greatly appreciated. It seems

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

There is no special provider for windows auth, it just uses either the IIS one or the HttpListener one.

Did you check the event viewer for security issues there?

The actual error can be seen at the bottom of the request:

You do not have permission to view this directory or page using the credentials that you supplied

Most likely causes:

* The username supplied to IIS is invalid.

* IIS could not verify the identity of the username and password provided.

* The resource is configured for Anonymous authentication, but the configured anonymous account either has an invalid password or was disabled.

* The server is configured to deny login privileges to the authenticating user or the group in which the user is a member

* Invalid Kerberos configuration may be the cause if all of the following are true:

**  Integrated authentication was used.

** the application pool identity is a custom account.

** the server is a member of a domain.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Oren Eini (Ayende Rahien)]

If this come and go, it might be IIS failing to talk to the domain

[Samson Lee]

The logs were from a server not domain joined, using local NetworkService account for both the client appPool and RavenDB appPool.

We did implement awhile ago PreAuthenticate into our app, for different performance issues observed when we were using RavenDB 2.5. Is this still recommended for application scenarios configured such as ours with RavenDB 3.5? I've seen a few older posts where it seems that larger operations to Raven may work as well with Windows Auth and the PreAuthenticate flag set to true. We're still testing reverting to PreAuthenticate=false on our side and wanted to see if there were any possibility of issues related to PreAuthenticate that you may know of, maybe related to this article: https://support.microsoft.com/en-us/help/908573/a-post-or-put-request-may-fail-when-you-use-the-httpwebrequest-class-to-send-lots-of-data-on-a-computer-that-is-running-the-.net-framework

Thanks again,
Sam

[Oren Eini (Ayende Rahien)]

Yes, that might be related, although that is supposed to be handled by us.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Anything on the security log?

[Samson Lee]

Nothing of note in the Security logs. 

You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/d3hywDgH6k8/unsubscribe.
To unsubscribe from this group and all its topics, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

The behavior I'm seeing from the the request tracking is that those are actually requested that failed to authenticate.

Because this is Windows doing the auth, those should show up in the security log. 

Just to verify, this _sometimes_ work, and sometimes doesn't, right?

If you retry a connection, it will work?

Does this happen on 15 minutes intervals?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/d3hywDgH6k8/unsubscribe.

To unsubscribe from this group and all its topics, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Samson Lee]

Yes, the issue is sporadic with the 401.1 errors coming in through our application log. In the test environment, there doesn't appear to be any type of interval between the errors, and we are still working on discerning any pattern. We are seeing it in a production environment, but even then it is sporadic and has happened at various times of day. 

I took another look at Event Viewer > Windows Logs > Security, and did not see any failures corresponding with the 401 errors from the application log time.

You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/d3hywDgH6k8/unsubscribe.

To unsubscribe from this group and all its topics, send an email to ravendb+u...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/d3hywDgH6k8/unsubscribe.

To unsubscribe from this group and all its topics, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Are you seeing any actual errors on the client?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/d3hywDgH6k8/unsubscribe.

To unsubscribe from this group and all its topics, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to a topic in the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/d3hywDgH6k8/unsubscribe.

To unsubscribe from this group and all its topics, send an email to ravendb+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Samson Lee]

The 401 error pops up in our client app, as well as in our app's logs, with the full 401.1 error. Request URLs will vary. 

[Oren Eini (Ayende Rahien)]

Hm... this might be related to the pre auth, can you disable this and see how it behaves?

--

[Samson Lee]

We were thinking the same, so we've got a test build with PreAuth=false. While we haven't been able to reproduce the error with this build, it's still not clear what the right conditions are to trigger the error are. It does seem like some sort of timeout from the server, maybe under load or large queries/batch operations, but again there isn't a solid pattern to this. We'll update this thread if we are able to get a solid repro on our side.

[Samson Lee]

Hi Oren,

I've attached two Fiddler session archives from tests between our app with PreAuth=true and a build with PreAuth=false (zip files labelled as such). The interesting point to note is that it seems that we see 401 > 304 responses for calls coming from the PreAuth=true build, but the we don't see this pattern in the PreAuth=false build. This seems to be inverse of the expected behavior for this configuration. Any thoughts?

Thanks

Sam

[Oren Eini (Ayende Rahien)]

304 is a standard not modified response, and doesn't indicate any error.

PreAuth shouldn't have any impact on this.

--

[Samson Lee]

I understand that 304 is expected, but it is strange that the app with preauth set to true results in recurred 401 calls, as opposed to the app with preauth disabled. This seems more like an opposite expected behavior.

[Oren Eini (Ayende Rahien)]

This mostly depend on when you caught it, probably. If you caught the neotiation, you'll see 401.

Both options have connection pooling, note.

[Kyle Levien]

We've reproduced the behavior in a Raven Unit Test that has the following code:

namespace RavenUnitTests

{

public class Item

{

public string Id { get; set; }

}

[TestClass]

public class PreAuth : RavenTestBase

{

[TestMethod]

public void PreAuthTest()

{

using (var store = new DocumentStore()

{

Url = "http://localhost/cmstrunk/contentstore",

DefaultDatabase = "IGXContentStore",

HttpMessageHandlerFactory = () => new WebRequestHandler()

{

UnsafeAuthenticatedConnectionSharing = true,

PreAuthenticate = true,

Credentials = CredentialCache.DefaultNetworkCredentials

}

}.Initialize())

{

using (var session = store.OpenSession())

{

session.Store(new Item() { Id = "Items/1" });

session.SaveChanges();

}

using (var session = store.OpenSession())

{

var item = session.Load<Item>("Items/1");

Assert.IsNotNull(item);

session.Delete(item);

session.SaveChanges();

}

}

}

}

}

The fiddler capture for the test is as follows:

Furthermore, if we set PreAuthenticate = false or remove the HttpMessageHandlerFactory override completely we get the following in fiddler:

Both fiddler exports are attached.

Now this appears to be the opposite behavior than what would be expected when using PreAuthenticate on a WebRequestHandler as we understand it. (https://weblog.west-wind.com/posts/2010/feb/18/net-webrequestpreauthenticate-not-quite-what-it-sounds-like)

I've re-run the test in Ravendb 2.5 with the old method of setting PreAuthenticate:

store.JsonRequestFactory.ConfigureRequest += (sender, e) => { (e.Request as HttpWebRequest).UnsafeAuthenticatedConnectionSharing = true; (e.Request as HttpWebRequest).PreAuthenticate = true; };

And the fiddler capture resembles the above PreAuth = false behavior no matter what we set it to.

These tests are run on Windows 10 with IIS 10.

Is there some possible behavior change between setting an event handler in Raven 2.5 and providing a message handler override in 3.5 that could explain the confusing behavior we see?

Thanks,

Kyle

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Kyle Levien]

Interestingly, if we repeat the test code (connect to a store and open store/read/delete sessions) and alternate the PreAuthentication boolean on the document stores we get the attached fiddler captures.

If PreAuth = true, then False:

The first half of the requests are all 401 challenged, and the second half are not

If PreAuth = false then True:

The first request goes through a 401 handshake, and all subsequent requests are not.

[Grisha Kotler]

Hi,

Looking into this.

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

Thank you, any luck?

Kyle

[Grisha Kotler]

Are you using the 2.5 or 3.5 client?

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

We are using the 3.5 client in our product and in the above test.

[Grisha Kotler]

What kind of error do you get when running your test?

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

No error when we run the test, it is just to verify the behavior of PreAuthenticate. The results posted above seem to indicate that the PreAuthenticate value is behaving in a manner opposite to what is expected.

 

The original error we are investigating is a 401 Unauthorized exception that bubbles up into our product code seemingly at random during periods of heavy load. Subsequent connections operate just fine. We are using windows authentication as described in Samson's post above.

[Grisha Kotler]

Are you using Replication?

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

On 2 March 2017 at 19:48, Kyle Levien <teh...@gmail.com> wrote:

No error when we run the test, it is just to verify the behavior of PreAuthenticate. The results posted above seem to indicate that the PreAuthenticate value is behaving in a manner opposite to what is expected.

 

The original error we are investigating is a 401 Unauthorized exception that bubbles up into our product code seemingly at random during periods of heavy load. Subsequent connections operate just fine. We are using windows authentication as described in Samson's post above.

--

[Kyle Levien]

No, we don't have any additional bundles enabled.

Are you using Replication?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Grisha Kotler]

Aggressive caching?

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

Nope

[Grisha Kotler]

Hi,

Can you run this on your server and post here the output:

IEnumerator enumerator = AuthenticationManager.RegisteredModules;

            while (enumerator.MoveNext())

            {

                IAuthenticationModule module = (IAuthenticationModule)enumerator.Current;

                Console.WriteLine("AuthenticationType: " + module.AuthenticationType + ", CanPreAuthenticate: " + module.CanPreAuthenticate);

            }

Hibernating Rhinos Ltd  

Grisha Kotler l RavenDB Core Team Developer l Mobile: +972-54-586-8647

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

RavenDB paving the way to "Data Made Simple" http://ravendb.net/

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Kyle Levien]

Ran the provided snippet in our unit test and got the following results:

Result StandardOutput:

AuthenticationType: Negotiate, CanPreAuthenticate: True

AuthenticationType: Kerberos, CanPreAuthenticate: True

AuthenticationType: NTLM, CanPreAuthenticate: True

AuthenticationType: Digest, CanPreAuthenticate: True

AuthenticationType: Basic, CanPreAuthenticate: True

[Oren Eini (Ayende Rahien)]

Okay, this looks fine.

I'm not sure what is going on, and I think the pre auth isn't related to this.

401 is only ever raised out by windows auth if the creds are invalid for some reason.

Otherwise, you'll get 403.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.