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

'InvalidStateException: Invalid state: FAILED; allowed: [STARTED]' after upgrading from 3.39 to 3.40

    Details

    • Story Points:
      2
    • Sprint:
      NXRM Sentinels Sprint 37
    • InvestmentLayer:
      support-escalated
    • Aha Concept:
      non-concept

      Description

      SYMPTOM:

      After upgrading Nexus from 3.39 to 3.40 with PostgreSQL, downloading or uploading files fail, and nexus.log shows:

      2022-06-24 02:20:47,383+0000 WARN  [qtp491203635-109]  admin org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Failure servicing: PUT /repository/raw-hosted/test.txt
      org.sonatype.nexus.common.stateguard.InvalidStateException: Invalid state: FAILED; allowed: [STARTED]
              at org.sonatype.nexus.common.stateguard.StateGuard._ensure(StateGuard.java:115)
              at org.sonatype.nexus.common.stateguard.StateGuard.access$1(StateGuard.java:108)
              at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:271)
              at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:54)
              at org.sonatype.nexus.repository.content.fluent.internal.FluentBlobsImpl.ingest(FluentBlobsImpl.java:99)
      ...
      

      The issue could affect any upgrade using a file blobstore upgrading to 3.40.0 on H2 or PostgreSQL

      WORKAROUND:

      1. Stop Nexus normally
      2. Remove the UUID-deletions.index from the file blob store (eg: ./sonatype-work/nexus3/blobs/default/c2c0002d-b20c44f1-b564df4b-542113f0-32287852-deletions.index)
      3. Append "rebuildDeletedBlobIndex=true" in the metadata.properties, which is located in the same directory as UUID-deletions.index file.

      REPRODUCE STEPS:

      1. Install NXRM 3.39.0 with "nexus.datastore.enabled=true" (using H2 for this testing)
      2. create raw-hosted, upload a dummy file, then delete
        curl -D- -u "admin:admin123" -X POST "http://localhost:8081/service/rest/v1/repositories/raw/hosted" \
          -H 'accept: application/json' \
          -H 'Content-Type: application/json' \
          -d '{
          "name": "raw-hosted",
          "online": true,
          "storage": {
            "blobStoreName": "default",
            "strictContentTypeValidation": true,
            "writePolicy": "ALLOW"
          }
        }'
        
        curl -D- -u "admin:admin123" -T <(echo 'test text') "http://localhost:8081/repository/raw-hosted/test.txt"
        curl -D- -u "admin:admin123" -T <(echo 'test text 2') "http://localhost:8081/repository/raw-hosted/test2.txt"
        
        curl -D- -u "admin:admin123" -X DELETE "http://localhost:8081/repository/raw-hosted/test.txt"
        curl -D- -u "admin:admin123" -X DELETE "http://localhost:8081/repository/raw-hosted/test2.txt"
        
      3. Restart Nexus to force writing the deletions.index
        [root@node3390 sonatype]# strings ./sonatype-work/nexus3/blobs/default/c2c0002d-b20c44f1-b564df4b-542113f0-32287852-deletions.index
        $fc16d068-cc61-4d78-bd1c-e96b04d9c0f2
        $4e74a334-91f8-4cf9-bb1f-d0288d2e801a
        
      4. Upgrade to 3.40 normally
      5. Try downloading or uploading something
        [root@node3390 ~]# curl -D- -u "admin:admin123" -T <(echo 'test text') "http://localhost:8081/repository/raw-hosted/test.txt"
        HTTP/1.1 100 Continue
        
        HTTP/1.1 500 Server Error
        Server: Nexus/3.40.0-03 (PRO)
        X-Content-Type-Options: nosniff
        Content-Security-Policy: sandbox allow-forms allow-modals allow-popups allow-presentation allow-scripts allow-top-navigation
        X-XSS-Protection: 1; mode=block
        X-Frame-Options: DENY
        Content-Length: 0
        

      EXPECTED BEHAVIOUR:

      Upgrading should not make Nexus unusable.

      ACTUAL BEHAVIOUR:

      Because of uncaught exception, it looks like failed to start the Blobstore:

      2022-06-23 22:42:04,877+0000 INFO  [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.internal.datastore.DatastoreFileBlobDeletionIndex - Processing blobstore default, discovered file-based deletion index. Migrating to DB-based
      2022-06-23 22:42:04,950+0000 ERROR [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.FileBlobStore - Failed transition: NEW -> STARTED
      org.sonatype.nexus.datastore.api.DuplicateKeyException: Duplicate key
              at org.sonatype.nexus.datastore.mybatis.EntityExecutor.update(EntityExecutor.java:86)
              at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:194)
              at org.sonatype.nexus.datastore.mybatis.DataAccessSqlSession.update(DataAccessSqlSession.java:83)
              at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:181)
              at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:62)
              at org.apache.ibatis.binding.MapperProxy$PlainMethodInvoker.invoke(MapperProxy.java:145)
              at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:86)
              at com.sun.proxy.$Proxy150.createRecord(Unknown Source)
              at org.sonatype.nexus.blobstore.file.internal.SoftDeletedBlobsStoreImpl.createRecord(SoftDeletedBlobsStoreImpl.java:45)
              at org.sonatype.nexus.transaction.TransactionalWrapper.proceedWithTransaction(TransactionalWrapper.java:58)
              at org.sonatype.nexus.transaction.TransactionInterceptor.proceedWithTransaction(TransactionInterceptor.java:66)
              at org.sonatype.nexus.transaction.TransactionInterceptor.invoke(TransactionInterceptor.java:55)
              at org.sonatype.nexus.blobstore.file.internal.datastore.DatastoreFileBlobDeletionIndex.migrateDeletionIndexFromFileIfExists(DatastoreFileBlobDeletionIndex.java:155)
              at org.sonatype.nexus.blobstore.file.internal.datastore.DatastoreFileBlobDeletionIndex.initIndex(DatastoreFileBlobDeletionIndex.java:73)
              at org.sonatype.nexus.blobstore.file.FileBlobStore.doStart(FileBlobStore.java:240)
              at org.sonatype.nexus.common.stateguard.StateGuardLifecycleSupport.start(StateGuardLifecycleSupport.java:69)
              at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
              at org.sonatype.nexus.common.stateguard.StateGuard$TransitionImpl.run(StateGuard.java:193)
              at org.sonatype.nexus.common.stateguard.TransitionsInterceptor.invoke(TransitionsInterceptor.java:57)
              at org.sonatype.nexus.repository.internal.blobstore.BlobStoreManagerImpl.doStart(BlobStoreManagerImpl.java:181)
              at org.sonatype.nexus.common.stateguard.StateGuardLifecycleSupport.start(StateGuardLifecycleSupport.java:69)
              at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
              at org.sonatype.nexus.common.stateguard.StateGuard$TransitionImpl.run(StateGuard.java:193)
              at org.sonatype.nexus.common.stateguard.TransitionsInterceptor.invoke(TransitionsInterceptor.java:57)
              at org.sonatype.nexus.repository.manager.internal.RepositoryManagerImpl.doStart(RepositoryManagerImpl.java:238)
              at org.sonatype.nexus.common.stateguard.StateGuardLifecycleSupport.start(StateGuardLifecycleSupport.java:69)
              at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
              at org.sonatype.nexus.common.stateguard.StateGuard$TransitionImpl.run(StateGuard.java:193)
              at org.sonatype.nexus.common.stateguard.TransitionsInterceptor.invoke(TransitionsInterceptor.java:57)
              at org.sonatype.nexus.extender.NexusLifecycleManager.startComponent(NexusLifecycleManager.java:199)
              at org.sonatype.nexus.extender.NexusLifecycleManager.to(NexusLifecycleManager.java:111)
              at org.sonatype.nexus.extender.NexusContextListener.moveToPhase(NexusContextListener.java:319)
              at org.sonatype.nexus.extender.NexusContextListener.frameworkEvent(NexusContextListener.java:216)
              at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1597)
              at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)
              at java.lang.Thread.run(Thread.java:750)
      Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "pk_soft_deleted_blobs_blob_id"
        Detail: Key (blob_id)=(5cfba807-47d5-470d-a35b-51d0a2150e04) already exists.
              at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2675)
              at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2365)
              at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:355)
              at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:490)
              at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:408)
              at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:166)
              at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:155)
              at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
              at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
              at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:47)
              at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
              at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
              at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
              at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)
              at org.sonatype.nexus.datastore.mybatis.EntityExecutor.update(EntityExecutor.java:81)
              ... 35 common frames omitted
      

      Interesting thing is the code tries to INSERT same one twice immediately:

      2022-06-24 02:11:05,558+0000 INFO  [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.internal.datastore.DatastoreFileBlobDeletionIndex - Processing blobstore default, discovered file-based deletion index. Migrating to DB-based
      2022-06-24 02:11:05,558+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Opening JDBC Connection
      2022-06-24 02:11:05,559+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [HikariProxyConnection@1173111055 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,559+0000 DEBUG [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.store.internal.SoftDeletedBlobsDAO.createRecord - ==>  Preparing: INSERT INTO soft_deleted_blobs (blob_id, source_blob_store_name) VALUES (?, ?);
      2022-06-24 02:11:05,559+0000 DEBUG [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.store.internal.SoftDeletedBlobsDAO.createRecord - ==> Parameters: fc16d068-cc61-4d78-bd1c-e96b04d9c0f2(String), default(String)
      2022-06-24 02:11:05,559+0000 DEBUG [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.store.internal.SoftDeletedBlobsDAO.createRecord - <==    Updates: 1
      2022-06-24 02:11:05,560+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@1173111055 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,560+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1173111055 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,560+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1173111055 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,561+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Opening JDBC Connection
      2022-06-24 02:11:05,561+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [HikariProxyConnection@1055147817 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,561+0000 DEBUG [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.store.internal.SoftDeletedBlobsDAO.createRecord - ==>  Preparing: INSERT INTO soft_deleted_blobs (blob_id, source_blob_store_name) VALUES (?, ?);
      2022-06-24 02:11:05,562+0000 DEBUG [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.store.internal.SoftDeletedBlobsDAO.createRecord - ==> Parameters: fc16d068-cc61-4d78-bd1c-e96b04d9c0f2(String), default(String)
      2022-06-24 02:11:05,563+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Rolling back JDBC Connection [HikariProxyConnection@1055147817 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,563+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1055147817 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,563+0000 DEBUG [FelixStartLevel]  *SYSTEM org.apache.ibatis.transaction.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1055147817 wrapping conn0: url=jdbc:h2:file:/opt/sonatype/nexus-3.40.0/sonatype-work/nexus3/db/nexus user=]
      2022-06-24 02:11:05,563+0000 ERROR [FelixStartLevel]  *SYSTEM org.sonatype.nexus.blobstore.file.FileBlobStore - Failed transition: NEW -> STARTED
      org.sonatype.nexus.datastore.api.DuplicateKeyException: Duplicate key
      

      This might be because the code uses com.squareup.tape.QueueFile#peek() in DatastoreFileBlobDeletionIndex.migrateDeletionIndexFromFileIfExists.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              mpiggott Matthew Piggott
              Reporter:
              hosako Hajime Osako
              Last Updated By:
              Michael Oliverio Michael Oliverio
              Team:
              NXRM - Sentinels
              Owner:
              Matthew Piggott Matthew Piggott
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title