[
https://issues.apache.org/jira/browse/CASSANDRA-18747?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17765856#comment-17765856
]
Ekaterina Dimitrova commented on CASSANDRA-18747:
-------------------------------------------------
So from the logs from nightlies we can see the following race is happening on
startup of node 3:
{code:java}
INFO [MigrationStage:1] 2023-08-10 18:39:32,992
DefaultSchemaUpdateHandler.java:221 - Applying schema change due to received
mutations: SchemaTransformationResult{2e847089-a5be-3705-a1aa-4a7f9b3ebe36 -->
d03783d7-b468-3c1a-82f1-8e30b2edde8b,
diff=KeyspacesDiff{created=[KeyspaceMetadata{name=system_auth, kind=REGULAR,
params=KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}, tables=[system_auth.cidr_groups,
system_auth.cidr_permissions, system_auth.identity_to_role,
system_auth.network_permissions, system_auth.resource_role_permissons_index,
system_auth.role_members, system_auth.role_permissions, system_auth.roles],
views=[], functions=[], types=[]}], dropped=[], altered=[]}}
DEBUG [MigrationStage:1] 2023-08-10 18:39:32,993
DefaultSchemaUpdateHandler.java:259 - Schema updated:
SchemaTransformationResult{2e847089-a5be-3705-a1aa-4a7f9b3ebe36 -->
d03783d7-b468-3c1a-82f1-8e30b2edde8b,
diff=KeyspacesDiff{created=[KeyspaceMetadata{name=system_auth, kind=REGULAR,
params=KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}, tables=[system_auth.cidr_groups,
system_auth.cidr_permissions, system_auth.identity_to_role,
system_auth.network_permissions, system_auth.resource_role_permissons_index,
system_auth.role_members, system_auth.role_permissions, system_auth.roles],
views=[], functions=[], types=[]}], dropped=[], altered=[]}}
DEBUG [PendingRangeCalculator:1] 2023-08-10 18:39:32,997 TokenMetadata.java:876
- Starting pending range calculation for system_traces
DEBUG [PendingRangeCalculator:1] 2023-08-10 18:39:32,997 TokenMetadata.java:881
- Pending range calculation for system_traces completed (took: 0ms)
DEBUG [PendingRangeCalculator:1] 2023-08-10 18:39:32,997 TokenMetadata.java:876
- Starting pending range calculation for system_distributed
DEBUG [PendingRangeCalculator:1] 2023-08-10 18:39:32,997 TokenMetadata.java:881
- Pending range calculation for system_distributed completed (took: 0ms)
INFO [MigrationStage:1] 2023-08-10 18:39:32,998 Keyspace.java:366 - Creating
replication strategy system_auth params KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}
DEBUG [MigrationStage:1] 2023-08-10 18:39:32,998 Keyspace.java:370 - New
replication settings for keyspace system_auth - invalidating disk boundary
caches
ERROR [PendingRangeCalculator:1] 2023-08-10 18:39:33,000
JVMStabilityInspector.java:70 - Exception in thread
Thread[PendingRangeCalculator:1,5,PendingRangeCalculator]
java.lang.AssertionError: Unknown keyspace system_auth
at org.apache.cassandra.db.Keyspace.<init>(Keyspace.java:324)
at org.apache.cassandra.db.Keyspace.lambda$open$0(Keyspace.java:162)
at
org.apache.cassandra.utils.concurrent.LoadingMap.blockingLoadIfAbsent(LoadingMap.java:105)
at
org.apache.cassandra.schema.Schema.maybeAddKeyspaceInstance(Schema.java:251)
at org.apache.cassandra.db.Keyspace.open(Keyspace.java:162)
at org.apache.cassandra.db.Keyspace.open(Keyspace.java:151)
at
org.apache.cassandra.service.PendingRangeCalculatorService.lambda$new$1(PendingRangeCalculatorService.java:58)
at
org.apache.cassandra.concurrent.SingleThreadExecutorPlus$AtLeastOnce.run(SingleThreadExecutorPlus.java:60)
at
org.apache.cassandra.concurrent.ExecutionFailure$1.run(ExecutionFailure.java:133)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:829)
DEBUG [GossipStage:1] 2023-08-10 18:39:33,002 MigrationCoordinator.java:428 -
Reported schema d03783d7-b468-3c1a-82f1-8e30b2edde8b at endpoint /127.0.0.1:7000
INFO [GossipStage:1] 2023-08-10 18:39:33,006 TokenMetadata.java:539 - Updating
topology for /127.0.0.1:7000
INFO [MigrationStage:1] 2023-08-10 18:39:33,008 ColumnFamilyStore.java:493 -
Initializing system_auth.cidr_groups
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,011 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.cidr_groups
INFO [GossipStage:1] 2023-08-10 18:39:33,010 TokenMetadata.java:539 - Updating
topology for /127.0.0.1:7000
DEBUG [PendingRangeCalculator:1] 2023-08-10 18:39:33,026 HeapUtils.java:133 -
Heap dump creation on uncaught exceptions is disabled.
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,034 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 5)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,034 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=5, directoriesVersion=0} for
system_auth.cidr_groups
INFO [GossipStage:1] 2023-08-10 18:39:33,034 Gossiper.java:1467 - Node
/127.0.0.2:7000 is now part of the cluster
DEBUG [GossipStage:1] 2023-08-10 18:39:33,038 StorageService.java:3187 - Node
/127.0.0.2:7000 state NORMAL, token [-149492677599243657, -2026557007112229685,
-3846561308092176084, -4910902297865239480, -6169322889008892514,
-8291017789011127624, 1019462245579770721, 2068586045908961809,
3004499218700477229, 3420136878272117109, 4631817224944098254,
5029140077292811045, 6287560793238254133, 7321861439913658500,
7748147941194787890, 9098349767769465773]
INFO [MigrationStage:1] 2023-08-10 18:39:33,055 ColumnFamilyStore.java:493 -
Initializing system_auth.cidr_permissions
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,058 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.cidr_permissions
DEBUG [GossipStage:1] 2023-08-10 18:39:33,060 StorageService.java:3097 - New
node /127.0.0.2:7000 at token -149492677599243657
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,061 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 5)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,061 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=5, directoriesVersion=0} for
system_auth.cidr_permissions
DEBUG [GossipStage:1] 2023-08-10 18:39:33,061 StorageService.java:3097 - New
node /127.0.0.2:7000 at token -2026557007112229685
DEBUG [GossipStage:1] 2023-08-10 18:39:33,062 StorageService.java:3097 - New
node /127.0.0.2:7000 at token -3846561308092176084
DEBUG [GossipStage:1] 2023-08-10 18:39:33,062 StorageService.java:3097 - New
node /127.0.0.2:7000 at token -4910902297865239480
DEBUG [GossipStage:1] 2023-08-10 18:39:33,063 StorageService.java:3097 - New
node /127.0.0.2:7000 at token -6169322889008892514
DEBUG [GossipStage:1] 2023-08-10 18:39:33,065 StorageService.java:3097 - New
node /127.0.0.2:7000 at token -8291017789011127624
DEBUG [GossipStage:1] 2023-08-10 18:39:33,065 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 1019462245579770721
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 2068586045908961809
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 3004499218700477229
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 3420136878272117109
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 4631817224944098254
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 5029140077292811045
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 6287560793238254133
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 7321861439913658500
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 7748147941194787890
DEBUG [GossipStage:1] 2023-08-10 18:39:33,066 StorageService.java:3097 - New
node /127.0.0.2:7000 at token 9098349767769465773
INFO [MigrationStage:1] 2023-08-10 18:39:33,080 ColumnFamilyStore.java:493 -
Initializing system_auth.identity_to_role
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,083 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.identity_to_role
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,084 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 6)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,085 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=6, directoriesVersion=0} for
system_auth.identity_to_role
INFO [MigrationStage:1] 2023-08-10 18:39:33,094 ColumnFamilyStore.java:493 -
Initializing system_auth.network_permissions
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,095 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.network_permissions
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,097 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 6)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,098 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=6, directoriesVersion=0} for
system_auth.network_permissions
INFO [MigrationStage:1] 2023-08-10 18:39:33,107 ColumnFamilyStore.java:493 -
Initializing system_auth.resource_role_permissons_index
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,109 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.resource_role_permissons_index
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,111 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 6)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,111 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=6, directoriesVersion=0} for
system_auth.resource_role_permissons_index
INFO [MigrationStage:1] 2023-08-10 18:39:33,121 ColumnFamilyStore.java:493 -
Initializing system_auth.role_members
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,122 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.role_members
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,124 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 6)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,124 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=6, directoriesVersion=0} for
system_auth.role_members
INFO [MigrationStage:1] 2023-08-10 18:39:33,135 ColumnFamilyStore.java:493 -
Initializing system_auth.role_permissions
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,137 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.role_permissions
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,140 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 6)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,141 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=6, directoriesVersion=0} for
system_auth.role_permissions
INFO [MigrationStage:1] 2023-08-10 18:39:33,152 ColumnFamilyStore.java:493 -
Initializing system_auth.roles
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,154 DiskBoundaryManager.java:54 -
Refreshing disk boundary cache for system_auth.roles
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,156 DiskBoundaryManager.java:93 -
Got local ranges [] (ringVersion = 6)
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,156 DiskBoundaryManager.java:57 -
Updating boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data0},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data1},
DataDirectory{location=/home/cassandra/cassandra/cassandra-dtest/tmp/dtest-3qsf1zsl/test/node3/data2}],
positions=null, ringVersion=6, directoriesVersion=0} for system_auth.roles
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,167 TokenMetadata.java:876 -
Starting pending range calculation for system_auth
DEBUG [MigrationStage:1] 2023-08-10 18:39:33,167 TokenMetadata.java:881 -
Pending range calculation for system_auth completed (took: 0ms)
DEBUG [GossipStage:1] 2023-08-10 18:39:33,167 MigrationCoordinator.java:428 -
Reported schema d03783d7-b468-3c1a-82f1-8e30b2edde8b at endpoint
/127.0.0.2:7000{code}
[~jlewandowski] , can you take a look? You've worked a lot on those issues in
the past year or two.
What would be the best way forward?
> Test failure: Fix assertion error AssertionError: Unknown keyspace
> system_auth\n\tat
> org.apache.cassandra.db.Keyspace.<init>(Keyspace.java:324)\n\tat
> org.apache.cassandra.db.Keyspace.lambda$open$0(Keyspace.java:162)
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-18747
> URL: https://issues.apache.org/jira/browse/CASSANDRA-18747
> Project: Cassandra
> Issue Type: Bug
> Components: Test/dtest/python
> Reporter: Ekaterina Dimitrova
> Priority: Normal
> Fix For: 5.0.x, 5.x
>
>
> I've been seeing this assertion error in different tests lately.
> Full error message:
> {code:java}
> failed on teardown with "Unexpected error found in node logs (see stdout for
> full details). Errors: [[node2] 'ERROR [PendingRangeCalculator:1] 2023-08-11
> 16:35:14,445 JVMStabilityInspector.java:70 - Exception in thread
> Thread[PendingRangeCalculator:1,5,PendingRangeCalculator]\njava.lang.AssertionError:
> Unknown keyspace system_auth\n\tat
> org.apache.cassandra.db.Keyspace.<init>(Keyspace.java:324)\n\tat
> org.apache.cassandra.db.Keyspace.lambda$open$0(Keyspace.java:162)\n\tat
> org.apache.cassandra.utils.concurrent.LoadingMap.blockingLoadIfAbsent(LoadingMap.java:105)\n\tat
>
> org.apache.cassandra.schema.Schema.maybeAddKeyspaceInstance(Schema.java:251)\n\tat
> org.apache.cassandra.db.Keyspace.open(Keyspace.java:162)\n\tat
> org.apache.cassandra.db.Keyspace.open(Keyspace.java:151)\n\tat
> org.apache.cassandra.service.PendingRangeCalculatorService.lambda$new$1(PendingRangeCalculatorService.java:58)\n\tat
>
> org.apache.cassandra.concurrent.SingleThreadExecutorPlus$AtLeastOnce.run(SingleThreadExecutorPlus.java:60)\n\tat
>
> org.apache.cassandra.concurrent.ExecutionFailure$1.run(ExecutionFailure.java:133)\n\tat
>
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat
>
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat
>
> io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat
> java.base/java.lang.Thread.run(Thread.java:829)']" Unexpected error found in
> node logs (see stdout for full details). Errors: [[node2] 'ERROR
> [PendingRangeCalculator:1] 2023-08-11 16:35:14,445
> JVMStabilityInspector.java:70 - Exception in thread
> Thread[PendingRangeCalculator:1,5,PendingRangeCalculator]\njava.lang.AssertionError:
> Unknown keyspace system_auth\n\tat
> org.apache.cassandra.db.Keyspace.<init>(Keyspace.java:324)\n\tat
> org.apache.cassandra.db.Keyspace.lambda$open$0(Keyspace.java:162)\n\tat
> org.apache.cassandra.utils.concurrent.LoadingMap.blockingLoadIfAbsent(LoadingMap.java:105)\n\tat
>
> org.apache.cassandra.schema.Schema.maybeAddKeyspaceInstance(Schema.java:251)\n\tat
> org.apache.cassandra.db.Keyspace.open(Keyspace.java:162)\n\tat
> org.apache.cassandra.db.Keyspace.open(Keyspace.java:151)\n\tat
> org.apache.cassandra.service.PendingRangeCalculatorService.lambda$new$1(PendingRangeCalculatorService.java:58)\n\tat
>
> org.apache.cassandra.concurrent.SingleThreadExecutorPlus$AtLeastOnce.run(SingleThreadExecutorPlus.java:60)\n\tat
>
> org.apache.cassandra.concurrent.ExecutionFailure$1.run(ExecutionFailure.java:133)\n\tat
>
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat
>
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat
>
> io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat
> java.base/java.lang.Thread.run(Thread.java:829)']{code}
> Example failures:
> test_failed_snitch_update_property_file_snitch -
> [https://app.circleci.com/pipelines/github/ekaterinadimitrova2/cassandra/2475/workflows/2086619e-0f21-464b-a866-84aca516b5e5/jobs/36716/tests]
> test_gcgs_validation -
> [https://ci-cassandra.apache.org/job/Cassandra-trunk/1666/testReport/junit/dtest.materialized_views_test/TestMaterializedViews/test_gcgs_validation/]
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
