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.

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

Unit_race failure #5489

Closed
morgo opened this issue Nov 29, 2019 · 0 comments · Fixed by #5490
Closed

Unit_race failure #5489

morgo opened this issue Nov 29, 2019 · 0 comments · Fixed by #5490

Comments

@morgo
Copy link
Contributor

morgo commented Nov 29, 2019

Discovered in #5488 : It looks like unit_race is failing, but the script that wraps around it is marking tests as passed:

2019-11-29T03:22:18.0647276Z ok  	vitess.io/vitess/go/vt/workflow	1.110s
2019-11-29T03:22:18.0649339Z ok  	vitess.io/vitess/go/vt/workflow/resharding	1.117s
2019-11-29T03:22:18.0651162Z ok  	vitess.io/vitess/go/vt/workflow/reshardingworkflowgen	1.081s
2019-11-29T03:22:18.0652643Z ok  	vitess.io/vitess/go/vt/workflow/topovalidator	1.032s
2019-11-29T03:22:26.7219914Z E1129 03:22:17.906325   18557 migrater.go:158] validate failed: missing tablet type specific routing, read-only traffic must be migrated before migrating writes: t1
2019-11-29T03:22:26.7220563Z E1129 03:22:17.946569   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7221514Z E1129 03:22:17.947081   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7221770Z E1129 03:22:17.955954   18557 migrater.go:209] waitForCatchup failed: Code: UNKNOWN
2019-11-29T03:22:26.7222222Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7222865Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7223216Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7223677Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7223845Z E1129 03:22:18.012876   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7224022Z E1129 03:22:18.015171   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7224812Z W1129 03:22:18.151055   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/-80
2019-11-29T03:22:26.7225286Z W1129 03:22:18.151159   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/80-
2019-11-29T03:22:26.7225835Z E1129 03:22:18.421051   18557 migrater.go:158] validate failed: cannot migrate MASTER away from ks/-40 until everything else is migrated. Make sure that the following types are migrated first: RDONLY
2019-11-29T03:22:26.7226035Z E1129 03:22:18.536418   18557 migrater.go:209] waitForCatchup failed: Code: UNKNOWN
2019-11-29T03:22:26.7226250Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7226451Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7226648Z rpc error: code = DeadlineExceeded desc = context deadline exceeded
2019-11-29T03:22:26.7226946Z E1129 03:22:18.886163   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7228127Z W1129 03:22:18.952289   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/-80
2019-11-29T03:22:26.7228573Z W1129 03:22:18.952652   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/80-
2019-11-29T03:22:26.7228745Z E1129 03:22:19.058814   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7228910Z E1129 03:22:19.061031   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7229083Z W1129 03:22:19.126972   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/0
2019-11-29T03:22:26.7229383Z E1129 03:22:19.233707   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7229538Z E1129 03:22:19.235385   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7230838Z W1129 03:22:19.361830   18557 rpc_server.go:91] TabletManager.VReplicationExec(query:"insert into _vt.resharding_journal (id, db_name, val) values (7672494164556733923, 'vt_ks1', 'id:7672494164556733923 tables:\\\"t1\\\" tables:\\\"t2\\\" local_position:\\\"MariaDB/5-456-892\\\" shard_gtids:<keyspace:\\\"ks2\\\" shard:\\\"-80\\\" gtid:\\\"MariaDB/5-456-893\\\" > shard_gtids:<keyspace:\\\"ks2\\\" shard:\\\"80-\\\" gtid:\\\"MariaDB/5-456-893\\\" > participants:<keyspace:\\\"ks1\\\" shard:\\\"-40\\\" > participants:<keyspace:\\\"ks1\\\" shard:\\\"40-\\\" > ')" )(on cell1-0000000020 from ) error: journaling intentionally failed
2019-11-29T03:22:26.7232410Z W1129 03:22:19.366576   18557 rpc_server.go:91] TabletManager.VReplicationExec(query:"insert into _vt.resharding_journal (id, db_name, val) values (7672494164556733923, 'vt_ks1', 'id:7672494164556733923 tables:\\\"t1\\\" tables:\\\"t2\\\" local_position:\\\"MariaDB/5-456-892\\\" shard_gtids:<keyspace:\\\"ks2\\\" shard:\\\"-80\\\" gtid:\\\"MariaDB/5-456-893\\\" > shard_gtids:<keyspace:\\\"ks2\\\" shard:\\\"80-\\\" gtid:\\\"MariaDB/5-456-893\\\" > participants:<keyspace:\\\"ks1\\\" shard:\\\"-40\\\" > participants:<keyspace:\\\"ks1\\\" shard:\\\"40-\\\" > ')" )(on cell1-0000000010 from ) error: journaling intentionally failed
2019-11-29T03:22:26.7232706Z E1129 03:22:19.367639   18557 migrater.go:239] createJournals failed: Code: UNKNOWN
2019-11-29T03:22:26.7235439Z rpc error: code = Unknown desc = TabletManager.VReplicationExec on cell1-0000000010 error: journaling intentionally failed: journaling intentionally failed
2019-11-29T03:22:26.7236038Z rpc error: code = Unknown desc = TabletManager.VReplicationExec on cell1-0000000020 error: journaling intentionally failed: journaling intentionally failed
2019-11-29T03:22:26.7236699Z W1129 03:22:19.522693   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/80-
2019-11-29T03:22:26.7237144Z W1129 03:22:19.523876   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/-80
2019-11-29T03:22:26.7237572Z W1129 03:22:19.881769   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks1/-40
2019-11-29T03:22:26.7237993Z W1129 03:22:19.882288   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks1/40-
2019-11-29T03:22:26.7238137Z E1129 03:22:20.026354   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7238298Z E1129 03:22:20.027778   18557 state_change.go:290] Cannot update blacklisted tables rule: no schema defined
2019-11-29T03:22:26.7238717Z W1129 03:22:20.169781   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/-80
2019-11-29T03:22:26.7239137Z W1129 03:22:20.170902   18557 shard.go:407] Trying to remove TabletControl.BlacklistedTables for missing type MASTER in shard ks2/80-
2019-11-29T03:22:26.7239478Z E1129 03:22:20.395493   18557 migrater.go:107] buildMigrater failed: no streams found in keyspace ks2 for: test
2019-11-29T03:22:26.7239622Z E1129 03:22:20.463551   18557 migrater.go:107] buildMigrater failed: source keyspaces are mismatched across streams: ks2 vs ks1
2019-11-29T03:22:26.7239791Z E1129 03:22:20.526672   18557 migrater.go:107] buildMigrater failed: table lists are mismatched across streams: [t1] vs [t1 t2]
2019-11-29T03:22:26.7240276Z E1129 03:22:20.599254   18557 migrater.go:114] validate failed: mismatched shards for keyspace ks2: topo: [-80 80-] vs migrate command: [80-]
2019-11-29T03:22:26.7240453Z E1129 03:22:20.654210   18557 migrater.go:114] validate failed: cannot migrate streams with wild card table names: /.*
2019-11-29T03:22:26.7240608Z E1129 03:22:23.216578   18557 migrater.go:199] stopStreams failed: Code: UNKNOWN
2019-11-29T03:22:26.7241231Z ks1:-40: stream 1 position: MariaDB/5-456-887 does not match MariaDB/5-456-888
2019-11-29T03:22:26.7241661Z ks1:40-: stream 2 position: MariaDB/5-456-887 does not match MariaDB/5-456-888
2019-11-29T03:22:26.7242193Z W1129 03:22:23.395103   18557 rpc_server.go:91] TabletManager.VReplicationExec(query:"update _vt.vreplication set state='Stopped', message='for cutover' where id in (1, 2)" )(on cell1-0000000010 from ) error: intentionally failed
2019-11-29T03:22:26.7242731Z W1129 03:22:23.395903   18557 rpc_server.go:91] TabletManager.VReplicationExec(query:"update _vt.vreplication set state='Stopped', message='for cutover' where id in (1, 2)" )(on cell1-0000000020 from ) error: intentionally failed
2019-11-29T03:22:26.7243093Z E1129 03:22:23.397517   18557 migrater.go:199] stopStreams failed: Code: UNKNOWN
2019-11-29T03:22:26.7244197Z rpc error: code = Unknown desc = TabletManager.VReplicationExec on cell1-0000000010 error: intentionally failed: intentionally failed
2019-11-29T03:22:26.7244706Z rpc error: code = Unknown desc = TabletManager.VReplicationExec on cell1-0000000020 error: intentionally failed: intentionally failed
2019-11-29T03:22:26.7244872Z E1129 03:22:23.541971   18557 migrater.go:189] buildStreamMigrater failed: Code: UNKNOWN
2019-11-29T03:22:26.7245197Z cannot migrate until all streams are running: 0
2019-11-29T03:22:26.7245363Z E1129 03:22:23.846622   18557 migrater.go:189] buildStreamMigrater failed: Code: UNKNOWN
2019-11-29T03:22:26.7245608Z cannot migrate while vreplication streams in source shards are still copying: 0
2019-11-29T03:22:26.7245769Z E1129 03:22:23.953423   18557 migrater.go:189] buildStreamMigrater failed: Code: UNKNOWN
2019-11-29T03:22:26.7245980Z VReplication streams must have named workflows for migration: shard: ks:0, stream: 1
2019-11-29T03:22:26.7246239Z E1129 03:22:24.056668   18557 migrater.go:189] buildStreamMigrater failed: Code: UNKNOWN
2019-11-29T03:22:26.7246521Z VReplication stream has the same workflow name as the resharding workflow: shard: ks:0, stream: 1
2019-11-29T03:22:26.7247042Z E1129 03:22:24.172156   18557 migrater.go:189] buildStreamMigrater failed: streams are mismatched across source shards: 80- vs -80
2019-11-29T03:22:26.7247233Z Summary for t1: {ProcessedRows:3 MatchingRows:3 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7247448Z E1129 03:22:24.401158   18557 vdiff.go:732] Draining extra row(s) found on the target starting with: [INT64(2) INT64(4)]
2019-11-29T03:22:26.7247635Z Summary for t1: {ProcessedRows:3 MatchingRows:1 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:2}
2019-11-29T03:22:26.7247952Z E1129 03:22:24.507175   18557 vdiff.go:744] Draining extra row(s) found on the source starting with: [INT64(2) INT64(4)]
2019-11-29T03:22:26.7248129Z Summary for t1: {ProcessedRows:3 MatchingRows:1 MismatchedRows:0 ExtraRowsSource:2 ExtraRowsTarget:0}
2019-11-29T03:22:26.7248272Z E1129 03:22:24.613153   18557 vdiff.go:763] [table=t1] Extra row 0 on source: [INT64(2) INT64(4)]
2019-11-29T03:22:26.7248514Z Summary for t1: {ProcessedRows:3 MatchingRows:2 MismatchedRows:0 ExtraRowsSource:1 ExtraRowsTarget:0}
2019-11-29T03:22:26.7248824Z E1129 03:22:24.718741   18557 vdiff.go:770] [table=t1] Extra row 0 on target: [INT64(2) INT64(4)]
2019-11-29T03:22:26.7249002Z Summary for t1: {ProcessedRows:3 MatchingRows:2 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:1}
2019-11-29T03:22:26.7255711Z E1129 03:22:24.824436   18557 vdiff.go:785] [table=t1] Different content 0 in same PK: [INT64(2) INT64(3)] != [INT64(2) INT64(4)]
2019-11-29T03:22:26.7255953Z Summary for t1: {ProcessedRows:3 MatchingRows:2 MismatchedRows:1 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7256141Z Summary for t1: {ProcessedRows:3 MatchingRows:3 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7256324Z Summary for t1: {ProcessedRows:5 MatchingRows:5 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7256664Z Summary for t1: {ProcessedRows:4 MatchingRows:4 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7256840Z Summary for t1: {ProcessedRows:4 MatchingRows:4 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7257016Z Summary for t1: {ProcessedRows:3 MatchingRows:3 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7257189Z Summary for t1: {ProcessedRows:3 MatchingRows:3 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7257362Z Summary for t1: {ProcessedRows:3 MatchingRows:3 MismatchedRows:0 ExtraRowsSource:0 ExtraRowsTarget:0}
2019-11-29T03:22:26.7257491Z PASS
2019-11-29T03:22:26.7257605Z ==================
2019-11-29T03:22:26.7257904Z WARNING: DATA RACE
2019-11-29T03:22:26.7258058Z Read at 0x00c000984fc0 by goroutine 188:
2019-11-29T03:22:26.7258203Z   runtime.mapaccess1_fast64()
2019-11-29T03:22:26.7258389Z       /opt/hostedtoolcache/go/1.12.13/x64/src/runtime/map_fast64.go:12 +0x0
2019-11-29T03:22:26.7258565Z   vitess.io/vitess/go/vt/wrangler.init.1.func1()
2019-11-29T03:22:26.7258776Z       /home/runner/work/vitess/vitess/go/vt/wrangler/vdiff_env_test.go:66 +0xba
2019-11-29T03:22:26.7258977Z   vitess.io/vitess/go/vt/discovery.(*healthCheckConn).stream()
2019-11-29T03:22:26.7259317Z       /home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:614 +0x3e3
2019-11-29T03:22:26.7259538Z   vitess.io/vitess/go/vt/discovery.(*HealthCheckImpl).checkConn()
2019-11-29T03:22:26.7259754Z       /home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:545 +0x471
2019-11-29T03:22:26.7259824Z 
2019-11-29T03:22:26.7259992Z Previous write at 0x00c000984fc0 by goroutine 534:
2019-11-29T03:22:26.7260138Z   runtime.mapdelete_fast64()
2019-11-29T03:22:26.7260342Z       /opt/hostedtoolcache/go/1.12.13/x64/src/runtime/map_fast64.go:272 +0x0
2019-11-29T03:22:26.7260515Z   vitess.io/vitess/go/vt/wrangler.(*testVDiffEnv).close()
2019-11-29T03:22:26.7260728Z       /home/runner/work/vitess/vitess/go/vt/wrangler/vdiff_env_test.go:203 +0x200
2019-11-29T03:22:26.7260925Z   vitess.io/vitess/go/vt/wrangler.TestVDiffReplicationWait()
2019-11-29T03:22:26.7261134Z       /home/runner/work/vitess/vitess/go/vt/wrangler/vdiff_test.go:889 +0x94d
2019-11-29T03:22:26.7261280Z   testing.tRunner()
2019-11-29T03:22:26.7261463Z       /opt/hostedtoolcache/go/1.12.13/x64/src/testing/testing.go:865 +0x163
2019-11-29T03:22:26.7261545Z 
2019-11-29T03:22:26.7261674Z Goroutine 188 (running) created at:
2019-11-29T03:22:26.7261865Z   vitess.io/vitess/go/vt/discovery.(*HealthCheckImpl).AddTablet()
2019-11-29T03:22:26.7262260Z       /home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:768 +0x597
2019-11-29T03:22:26.7263691Z   vitess.io/vitess/go/vt/discovery.(*TopologyWatcher).loadTablets()
2019-11-29T03:22:26.7263925Z       /home/runner/work/vitess/vitess/go/vt/discovery/topology_watcher.go:259 +0xd88
2019-11-29T03:22:26.7264137Z   vitess.io/vitess/go/vt/discovery.(*TopologyWatcher).watch()
2019-11-29T03:22:26.7264371Z       /home/runner/work/vitess/vitess/go/vt/discovery/topology_watcher.go:168 +0xdc
2019-11-29T03:22:26.7264444Z 
2019-11-29T03:22:26.7264601Z Goroutine 534 (finished) created at:
2019-11-29T03:22:26.7265648Z   testing.(*T).Run()
2019-11-29T03:22:26.7265873Z       /opt/hostedtoolcache/go/1.12.13/x64/src/testing/testing.go:916 +0x65a
2019-11-29T03:22:26.7266039Z   testing.runTests.func1()
2019-11-29T03:22:26.7266239Z       /opt/hostedtoolcache/go/1.12.13/x64/src/testing/testing.go:1157 +0xa8
2019-11-29T03:22:26.7266387Z   testing.tRunner()
2019-11-29T03:22:26.7266594Z       /opt/hostedtoolcache/go/1.12.13/x64/src/testing/testing.go:865 +0x163
2019-11-29T03:22:26.7266741Z   testing.runTests()
2019-11-29T03:22:26.7266937Z       /opt/hostedtoolcache/go/1.12.13/x64/src/testing/testing.go:1155 +0x523
2019-11-29T03:22:26.7267082Z   testing.(*M).Run()
2019-11-29T03:22:26.7267294Z       /opt/hostedtoolcache/go/1.12.13/x64/src/testing/testing.go:1072 +0x2eb
2019-11-29T03:22:26.7267432Z   main.main()
2019-11-29T03:22:26.7267560Z       _testmain.go:122 +0x222
2019-11-29T03:22:26.7267697Z ==================
2019-11-29T03:22:26.7267839Z panic: runtime error: invalid memory address or nil pointer dereference
2019-11-29T03:22:26.7267999Z 	panic: runtime error: invalid memory address or nil pointer dereference
2019-11-29T03:22:26.7268183Z [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x123a246]
2019-11-29T03:22:26.7268270Z 
2019-11-29T03:22:26.7268395Z goroutine 8051 [running]:
2019-11-29T03:22:26.7268670Z vitess.io/vitess/go/vt/wrangler.(*testVDiffTablet).Close(0x0, 0x16d9940, 0xc000b11ec0, 0x16d9940, 0xc000b11ec0)
2019-11-29T03:22:26.7268831Z 	<autogenerated>:1 +0x46
2019-11-29T03:22:26.7269075Z vitess.io/vitess/go/vt/discovery.(*HealthCheckImpl).finalizeConn(0xc0006865a0, 0xc000484500)
2019-11-29T03:22:26.7269459Z 	/home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:500 +0x283
2019-11-29T03:22:26.7269595Z panic(0x1355be0, 0x20f3d90)
2019-11-29T03:22:26.7269791Z 	/opt/hostedtoolcache/go/1.12.13/x64/src/runtime/panic.go:522 +0x1b5
2019-11-29T03:22:26.7270072Z vitess.io/vitess/go/vt/wrangler.(*testVDiffTablet).StreamHealth(0x0, 0x16d98c0, 0xc0008f1540, 0xc0009dc9c0, 0x0, 0x0)
2019-11-29T03:22:26.7270304Z 	/home/runner/work/vitess/vitess/go/vt/wrangler/vdiff_env_test.go:227 +0x10d
2019-11-29T03:22:26.7270705Z vitess.io/vitess/go/vt/discovery.(*healthCheckConn).stream(0xc000484500, 0x16d98c0, 0xc0008f1540, 0xc0006865a0, 0xc0009dc9c0)
2019-11-29T03:22:26.7270950Z 	/home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:623 +0xc7
2019-11-29T03:22:26.7271223Z vitess.io/vitess/go/vt/discovery.(*HealthCheckImpl).checkConn(0xc0006865a0, 0xc000484500, 0xc0006b2340, 0x10)
2019-11-29T03:22:26.7271438Z 	/home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:545 +0x472
2019-11-29T03:22:26.7271651Z created by vitess.io/vitess/go/vt/discovery.(*HealthCheckImpl).AddTablet
2019-11-29T03:22:26.7271848Z 	/home/runner/work/vitess/vitess/go/vt/discovery/healthcheck.go:768 +0x598
2019-11-29T03:22:26.7272022Z FAIL	vitess.io/vitess/go/vt/wrangler	8.984s
2019-11-29T03:22:35.7720265Z ok  	vitess.io/vitess/go/vt/wrangler/testlib	12.998s
2019-11-29T03:22:35.7721152Z ok  	vitess.io/vitess/go/vt/zkctl	5.181s
2019-11-29T03:22:35.8533303Z 
2019-11-29T03:22:35.8534144Z SUCCESS: No data race was found.
2019-11-29T03:22:35.8576832Z Cleaning up orphan processes
sougou added a commit to planetscale/vitess that referenced this issue Dec 1, 2019
Fixes vitessio#5489

Signed-off-by: Sugu Sougoumarane <ssougou@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant