Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

got 2 log errors every minute in latest 1.10.x #6784

Closed
infofromca opened this issue Apr 15, 2016 · 15 comments
Closed

got 2 log errors every minute in latest 1.10.x #6784

infofromca opened this issue Apr 15, 2016 · 15 comments

Comments

@infofromca
Copy link
Contributor

infofromca commented Apr 15, 2016

2016-04-15 18:45:09,214 [84] NHibernate.AssertionFailure - (null) - An AssertionFailure occurred - this may indicate a bug in NHibernate or in your custom types. [(null)]
NHibernate.AssertionFailure: null id in Orchard.Tasks.Locking.Records.DistributedLockRecord entry (don't flush the Session after an exception occurs)
2016-04-15 18:45:09,242 [84] Orchard.Tasks.Locking.Services.DistributedLockService - (null) - An error occurred while trying to acquire lock 'DistributedLock:RealEstateWorld:Orchard.JobsQueue.Services.JobsQueueProcessor'. [(null)]
NHibernate.AssertionFailure: null id in Orchard.Tasks.Locking.Records.DistributedLockRecord entry (don't flush the Session after an exception occurs)
   at NHibernate.Event.Default.DefaultFlushEntityEventListener.CheckId(Object obj, IEntityPersister persister, Object id, EntityMode entityMode)
   at NHibernate.Event.Default.DefaultFlushEntityEventListener.GetValues(Object entity, EntityEntry entry, EntityMode entityMode, Boolean mightBeDirty, ISessionImplementor session)
   at NHibernate.Event.Default.DefaultFlushEntityEventListener.OnFlushEntity(FlushEntityEvent event)
   at NHibernate.Event.Default.AbstractFlushingEventListener.FlushEntities(FlushEvent event)
   at NHibernate.Event.Default.AbstractFlushingEventListener.FlushEverythingToExecutions(FlushEvent event)
   at NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event)
   at NHibernate.Impl.SessionImpl.Flush()
   at NHibernate.Transaction.AdoTransaction.Commit()
   at Orchard.Data.TransactionManager.DisposeSession() in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Data\SessionLocator.cs:line 96
   at Orchard.Data.TransactionManager.Dispose() in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Data\SessionLocator.cs:line 86
   at Autofac.Core.Disposer.Dispose(Boolean disposing)
   at Autofac.Util.Disposable.Dispose()
   at Autofac.Core.Lifetime.LifetimeScope.Dispose(Boolean disposing)
   at Autofac.Util.Disposable.Dispose()
   at Orchard.Tasks.Locking.Services.DistributedLockService.ExecuteOnSeparateTransaction(Action`1 action) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 215
   at Orchard.Tasks.Locking.Services.DistributedLockService.EnsureDistributedLockRecord(String internalName, Nullable`1 maxValidFor) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 142
   at Orchard.Tasks.Locking.Services.DistributedLockService.<>c__DisplayClass9_1.<AcquireLockInternal>b__0() in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 103
   at Orchard.Tasks.Locking.Services.DistributedLockService.RepeatUntilTimeout(Nullable`1 timeout, TimeSpan repeatInterval, Func`1 action) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 198
   at Orchard.Tasks.Locking.Services.DistributedLockService.AcquireLockInternal(String name, Nullable`1 maxValidFor, Nullable`1 timeout, Boolean throwOnTimeout) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 102
2016-04-15 18:45:09,263 [84] Orchard.Tasks.Locking.Services.DistributedLockService - (null) - Error while trying to acquire lock 'Orchard.JobsQueue.Services.JobsQueueProcessor'. [(null)]
NHibernate.AssertionFailure: null id in Orchard.Tasks.Locking.Records.DistributedLockRecord entry (don't flush the Session after an exception occurs)
   at NHibernate.Event.Default.DefaultFlushEntityEventListener.CheckId(Object obj, IEntityPersister persister, Object id, EntityMode entityMode)
   at NHibernate.Event.Default.DefaultFlushEntityEventListener.GetValues(Object entity, EntityEntry entry, EntityMode entityMode, Boolean mightBeDirty, ISessionImplementor session)
   at NHibernate.Event.Default.DefaultFlushEntityEventListener.OnFlushEntity(FlushEntityEvent event)
   at NHibernate.Event.Default.AbstractFlushingEventListener.FlushEntities(FlushEvent event)
   at NHibernate.Event.Default.AbstractFlushingEventListener.FlushEverythingToExecutions(FlushEvent event)
   at NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event)
   at NHibernate.Impl.SessionImpl.Flush()
   at NHibernate.Transaction.AdoTransaction.Commit()
   at Orchard.Data.TransactionManager.DisposeSession() in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Data\SessionLocator.cs:line 96
   at Orchard.Data.TransactionManager.Dispose() in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Data\SessionLocator.cs:line 86
   at Autofac.Core.Disposer.Dispose(Boolean disposing)
   at Autofac.Util.Disposable.Dispose()
   at Autofac.Core.Lifetime.LifetimeScope.Dispose(Boolean disposing)
   at Autofac.Util.Disposable.Dispose()
   at Orchard.Tasks.Locking.Services.DistributedLockService.ExecuteOnSeparateTransaction(Action`1 action) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 215
   at Orchard.Tasks.Locking.Services.DistributedLockService.EnsureDistributedLockRecord(String internalName, Nullable`1 maxValidFor) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 142
   at Orchard.Tasks.Locking.Services.DistributedLockService.<>c__DisplayClass9_1.<AcquireLockInternal>b__0() in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 103
   at Orchard.Tasks.Locking.Services.DistributedLockService.RepeatUntilTimeout(Nullable`1 timeout, TimeSpan repeatInterval, Func`1 action) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 198
   at Orchard.Tasks.Locking.Services.DistributedLockService.AcquireLockInternal(String name, Nullable`1 maxValidFor, Nullable`1 timeout, Boolean throwOnTimeout) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 134
   at Orchard.Tasks.Locking.Services.DistributedLockService.TryAcquireLock(String name, Nullable`1 maxValidFor, Nullable`1 timeout, IDistributedLock& dLock) in C:\Users\andy\Documents\orchard110house-zg\Orchard1203\Orchard\src\Orchard\Tasks\Locking\Services\DistributedLockService.cs:line 42
@infofromca infofromca changed the title got log error every minute got log error every minute in latest 1.10.x Apr 15, 2016
@infofromca infofromca changed the title got log error every minute in latest 1.10.x got log 2 errors every minute in latest 1.10.x Apr 15, 2016
@infofromca infofromca changed the title got log 2 errors every minute in latest 1.10.x got 2 log errors every minute in latest 1.10.x Apr 15, 2016
@sebastienros sebastienros added this to the Orchard 1.10.1 milestone Apr 15, 2016
@jtkech
Copy link
Member

jtkech commented Apr 16, 2016

Which database do you use?

See #6729, only applied to the dev branch, where it was needed to do the RequireNew() before creating the schema of the DistributedLockRecord table, this when using a PostgreSQL database. Maybe you have the same issue in 1.10.x.

But, we must be careful, it seems that we still need (at least with sqlce & sql server) to do a RequireNew() after the schema creation, see #6783.

Best.

@infofromca
Copy link
Contributor Author

compact ce

@sebastienros
Copy link
Member

Let's revert the fix for now if it's creating another issue, and reopen the initial bug

@sebastienros
Copy link
Member

So I am lost, the PostreSQL fix is only on dev, can everyone repro the issue on 1.10.x ? Since which commit then?

@infofromca
Copy link
Contributor Author

infofromca commented Apr 19, 2016

IT was NOT good ON 1.10 RELEASE

@jtkech
Copy link
Member

jtkech commented Apr 19, 2016

@sebastienros

So, i think the issue of @infofromca is on 1.10 but before this fix #6737 by @sfmskywalker. So, not related with #6729 only applied to dev.

I mentioned #6729 in case @infofromca would use e.g a PostgreSQL database.

@infofromca
Copy link
Contributor Author

it has been from 1.10 to 1.10.x today. which means not relate with #6737
I tested that in two.
got ex inside ExecuteOnSeparateTransaction method.
this is 1.10
distributelock

this is today's 1.10.x

ds1 10

@jtkech
Copy link
Member

jtkech commented Apr 19, 2016

@sebastienros @infofromca

Oh yes, i think i understand and i can simulate the use case in last 1.10.x.

So, it works as long as a lock record is acquired then deleted after the related job ended. But if a lock record is not deleted this way (this is my simulation), the following code added in #6737 will try to remove it before creating a new one:

        foreach (var expiredRecord in records) {
            repository.Delete(expiredRecord);
        }

        // No valid record existed, so we're good to create a new one.
        Logger.Debug("No valid record was found for lock '{0}'; creating a new record.", ...);

        repository.Create(new DistributedLockRecord {
        ...

So, if you already have a lock record, i think the issue is that we can't delete a lock record and create a new one with the same index in the same transaction.

Best

@jtkech
Copy link
Member

jtkech commented Apr 19, 2016

@sebastienros

Then, because we are already in a new transaction, so i think we can add a flush after the delete. Then, it seems to work.

                    repository.Delete(expiredRecord);
                    // Evolutive
                    repository.Flush();

Best.

@infofromca
Copy link
Contributor Author

@jtkech @sebastienros
I also added repository.Flush(); inside the foreach, verified that it is ok

@sebastienros
Copy link
Member

Even though Flush is usually not the solution, here it is correct.

@sebastienros
Copy link
Member

PR please

@jtkech
Copy link
Member

jtkech commented Apr 19, 2016

If @infofromca want to do it, otherwise i can do it.

@jtkech
Copy link
Member

jtkech commented Apr 19, 2016

@sebastienros

Another solution would be to use another transaction as in the DeleteDistributedLockRecord() method, but maybe too many transactions.

Or just an idea on the fly: not delete the record but only update the valid time.

Best.

@infofromca
Copy link
Contributor Author

so this give me a idea:
Can we create AddOrUpdate method on IRepository<> ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants