Uploaded image for project: 'Dev - Nexus Repo'
  1. Dev - Nexus Repo
  2. NEXUS-14103

log spam ERROR OModificationOperationProhibitedException from healthcheck.downloads.CacheRemovalListener.onRemoval event processing during DatabaseBackupTask execution

    XMLWordPrintable

    Details

      Description

      The DatabaseBackupTask needs to make all databases read only while backing them up.

      During this time, events may be triggered that print stack traces in the nexus.log because they cannot complete:

      2017-08-24 04:30:00,707+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.internal.backup.DatabaseBackupTask - Task log: /data/sonatype/application-data/nexus-professional/nexus3/log/tasks/db.backup-20170824043000.log
      2017-08-24 04:30:00,737+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.internal.backup.DatabaseBackupTask - task named 'backupConfig' database backup to location /data/sonatype/backup
      2017-08-24 04:30:00,835+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.orient.internal.freeze.DatabaseFreezeServiceImpl - Freezing all databases.
      2017-08-24 04:30:00,951+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI - Scheduler put into stand-by mode
      2017-08-24 04:30:01,028+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.quartz.internal.task.QuartzTaskJob - Task not cancelable: 'backupConfig' [db.backup]
      2017-08-24 04:30:01,099+0200 WARN  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.scheduling.internal.TaskActivation - Unable to cancel task: backupConfig
      
      ...
      
      4700 of these:
      
      2017-08-24 04:30:01,902+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - Exception in thread "pool-21-thread-1" Exception in thread "pool-21-thread-8" com.orientechnologies.common.concur.lock.OModificationOperationProhibitedException: Modification requests are prohibited
      	DB name="component"
      2017-08-24 04:30:01,918+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      2017-08-24 04:30:01,918+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
      2017-08-24 04:30:01,918+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
      2017-08-24 04:30:01,918+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.storage.impl.local.paginated.atomicoperations.OAtomicOperationsManager.throwFreezeExceptionIfNeeded(OAtomicOperationsManager.java:363)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.storage.impl.local.paginated.atomicoperations.OAtomicOperationsManager.startAtomicOperation(OAtomicOperationsManager.java:201)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.startStorageTx(OAbstractPaginatedStorage.java:3677)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.commit(OAbstractPaginatedStorage.java:1638)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.tx.OTransactionOptimistic.doCommit(OTransactionOptimistic.java:541)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.tx.OTransactionOptimistic.commit(OTransactionOptimistic.java:99)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:2891)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:2860)
      2017-08-24 04:30:01,919+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.sonatype.nexus.orient.transaction.OrientTransaction.commit(OrientTransaction.java:83)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.sonatype.nexus.transaction.TransactionalWrapper.proceedWithTransaction(TransactionalWrapper.java:67)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.sonatype.nexus.transaction.Operations.transactional(Operations.java:200)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.sonatype.nexus.transaction.Operations.run(Operations.java:155)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.sonatype.nexus.orient.transaction.OrientOperations.run(OrientOperations.java:63)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.sonatype.nexus.plugins.healthcheck.downloads.CacheRemovalListener.onRemoval(CacheRemovalListener.java:52)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at com.google.common.cache.RemovalListeners$1$1.run(RemovalListeners.java:51)
      2017-08-24 04:30:01,920+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.sonatype.nexus.thread.internal.MDCAwareRunnable.run(MDCAwareRunnable.java:40)
      2017-08-24 04:30:01,921+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.apache.shiro.subject.support.SubjectRunnable.doRun(SubjectRunnable.java:120)
      2017-08-24 04:30:01,921+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at org.apache.shiro.subject.support.SubjectRunnable.run(SubjectRunnable.java:108)
      2017-08-24 04:30:01,921+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      2017-08-24 04:30:01,921+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      2017-08-24 04:30:01,921+0200 ERROR [pool-21-thread-1] anonymous java.lang.Throwable - 	at java.lang.Thread.run(Thread.java:745)
      
      14 minutes later....
      
      2017-08-24 04:44:00,706+0200 INFO  [pool-143-thread-1] *SYSTEM org.sonatype.nexus.internal.backup.DatabaseBackupTask - ---- Mark ----
      2017-08-24 04:44:03,543+0200 INFO  [dbbackup-9-thread-3] *SYSTEM org.sonatype.nexus.internal.backup.DatabaseBackupRunner - database backup of component completed successfully
      2017-08-24 04:44:03,577+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.orient.internal.freeze.DatabaseFreezeServiceImpl - Releasing all databases.
      2017-08-24 04:44:03,601+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.quartz.internal.QuartzSchedulerSPI - Scheduler put into ready mode
      2017-08-24 04:44:03,639+0200 INFO  [quartz-5-thread-20] *SYSTEM org.sonatype.nexus.quartz.internal.task.QuartzTaskInfo - Task 'backupConfig' [db.backup] state change RUNNING -> WAITING (OK)
      
      

      This processing seems related to healthcheck download counts trying to update a read only database:

      at com.sonatype.nexus.plugins.healthcheck.downloads.CacheRemovalListener.onRemoval(CacheRemovalListener.java:52)
      

      Expected

      • do not spam the log with these stack traces. Review if even attempting the database update is warranted during read only mode.
      • rule out a potential thread pool leak if this case happens. a customer reporting this log spam also is reporting java.lang.OutOfMemoryError: unable to create new native thread in a host that otherwise has robust resources we now believe the thread leak was caused by task logging NEXUS-14227, not attempting to write to the database when it is read only mode

        Attachments

          Activity

            People

            Assignee:
            Unassigned
            Reporter:
            plynch Peter Lynch
            Last Updated By:
            Peter Lynch
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:
              Date of First Response:

                tigCommentSecurity.panel-title