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

Expand Snapshot Remover task log messages with context

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 3.5.0
    • Fix Version/s: 3.6.0
    • Component/s: Logging
    • Labels:
    • Story Points:
      2
    • Epic Link:
    • Sprint:
      Core Sprint 102, Core Sprint 103, Core Sprint 104

      Description

      Per -NEXUS-13580  Tasks that can support additional task log progress information need to be updated to provide

      1. At the start and end of each major area of work performed by the task, add a contextual INFO log message to the nexus.log and task specific log indicating what work is being/been performed
      2. At regular intervals during work, log progress with contextual data about the actual progress of that specific work

      AC for the Snapshot Remover task:

      1. Major areas of work: Effectively each major method in RemoveSnapshotsFacetImpl can have a log.info. A number already do (e.g. processSnapshots), but some do not (e.g. processRepository and findReleasedSnapshots). There are many possible places of 'major work' in this task (compared to all others) so this may require some iteration with feedback from support.
      2. Contextual data: depends on the major stage we are in, but there are a number of iterators in the task that can be leveraged.

      Note: the exact items logged may get clearer as the work is done. Above AC is from a quick analysis of the code

      Original description (above description added to be inline with the other task log context updates:


      In contrast to NEXUS-13939 which deals with Mark messages only across all tasks, this is a more specific issue about snapshot removal task.

      Expected

      • At the start and end of each major area of work performed by the task, add a contextual INFO log message to the nexus.log and task specific log indicating what work is being/been performed
      • at regular intervals during work, log progress with contextual data about the actual progress of that specific work
      • looking at a thread dump should not be the only way to tell what the task is doing at any given moment.

      Attached Example task log output which is not adequate.

      When the log was captured, a thread dump shows the task is busy trying to find released snapshots, but there is no indication in the log that this is what it is actually doing or what progress it has made so that one can have a better sense of when it might complete or move on to the next piece of work.

      quartz-1-thread-2 id=204 state=RUNNABLE
          at com.orientechnologies.common.concur.lock.ODistributedCounter.increment(ODistributedCounter.java:46)
          at com.orientechnologies.common.concur.lock.OReadersWriterSpinLock.acquireReadLock(OReadersWriterSpinLock.java:77)
          at com.orientechnologies.orient.core.storage.cache.local.twoq.O2QCache.release(O2QCache.java:432)
          at com.orientechnologies.orient.core.storage.impl.local.paginated.base.ODurableComponent.releasePage(ODurableComponent.java:169)
          at com.orientechnologies.orient.core.index.sbtree.local.OSBTree.access$3200(OSBTree.java:75)
          at com.orientechnologies.orient.core.index.sbtree.local.OSBTree$OSBTreeCursorForward.next(OSBTree.java:2111)
          at com.orientechnologies.orient.core.index.engine.OSBTreeIndexEngine$OSBTreeIndexCursor.nextEntry(OSBTreeIndexEngine.java:271)
          at com.orientechnologies.orient.core.index.OIndexAbstractCursor.hasNext(OIndexAbstractCursor.java:83)
          at com.orientechnologies.orient.core.index.OIndexChangesWrapper.hasNext(OIndexChangesWrapper.java:138)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.serialIterator(OCommandExecutorSQLSelect.java:1635)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.fetchFromTarget(OCommandExecutorSQLSelect.java:1584)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.fetchValuesFromIndexCursor(OCommandExecutorSQLSelect.java:2464)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.searchForIndexes(OCommandExecutorSQLSelect.java:2278)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.searchInClasses(OCommandExecutorSQLSelect.java:1019)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLResultsetAbstract.assignTarget(OCommandExecutorSQLResultsetAbstract.java:209)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.assignTarget(OCommandExecutorSQLSelect.java:530)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.executeSearch(OCommandExecutorSQLSelect.java:512)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLSelect.execute(OCommandExecutorSQLSelect.java:488)
          at com.orientechnologies.orient.core.sql.OCommandExecutorSQLDelegate.execute(OCommandExecutorSQLDelegate.java:74)
          at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.executeCommand(OAbstractPaginatedStorage.java:3208)
          at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.command(OAbstractPaginatedStorage.java:3146)
          at com.orientechnologies.orient.core.sql.query.OSQLQuery.run(OSQLQuery.java:78)
          at com.orientechnologies.orient.core.sql.query.OSQLAsynchQuery.run(OSQLAsynchQuery.java:74)
          at com.orientechnologies.orient.core.sql.query.OSQLSynchQuery.run(OSQLSynchQuery.java:85)
          at com.orientechnologies.orient.core.query.OQueryAbstract.execute(OQueryAbstract.java:33)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl.lambda$7(RemoveSnapshotsFacetImpl.java:327)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$Lambda$226/595543127.apply(Unknown Source)
          at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:267)
          at java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1548)
          at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
          at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
          at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
          at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
          at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl.findReleasedSnapshots(RemoveSnapshotsFacetImpl.java:336)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl.processReleasedSnapshots(RemoveSnapshotsFacetImpl.java:213)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl.processRepository(RemoveSnapshotsFacetImpl.java:197)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$EnhancerByGuice$$bbbe27aa.CGLIB$processRepository$1(<generated>)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$EnhancerByGuice$$bbbe27aa$$FastClassByGuice$$6f372d4a.invoke(<generated>)
          at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:76)
          at org.sonatype.nexus.transaction.TransactionalWrapper.proceedWithTransaction(TransactionalWrapper.java:56)
          at org.sonatype.nexus.transaction.TransactionInterceptor.invoke(TransactionInterceptor.java:54)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:77)
          at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$EnhancerByGuice$$bbbe27aa.processRepository(<generated>)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl.removeSnapshots(RemoveSnapshotsFacetImpl.java:150)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$EnhancerByGuice$$bbbe27aa.CGLIB$removeSnapshots$0(<generated>)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$EnhancerByGuice$$bbbe27aa$$FastClassByGuice$$6f372d4a.invoke(<generated>)
          at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:76)
          at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
          at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:270)
          at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:77)
          at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)
          at org.sonatype.nexus.repository.maven.internal.RemoveSnapshotsFacetImpl$$EnhancerByGuice$$bbbe27aa.removeSnapshots(<generated>)
          at org.sonatype.nexus.repository.maven.tasks.RemoveSnapshotsTask.execute(RemoveSnapshotsTask.java:58)
          at org.sonatype.nexus.repository.RepositoryTaskSupport.execute(RepositoryTaskSupport.java:56)
          at org.sonatype.nexus.scheduling.TaskSupport.call(TaskSupport.java:92)
          at org.sonatype.nexus.quartz.internal.task.QuartzTaskJob.doExecute(QuartzTaskJob.java:145)
          at org.sonatype.nexus.quartz.internal.task.QuartzTaskJob.execute(QuartzTaskJob.java:108)
          at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
          at org.sonatype.nexus.thread.internal.MDCAwareRunnable.run(MDCAwareRunnable.java:40)
          at org.apache.shiro.subject.support.SubjectRunnable.doRun(SubjectRunnable.java:120)
          at org.apache.shiro.subject.support.SubjectRunnable.run(SubjectRunnable.java:108)
          at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
          at java.util.concurrent.FutureTask.run(FutureTask.java:266)
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
          at java.lang.Thread.run(Thread.java:748)
      
          Locked synchronizers: count = 1
            - java.util.concurrent.ThreadPoolExecutor$Worker@70357a64
      
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              bradbeck Brad Beck
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Peter Lynch
              Team:
              Nexus - Core
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  tigCommentSecurity.panel-title