2012-09-28 11 views
11

Nella mia webapp ho un problema con una condizione di competizione inaccessibile.Condizione di gara vietata durante il caricamento dell'entità

Sono consapevole di ciò che accade quando si utilizzano versioni precedenti di log4net (dovrebbe essere corretto in 1.2.10), anche se ho anche sperimentato questo. Per questo motivo abbiamo disabilitato log4net per ora, dal momento che la condizione della competizione si blocca su IIS ed è inaccettabile che ciò avvenga in produzione. Questo è successo quando si carica un'entità (vedere stacktrace sotto). Oltre a questo, sembra che un problema simile si sia verificato in RavenDB, vedere questo link e un esempio senza NHibernate qui 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 

La mappatura per utente:

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(); 
} 

Alcuni dettagli: io uso due sessioni per le query e comandi (e due fabbriche di sessione) dato che io uso un CQRS simile un po ' modello. Una sessione per leggere gli oggetti, uno per apportare modifiche (questo mi aiuta a mantenere il mio modello di dominio semplice e a visualizzare modelli e mappature possibilmente differenti dal modello di comando).

La condizione di competizione si è verificata durante il caricamento di viewmodel Utente nel mio ambiente di sviluppo (utente singolo), ma ci assicuriamo che ciò non accada mai in produzione, poiché si è bloccato IIS 7. Inoltre, in produzione ci saranno più utenti, quindi forse l'errore si verificherà più spesso.

Inoltre, abbiamo un sacco di codice legacy che utilizza System.Data e MySql.Data.MySqlClient.MySqlDataAdapter per leggere/scrivere nel database. Potrebbe essere d'influenza?

Sto usando NHibernate 3.1.0 (eseguiremo l'aggiornamento a 3.3.1GA, ma questo è difficile da riprodurre), e fluente Nibisco per i miei mapping.

I sessionfactories vengono creati nella global.asax:

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

mie pagine ereditano dalla mia DynamicPage in cui si apre la sessione di query e chiusi:

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(); 
    } 
} 

Nel SessionInit (legge userID da httpcontext.session e crea un 'webuser', un utente con alcune informazioni semplici come userId. Più tardi, ho bloccato il blocco e ho fatto in modo che l'utente ottenga la richiesta in una transazione, non certo se sarebbe utile.

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; 
} 

Le sessioni di comando vengono aperte e chiuse in un blocco di utilizzo quando necessario.

In base allo stacktrace, il problema si verifica in StreamWriter -> System.Buffer, che viene nuovamente chiamato da System.IO.SyncTextWriter, che si suppone essere un wrapper thread-safe attorno a System.IO.TextWriter.

Dal momento che ciò è accaduto nel TextWriter, c'è un modo per aggirare questo, per usare un TextWriter a prova di thread?

È sicuro aprire e chiudere la sessione nel modo in cui lo faccio in DynamicPage?

Poiché questo è ovviamente difficile da riprodurre, anche le idee su come farlo sono ben accette.

[UPDATE] Il NHibernate Profiler ha detto che abbiamo anche aperto e chiuso una sessione (in un blocco utilizzando) in una pagina master, in quanto è stato necessario per controllare alcune autorizzazioni per l'utente corrente, quindi due sessioni sono state aperte per richiesta. L'ho rifattorizzato, quindi ora invece di aprire una sessione in una superclasse di pagina, apre la sessione in global.asax su Application_BeginRequest e lo chiude di nuovo su Application_EndRequest, dove la sessione viene inserita in HttpContext.Current.Items.

Ma non esiste un modo sicuro di testare se questo lo risolve.

+0

Sono interessato a questo articolo SO. Nella traccia dello stack, hai questo: - 'SessionInit.GetCurrentUser (sessione di sessione) in j: \ dev \ app \ app_wwwroot \ App_Code \ SessionInit.cs: 107' Cosa c'è nel codice SessionInit.cs? –

+0

Nick, ho aggiunto il codice per SessionInit.GetCurrentUser(). Guarda l'aggiornamento. – Stamppot

+0

Sto ricevendo questo problema ogni tanto nello stesso identico punto in NHibernate: sei riuscito ad accertare come risolvere? –

risposta

12

Stamppot, grazie per aver postato questo problema su StackOverflow; come sapete, non ci sono molte altre informazioni su questo messaggio di errore sul Web. Il mio team si è imbattuto in un problema simile alcuni mesi fa in una webapp che utilizza NHibernate e log4net. (StringTemplate sarebbe stato coinvolto anche.) Noi "fisse" alla problen reindirizzando Console.Out/Errore su null flussi (efficacemente loro disattivazione) nel gestore di eventi Application_Start() 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)); 
} 

Dettagli: Nel nostro caso, l'errore "probabile condizione di competizione ..." era correlato al carico. Sul server di produzione, questa eccezione si verificava sporadicamente, causando il crash del processo di lavoro in ogni occasione. Alla fine abbiamo scoperto come riprodurlo, eseguendo uno script che inondava la webapp con molte richieste in un breve periodo di tempo. Le tracce dello stack di eccezioni, quando correlate al codice sorgente di NHibernate/StringTemplate/log4net, indicavano l'uso dei metodi Console.Out/Error per l'accesso a varie situazioni. Sembra un posto strano perché un tale errore si verifichi --- non sono questi metodi considered to be thread-safe? Tuttavia, dopo aver applicato la soluzione precedente, il problema scompare immediatamente e da allora non è più tornato. Sfortunatamente, altre priorità ci hanno impedito di scavare più a fondo --- ma qualunque sia la causa principale del problema, non si è manifestata in nessun altro modo.

+0

Awk, grazie per questa "correzione". Se mantiene gli errori lontani sono felice. – Stamppot

+0

BTW, potresti riprodurlo ogni volta che hai eseguito la sceneggiatura?Qualche dettaglio su di esso, come quante richieste per quanto tempo ecc? Anche la sceneggiatura sarebbe bella, se possibile. – Stamppot

+3

@APW: Abbiamo riscontrato questo problema esatto quando abbiamo aggiornato log4net a 1.2.12 di recente. Non ho idea del motivo per cui scrivere su Console Out lo farebbe. La tua correzione disabiliterebbe globalmente la registrazione della console che risolverà definitivamente il problema. Un'altra cosa (meno globale) che puoi fare è assicurarti che, nel caso di NHibernate, l'opzione di configurazione "show_sql" sia impostata su false. show_sql scrive * direttamente * su Console Out, completamente indipendentemente da log4net. Credo che sia il caso specifico a causare i problemi che l'OP stava avendo. –

0

Il problema con la soluzione fornita da @APW è che, per impostazione predefinita, StreamWriter è non thread-safe. Controllalo qui: https://msdn.microsoft.com/en-us/library/system.io.streamwriter(v=vs.110).aspx

Passando "new StreamWriter" su Console.Set * si passa un'istanza non thread-safe. Quindi penso che sia una questione di tempo per vedere di nuovo errori simili.

Il modo corretto sarebbe utilizzare il metodo TextWriter.Synchronized per avvolgere Stream.Null non sicuro.

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

UPD: Ignora questo. Ho trovato che Console.SetOut avvolge qualsiasi flusso in TextWriter.Synchronized (...). Proof.

Problemi correlati