nhibernate race condition when loading entity

Question

I have a problem with a nhibernate race condition in my webapp.

I am aware of this happening when using older versions of log4net (should be fixed in 1.2.10), although I have also experienced this. Because of this we have disabled log4net for now, since the race condition crashes IIS and it's unacceptable for this to happen in production. This happened when loading an entity (see stacktrace below). Besides this, a similar problem seems to have occurred in RavenDB, see this link, and an example without NHibernate here link.

Stacktrace:

Server Error in '/' Application.
Probable I/O race condition detected while copying memory. The I/O package is not thread safe by default. In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods. This also applies to classes like StreamWriter and StreamReader.
Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.

Exception Details: System.IndexOutOfRangeException: Probable I/O race condition detected while copying memory. The I/O package is not thread safe by default. In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods. This also applies to classes like StreamWriter and StreamReader.

Source Error:


Line 105:
Line 106:                if(webUser.Id > 0) { // logged in
Line 107:                    _user = session.Get<User>(webUser.Id);
Line 108:                    if(_user == null) { // session exists, but no user in DB with this id
Line 109:                        new SessionInit().Remove();


Source File: \App_Code\SessionInit.cs    Line: 107

Stack Trace:


[IndexOutOfRangeException: Probable I/O race condition detected while copying memory. The I/O package is not thread safe by default. In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods. This also applies to classes like StreamWriter and StreamReader.]
   System.Buffer.InternalBlockCopy(Array src, Int32 srcOffsetBytes, Array dst, Int32 dstOffsetBytes, Int32 byteCount) +0
   System.IO.StreamWriter.Write(Char[] buffer, Int32 index, Int32 count) +117
   System.IO.TextWriter.WriteLine(String value) +204
   System.IO.SyncTextWriter.WriteLine(String value) +63
   NHibernate.AdoNet.AbstractBatcher.ExecuteReader(IDbCommand cmd) +71
   NHibernate.Loader.Loader.GetResultSet(IDbCommand st, Boolean autoDiscoverTypes, Boolean callable, RowSelection selection, ISessionImplementor session) +580
   NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies) +275
   NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies) +205
   NHibernate.Loader.Loader.LoadEntity(ISessionImplementor session, Object id, IType identifierType, Object optionalObject, String optionalEntityName, Object optionalIdentifier, IEntityPersister persister) +590

[GenericADOException: could not load an entity: [app.Presentation.User#338][SQL: SELECT user0_.userID as userID24_0_, user0_.instituteID as institut2_24_0_, user0_.email as email24_0_, user0_.password as password24_0_, user0_.username as username24_0_, user0_.mod_remarks as mod6_24_0_, user0_.lastLogin as lastLogin24_0_, user0_.active as active24_0_, user0_.isAcademic as isAcademic24_0_, user0_.created as created24_0_, (select p.firstName from ej_profile p where p.userID = user0_.userID) as formula11_0_, (select p.lastName from ej_profile p where p.userID = user0_.userID) as formula12_0_, (select p.timeZone from ej_profile p where p.userID = user0_.userID) as formula13_0_ FROM ej_user user0_ WHERE user0_.userID=?]]
   NHibernate.Loader.Loader.LoadEntity(ISessionImplementor session, Object id, IType identifierType, Object optionalObject, String optionalEntityName, Object optionalIdentifier, IEntityPersister persister) +960
   NHibernate.Loader.Entity.AbstractEntityLoader.Load(ISessionImplementor session, Object id, Object optionalObject, Object optionalId) +76
   NHibernate.Loader.Entity.AbstractEntityLoader.Load(Object id, Object optionalObject, ISessionImplementor session) +32
   NHibernate.Event.Default.DefaultLoadEventListener.LoadFromDatasource(LoadEvent event, IEntityPersister persister, EntityKey keyToLoad, LoadType options) +173
   NHibernate.Event.Default.DefaultLoadEventListener.Load(LoadEvent event, IEntityPersister persister, EntityKey keyToLoad, LoadType options) +181
   NHibernate.Event.Default.DefaultLoadEventListener.OnLoad(LoadEvent event, LoadType loadType) +1019
   NHibernate.Impl.SessionImpl.FireLoad(LoadEvent event, LoadType loadType) +403
   NHibernate.Impl.SessionImpl.Get(String entityName, Object id) +469
   NHibernate.Impl.SessionImpl.Get(Type entityClass, Object id) +374
   NHibernate.Impl.SessionImpl.Get(Object id) +391
   SessionInit.GetCurrentUser(ISession session) in j:\dev\app\app_wwwroot\App_Code\SessionInit.cs:107
   DynamicPage.OnPreInit(EventArgs e) in j:\dev\app\app_wwwroot\App_Code\DynamicPage.cs:24
   MemberPage.OnPreInit(EventArgs e) in j:\dev\app\app_wwwroot\App_Code\MemberPage.cs:20
   members_stocks_Default.OnPreInit(EventArgs e) in j:\dev\app\app_wwwroot\members\Default.aspx.cs:28
   System.Web.UI.Page.PerformPreInit() +49
   System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +1716

The mapping for User:

public class UserViewMapping : ClassMap<User>
{
    public UserViewMapping() {
        Table("ej_user");
        Id(s => s.Id, "userID").GeneratedBy.Native();
        Map(s => s.InstituteId, "instituteID");
        Map(s => s.Email, "email");
        Map(s => s.Password, "password");
        Map(s => s.Name, "username");
        Map(s => s.ModRemarks, "mod_remarks");
        Map(s => s.LastLogin, "lastLogin");
        Map(s => s.Active, "active");
        Map(s => s.IsAcademic, "isAcademic");
        Map(s => s.Created, "created");
        Map(s => s.FirstName).Formula("(select p.firstName from ej_profile p where p.userID = userID)");
        Map(s => s.LastName).Formula("(select p.lastName from ej_profile p where p.userID = userID)");
        Map(s => s.TimeZone).Formula("(select p.timeZone from ej_profile p where p.userID = userID)");
        HasMany<ProfileViewModel>(s => s.Profiles)
            .Table("ej_profile")
            .KeyColumn("userID")
            .Cascade.All()
            .Inverse();
}

Some details: I use two sessions for queries and commands (and two session factories) since I use a somewhat CQRS-like pattern. One session for reading objects, one for making changes (this helps me keep my domain model simple and view models and mapping possibly different from the command model).

The race condition occurred when loading the User viewmodel in my development environment (single user), but we make sure that this will never happen in production, since it crashed IIS 7. Also, in production there will be multiple users, so maybe the error will possibly occur more often.

Also, we have a lot of legacy code which uses System.Data and MySql.Data.MySqlClient.MySqlDataAdapter to read/write to the database. Could this be of influence?

I'm using NHibernate 3.1.0 (will upgrade to 3.3.1GA, but this is difficult to reproduce), and fluentNhibernate for my mappings.

The sessionfactories are created in the global.asax:

void Application_Start(object sender, EventArgs e)
{
    QuerySessionFactory.Create(connectionString);
    CommandSessionManager.Initialize(connString);
}

My pages inherit from my DynamicPage where the query session is opened, and closed:

public class DynamicPage : System.Web.UI.Page
{
    protected override void OnPreInit(EventArgs e)
    {
        Session = QuerySessionFactory.Instance.OpenSession();
    }

    protected override void OnUnload(EventArgs e) {
        base.OnUnload(e);
        Session.Close();
    }
}

In the SessionInit (reads userID from httpcontext.session, and creates a 'webuser', a user with some simple information like userId). Later, I have put the lock around and done the user get request in a transaction, not sure if it would be useful.

    public IUser GetCurrentUser(ISession session) {
        if(_user == null) { 
            var webUser = new SessionInit().Get;

            if(webUser.Id > 0) { // logged in
                lock(_lock) {
                    using(var tx = session.BeginTransaction()) {
                        _user = session.Get<User>(webUser.Id);
                        tx.Commit();
                    }
                }
                if(_user == null) { // session exists, but no user in DB with this id
                    new SessionInit().Remove();
                }
                ((User)_user)._currentUser = webUser;
            } else {
                if(webUser is CurrentUser && webUser.Id == 0) {
                    if(HttpContext.Current.Session != null) {
                        HttpContext.Current.Response.Cookies.Remove("ASPSESSID");
                        HttpContext.Current.Request.Cookies.Remove("ASPSESSID");
                        HttpContext.Current.Session.RemoveAll();
                        HttpContext.Current.Session.Abandon();
                    }

                    if(HttpContext.Current.Request.Url.Host.Contains("members"))
                        HttpContext.Current.Response.Redirect("/login");
                } else
                    if(webUser.Id == 0) {
                        var userId   = webUser.Id;
                        var userName = webUser.UserName;
                        var loginUrl = webUser.LoginUrl;
                        var clientIp = webUser.ClientIp;
                        var isAdmin  = webUser.IsAdmin();
                        return new eLab.Presentation.Visitor(userId, userName, loginUrl, clientIp, isAdmin, webUser.Theme); 
                    }
            }
            if (_user == null)
                return new eLab.Presentation.Visitor(webUser.Id, webUser.UserName, webUser.LoginUrl, webUser.ClientIp, false, webUser.Theme);
        }
        return _user;
}

Command sessions are opened and closed in a using block when needed.

According to the stacktrace, the problem occurs in the StreamWriter -> System.Buffer, which is again called by System.IO.SyncTextWriter, which is supposed to be thread-safe wrapper around System.IO.TextWriter.

Since this happened in the TextWriter, is there a way to get around this, to use a threadsafe TextWriter?

Is it safe to open and close the session the way I do it in DynamicPage?

Since this is obviously difficult to reproduce, any ideas on how to do that are welcome too.

[UPDATE] The NHibernate Profiler told that we also opened and closed a session (in a using block) in a master page, since it was needed to check some permissions for the current user, so two sessions were opened per request. I have refactored it, so it now instead of opening a session in a page superclass, it opens the session in the global.asax on Application_BeginRequest and closes it again on Application_EndRequest, where the session is put in HttpContext.Current.Items.

But no sure way of testing if this fixes it.

Answer 1

Stamppot, thank you for posting this problem to StackOverflow; as you know, there is not much other information about this error message to be found on the Web. My team ran into a similar problem a few months ago in a webapp that uses NHibernate and log4net. (StringTemplate might have been involved too.) We "fixed" the problen by redirecting Console.Out/Error to null streams (effectively disabling them) in the Application_Start() event handler in Global.ascx.cs:

protected void Application_Start(object sender, EventArgs e)
{
    Console.SetOut(new System.IO.StreamWriter(System.IO.Stream.Null));
    Console.SetError(new System.IO.StreamWriter(System.IO.Stream.Null)); 
}

Details: In our case, the "probable race condition..." error was related to load. On the production server, this exception would arise sporadically, crashing the worker process on each occasion. Eventually we found out how to reproduce it, by running a script that flooded the webapp with many requests in a short period of time. The exception stack traces, when correlated with the NHibernate/StringTemplate/log4net source code, pointed to the use of Console.Out/Error methods for logging in various situations. Seems like a strange place for such an error to arise---aren't these methods considered to be thread-safe? However, after we applied the above workaround, the problem immediately disappeared and hasn't returned since. Unfortunately, other priorities kept us from digging deeper---but whatever the root cause of the problem, it hasn't manifested itself in any other way.

Answer 2

The problem with solution that @APW provided is that by default, StreamWriter is not thread safe. Check it here: https://msdn.microsoft.com/en-us/library/system.io.streamwriter(v=vs.110).aspx

By passing "new StreamWriter" to Console.Set* you are passing non-thread safe instance. So I think it's a matter of time to see similar error again.

Correct way would be using TextWriter.Synchronized method to wrap unsafe Stream.Null.

using System.IO;
...
var nullStream = TextWriter.Synchronized(TextWriter.Null);
Console.SetOut(nullStream);
Console.SetError(nullStream);

UPD: Please ignore this. I have found that Console.SetOut wrapping any stream into TextWriter.Synchronized(...). Proof.