Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

kv/kvserver/protectedts/ptstorage: TestCorruptData failed #52176

Closed
cockroach-teamcity opened this issue Jul 31, 2020 · 1 comment · Fixed by #52200
Closed

kv/kvserver/protectedts/ptstorage: TestCorruptData failed #52176

cockroach-teamcity opened this issue Jul 31, 2020 · 1 comment · Fixed by #52200
Assignees
@knz
Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
20.2

Comments

@cockroach-teamcity
Copy link
Member

(kv/kvserver/protectedts/ptstorage).TestCorruptData failed on master@2beea9ef5bd5dce2fb6be59a71e5673053316d6d:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 12188 [running]:
runtime/debug.Stack(0x4eabb00, 0xc001882a50, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:424 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x74fc3e0, 0x1, 0x1626c0f817d1311e, 0x2f9c, 0x6e736a2, 0x1b, 0x499, 0xc0000771a0, 0x23, 0xc003efc6e0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:246 +0xc9
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x4eabb00, 0xc001882a50, 0x1, 0x2, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:52 +0x1ac
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x4eabb00, 0xc001882a50, 0x1, 0xc000000001, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x8c
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:80
github.com/cockroachdb/cockroach/pkg/sqlmigrations.migrateSchemaChangeJobs(0x4eabb00, 0xc001882a50, 0x4eabd80, 0xc005c0e080, 0xc005ba31e0, 0xc005ba31e0, 0x0, 0xc002a81740, 0xc000eda000, 0xc000d05a40, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:1177 +0x525
github.com/cockroachdb/cockroach/pkg/sqlmigrations.(*Manager).StartSchemaChangeJobMigration.func1(0x4eabb00, 0xc005eb5110)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:775 +0x6e9
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc00334fb00, 0x4eabb00, 0xc005eb5110, 0xc001404090, 0x27, 0x0, 0x0, 0xc0005a7680)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:347 +0xee
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:342 +0x131
 [recovered]
	panic: logging already active; first use:
goroutine 12188 [running]:
runtime/debug.Stack(0x4eabb00, 0xc001882a50, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:424 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x74fc3e0, 0x1, 0x1626c0f817d1311e, 0x2f9c, 0x6e736a2, 0x1b, 0x499, 0xc0000771a0, 0x23, 0xc003efc6e0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:246 +0xc9
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x4eabb00, 0xc001882a50, 0x1, 0x2, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:52 +0x1ac
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x4eabb00, 0xc001882a50, 0x1, 0xc000000001, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x8c
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:80
github.com/cockroachdb/cockroach/pkg/sqlmigrations.migrateSchemaChangeJobs(0x4eabb00, 0xc001882a50, 0x4eabd80, 0xc005c0e080, 0xc005ba31e0, 0xc005ba31e0, 0x0, 0xc002a81740, 0xc000eda000, 0xc000d05a40, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:1177 +0x525
github.com/cockroachdb/cockroach/pkg/sqlmigrations.(*Manager).StartSchemaChangeJobMigration.func1(0x4eabb00, 0xc005eb5110)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:775 +0x6e9
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc00334fb00, 0x4eabb00, 0xc005eb5110, 0xc001404090, 0x27, 0x0, 0x0, 0xc0005a7680)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:347 +0xee
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:342 +0x131
 [recovered]
	panic: logging already active; first use:
goroutine 12188 [running]:
runtime/debug.Stack(0x4eabb00, 0xc001882a50, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:424 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x74fc3e0, 0x1, 0x1626c0f817d1311e, 0x2f9c, 0x6e736a2, 0x1b, 0x499, 0xc0000771a0, 0x23, 0xc003efc6e0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:246 +0xc9
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x4eabb00, 0xc001882a50, 0x1, 0x2, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:52 +0x1ac
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x4eabb00, 0xc001882a50, 0x1, 0xc000000001, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x8c
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:80
github.com/cockroachdb/cockroach/pkg/sqlmigrations.migrateSchemaChangeJobs(0x4eabb00, 0xc001882a50, 0x4eabd80, 0xc005c0e080, 0xc005ba31e0, 0xc005ba31e0, 0x0, 0xc002a81740, 0xc000eda000, 0xc000d05a40, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:1177 +0x525
github.com/cockroachdb/cockroach/pkg/sqlmigrations.(*Manager).StartSchemaChangeJobMigration.func1(0x4eabb00, 0xc005eb5110)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:775 +0x6e9
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc00334fb00, 0x4eabb00, 0xc005eb5110, 0xc001404090, 0x27, 0x0, 0x0, 0xc0005a7680)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:347 +0xee
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:342 +0x131
 [recovered]
	panic: logging already active; first use:
goroutine 12188 [running]:
runtime/debug.Stack(0x4eabb00, 0xc001882a50, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:424 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x74fc3e0, 0x1, 0x1626c0f817d1311e, 0x2f9c, 0x6e736a2, 0x1b, 0x499, 0xc0000771a0, 0x23, 0xc003efc6e0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:246 +0xc9
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x4eabb00, 0xc001882a50, 0x1, 0x2, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:52 +0x1ac
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x4eabb00, 0xc001882a50, 0x1, 0xc000000001, 0x43b7e13, 0x23, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x8c
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:80
github.com/cockroachdb/cockroach/pkg/sqlmigrations.migrateSchemaChangeJobs(0x4eabb00, 0xc001882a50, 0x4eabd80, 0xc005c0e080, 0xc005ba31e0, 0xc005ba31e0, 0x0, 0xc002a81740, 0xc000eda000, 0xc000d05a40, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:1177 +0x525
github.com/cockroachdb/cockroach/pkg/sqlmigrations.(*Manager).StartSchemaChangeJobMigration.func1(0x4eabb00, 0xc005eb5110)
	/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:775 +0x6e9
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc00334fb00, 0x4eabb00, 0xc005eb5110, 0xc001404090, 0x27, 0x0, 0x0, 0xc0005a7680)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:347 +0xee
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:342 +0x131
Log preceding fatal error

=== RUN   TestCorruptData
--- FAIL: TestCorruptData (0.12s)
=== RUN   TestCorruptData/corrupt_spans
I200731 06:01:29.618822 11341 rpc/tls.go:234  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I200731 06:01:29.618854 11341 rpc/tls.go:283  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W200731 06:01:29.618932 11341 server/status/runtime.go:310  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I200731 06:01:29.634719 11341 server/server.go:821  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I200731 06:01:29.635392 11341 server/config.go:617  [n?] 1 storage engine initialized
I200731 06:01:29.635439 11341 server/config.go:620  [n?] Pebble cache size: 128 MiB
I200731 06:01:29.635456 11341 server/config.go:620  [n?] store 0: in-memory, size 0 B
I200731 06:01:29.640072 11341 server/init.go:173  [n?] no stores bootstrapped and --join flag specified, awaiting init command or join with an already initialized node.
I200731 06:01:29.640108 11341 server/init.go:193  [n?] **** cluster bb43bc7a-dffa-4e6f-9cd4-44b0afd381d8 has been created
I200731 06:01:29.640151 11341 gossip/gossip.go:403  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:36951" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc1" > > ServerVersion:<major_val:20 minor_val:1 patch:0 unstable:13 > build_tag:"v20.2.0-alpha.1-1673-g2beea9ef5b" started_at:1596175289640145991 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:45665" > tenant_address:<network_field:"tcp" address_field:"127.0.0.1:45831" > 
I200731 06:01:29.640451 11490 server/server.go:1400  [n1] connecting to gossip network to verify cluster ID "bb43bc7a-dffa-4e6f-9cd4-44b0afd381d8"
I200731 06:01:29.642911 11490 server/server.go:1403  [n1] node connected via gossip
W200731 06:01:29.653454 11565 kv/kvserver/store.go:1664  [n1,s1,r6/1:/Table/{SystemCon…-11}] could not gossip system config: [NotLeaseHolderError] r6: replica (n1,s1):1 not lease holder; lease holder unknown
I200731 06:01:29.653556 11341 server/node.go:413  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=18 KiB), ranges=34, leases=0, queries=0.00, writes=0.00, bytesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=166.00 pMax=15791.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I200731 06:01:29.653692 11341 kv/kvserver/stores.go:236  [n1] read 0 node addresses from persistent storage
I200731 06:01:29.653745 11341 server/node.go:469  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I200731 06:01:29.653818 11341 server/server.go:1512  [n1] starting https server at 127.0.0.1:33501 (use: 127.0.0.1:33501)
I200731 06:01:29.653852 11341 server/server.go:1517  [n1] starting postgres server at 127.0.0.1:45665 (use: 127.0.0.1:45665)
I200731 06:01:29.653889 11341 server/server.go:1519  [n1] starting grpc server at 127.0.0.1:36951
I200731 06:01:29.653921 11341 server/server.go:1520  [n1] advertising CockroachDB node at 127.0.0.1:36951
I200731 06:01:29.659392 11594 sql/temporary_schema.go:483  [n1] running temporary object cleanup background job
I200731 06:01:29.660622 11620 kv/kvserver/replica_rangefeed.go:608  [n1,s1,r6/1:/Table/{SystemCon…-11}] RangeFeed closed timestamp is empty
I200731 06:01:29.661798 11594 sql/temporary_schema.go:518  [n1] found 0 temporary schemas
I200731 06:01:29.661837 11594 sql/temporary_schema.go:521  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200731 06:01:29.661856 11594 sql/temporary_schema.go:522  [n1] completed temporary object cleanup job
I200731 06:01:29.661871 11594 sql/temporary_schema.go:605  [n1] temporary object cleaner next scheduled to run at 2020-07-31 06:31:29.659359777 +0000 UTC
I200731 06:01:29.663519 11593 sql/event_log.go:136  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:36951 Attrs: Locality:region=test,dc=dc1 ServerVersion:20.1-13 BuildTag:v20.2.0-alpha.1-1673-g2beea9ef5b StartedAt:1596175289640145991 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:45665 TenantAddress:127.0.0.1:45831} ClusterID:bb43bc7a-dffa-4e6f-9cd4-44b0afd381d8 StartedAt:1596175289640145991 LastUp:1596175289640145991}
I200731 06:01:29.665891 11624 sql/event_log.go:136  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I200731 06:01:29.672714 11631 sql/event_log.go:136  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1-13 User:root}
I200731 06:01:29.683826 12101 sql/event_log.go:136  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:36267736-eb64-46f8-a4a6-3bfc3a191ab3 User:root}
I200731 06:01:29.691320 12108 sql/event_log.go:136  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200731 06:01:29.694363 12179 sql/event_log.go:136  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200731 06:01:29.708816 11341 server/server_sql.go:677  [n1] done ensuring all necessary migrations have run
I200731 06:01:29.708863 11341 server/server.go:1894  [n1] serving sql connections
I200731 06:01:29.709159 12188 sqlmigrations/migrations.go:727  [n1] starting wait for upgrade finalization before schema change job migration
I200731 06:01:29.709386 11341 testutils/testcluster/testcluster.go:758  WaitForFullReplication
I200731 06:01:29.709407 11341 testutils/testcluster/testcluster.go:762  WaitForFullReplication took: 361ns
I200731 06:01:29.709380 12188 sqlmigrations/migrations.go:759  [n1] starting schema change job migration
I200731 06:01:29.716312 11592 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200731 06:01:29.733427 12188 sqlmigrations/migrations.go:1177  [schema-change-job-migration] evaluating tables for creating jobs
I200731 06:01:29.733586 12188 sqlmigrations/migrations.go:779  [n1] schema change job migration completed
    --- FAIL: TestCorruptData/corrupt_spans (0.12s)

More

Parameters:

  • TAGS=
  • GOFLAGS=-parallel=4
make stressrace TESTS=TestCorruptData PKG=./pkg/kv/kvserver/protectedts/ptstorage TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues
@cockroach-teamcity cockroach-teamcity added branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Jul 31, 2020
@cockroach-teamcity cockroach-teamcity added this to the 20.2 milestone Jul 31, 2020
@knz knz mentioned this issue Aug 3, 2020
Merged
@knz
Copy link
Contributor

knz commented Aug 4, 2020

I'm on this

@knz knz assigned knz and unassigned ajwerner Aug 4, 2020
@craig craig bot closed this as completed in 62b11e1 Aug 6, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@knz knz

Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
20.2
Development

Successfully merging a pull request may close this issue.

util/log: improvements, simplifications and bug fixes knz/cockroach
3 participants
@knz @ajwerner @cockroach-teamcity