Loading...

Details

Type: Bug
Resolution: Fixed
Priority: Critical
Fix Version/s: 3.40.1
Affects Version/s: 3.40.0
Component/s: Blobstore, Database H2, Database PostgreSQL, Upgrade
Labels:

Story Points:
2
Epic Link:
2022 Q2 Maintenance
Sprint:
NXRM Sentinels Sprint 37
Notability:
2
Aha Concept:
non-concept
Impact:
2

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:

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

REPRODUCE STEPS:

Install NXRM 3.39.0 with "nexus.datastore.enabled=true" (using H2 for this testing)

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"

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

Upgrade to 3.40 normally

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

relates

NEXUS-37958 Blob store health check fails reporting group blobstores as not writable

New

NEXUS-34969 "DatastoreFileBlobDeletionIndex - Processing blobstore" takes long time and block the startup

Closed

mentioned in: Page Loading...

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

Details

Description

SYMPTOM:

WORKAROUND:

REPRODUCE STEPS:

EXPECTED BEHAVIOUR:

ACTUAL BEHAVIOUR:

Attachments

Issue Links

Activity

People

Dates

tigCommentSecurity.panel-title