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

Unstable test: TestAuthPlugin2 #30266

Closed
djshow832 opened this issue Nov 30, 2021 · 6 comments · Fixed by #30287
Closed

Unstable test: TestAuthPlugin2 #30266

djshow832 opened this issue Nov 30, 2021 · 6 comments · Fixed by #30287
Assignees
@dveeden
Labels
affects-5.3 This bug affects 5.3.x versions. component/test severity/major sig/sql-infra SIG: SQL Infra type/bug The issue is confirmed as a bug.

Comments

@djshow832
Copy link
Contributor 

[2021-11-30T04:23:30.650Z] --- FAIL: TestAuthPlugin2 (1.20s)
[2021-11-30T04:23:30.650Z]     conn_test.go:1161: 
[2021-11-30T04:23:30.650Z]         	Error Trace:	conn_test.go:1161
[2021-11-30T04:23:30.650Z]         	Error:      	Not equal: 
[2021-11-30T04:23:30.650Z]         	            	expected: []byte{0x63, 0x61, 0x63, 0x68, 0x69, 0x6e, 0x67, 0x5f, 0x73, 0x68, 0x61, 0x32, 0x5f, 0x70, 0x61, 0x73, 0x73, 0x77, 0x6f, 0x72, 0x64}
[2021-11-30T04:23:30.650Z]         	            	actual  : []byte{0x6d, 0x79, 0x73, 0x71, 0x6c, 0x5f, 0x6e, 0x61, 0x74, 0x69, 0x76, 0x65, 0x5f, 0x70, 0x61, 0x73, 0x73, 0x77, 0x6f, 0x72, 0x64}
[2021-11-30T04:23:30.650Z]         	            	
[2021-11-30T04:23:30.650Z]         	            	Diff:
[2021-11-30T04:23:30.650Z]         	            	--- Expected
[2021-11-30T04:23:30.650Z]         	            	+++ Actual
[2021-11-30T04:23:30.650Z]         	            	@@ -1,3 +1,3 @@
[2021-11-30T04:23:30.650Z]         	            	 ([]uint8) (len=21) {
[2021-11-30T04:23:30.650Z]         	            	- 00000000  63 61 63 68 69 6e 67 5f  73 68 61 32 5f 70 61 73  |caching_sha2_pas|
[2021-11-30T04:23:30.650Z]         	            	+ 00000000  6d 79 73 71 6c 5f 6e 61  74 69 76 65 5f 70 61 73  |mysql_native_pas|
[2021-11-30T04:23:30.650Z]         	            	  00000010  73 77 6f 72 64                                    |sword|
[2021-11-30T04:23:30.650Z]         	Test:       	TestAuthPlugin2
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [telemetry.go:174] ["Telemetry configuration"] [endpoint=https://telemetry.pingcap.com/api/v1/tidb/report] [report_interval=6h0m0s] [enabled=true]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [telemetry.go:174] ["Telemetry configuration"] [endpoint=https://telemetry.pingcap.com/api/v1/tidb/report] [report_interval=6h0m0s] [enabled=true]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.390 +08:00] [INFO] [ddl_worker.go:313] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:58, Type:create table, State:none, SchemaState:queueing, SchemaID:1, TableID:57, RowCount:0, ArgLen:1, start time: 2021-11-30 12:19:51.389 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2021-11-30T04:23:30.650Z] [2021/11/30 12:19:51.391 +08:00] [INFO] [ddl.go:553] ["[ddl] start DDL job"] [job="ID:58, Type:create table, State:none, SchemaState:queueing, SchemaID:1, TableID:57, RowCount:0, ArgLen:1, start time: 2021-11-30 12:19:51.389 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE `test` (`iD` bigint(20) NOT NULL, `INT_TEST` int(11) DEFAULT NULL);"]
[2021-11-30T04:23:30.650Z] --- FAIL: TestHandleAuthPlugin (1.20s)
[2021-11-30T04:23:30.650Z] panic: runtime error: invalid memory address or nil pointer dereference [recovered]
[2021-11-30T04:23:30.650Z] 	panic: runtime error: invalid memory address or nil pointer dereference
[2021-11-30T04:23:30.650Z] [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x37116bf]
[2021-11-30T04:23:30.650Z] 
[2021-11-30T04:23:30.650Z] goroutine 504 [running]:
[2021-11-30T04:23:30.650Z] testing.tRunner.func1.2(0x3a557c0, 0x5c03590)
[2021-11-30T04:23:30.650Z] 	/usr/local/go/src/testing/testing.go:1143 +0x332
[2021-11-30T04:23:30.650Z] testing.tRunner.func1(0xc000603980)
[2021-11-30T04:23:30.650Z] 	/usr/local/go/src/testing/testing.go:1146 +0x4b6
[2021-11-30T04:23:30.650Z] panic(0x3a557c0, 0x5c03590)
[2021-11-30T04:23:30.650Z] 	/usr/local/go/src/runtime/panic.go:965 +0x1b9
[2021-11-30T04:23:30.650Z] github.com/pingcap/tidb/server.(*packetIO).readPacket(0xc1200934c0, 0x44366a0, 0xc0000520a8, 0x0, 0x0, 0x0)
[2021-11-30T04:23:30.650Z] 	/home/jenkins/agent/workspace/tidb_ghpr_check_2/go/src/github.com/pingcap/tidb/server/packetio.go:113 +0x37f
[2021-11-30T04:23:30.650Z] github.com/pingcap/tidb/server.(*clientConn).readPacket(...)
[2021-11-30T04:23:30.650Z] 	/home/jenkins/agent/workspace/tidb_ghpr_check_2/go/src/github.com/pingcap/tidb/server/conn.go:394
[2021-11-30T04:23:30.650Z] github.com/pingcap/tidb/server.(*clientConn).authSwitchRequest(0xc01162f6e0, 0x44366a0, 0xc0000520a8, 0xc11f3c51b9, 0x15, 0x2, 0x8, 0xc120a6b470, 0x27, 0xc01162f008)
[2021-11-30T04:23:30.650Z] 	/home/jenkins/agent/workspace/tidb_ghpr_check_2/go/src/github.com/pingcap/tidb/server/conn.go:236 +0x806
[2021-11-30T04:23:30.650Z] github.com/pingcap/tidb/server.(*clientConn).checkAuthPlugin(0xc01162f6e0, 0x44366a0, 0xc0000520a8, 0xc01162f418, 0x7f950c6f5db8, 0x7f950c6f5db8, 0x1000, 0x1, 0xc01162f148)
[2021-11-30T04:23:30.650Z] 	/home/jenkins/agent/workspace/tidb_ghpr_check_2/go/src/github.com/pingcap/tidb/server/conn.go:902 +0x726
[2021-11-30T04:23:30.650Z] github.com/pingcap/tidb/server.(*clientConn).handleAuthPlugin(0xc01162f6e0, 0x44366a0, 0xc0000520a8, 0xc01162f418, 0x0, 0x0)
[2021-11-30T04:23:30.650Z] 	/home/jenkins/agent/workspace/tidb_ghpr_check_2/go/src/github.com/pingcap/tidb/server/conn.go:715 +0x8c
[2021-11-30T04:23:30.650Z] github.com/pingcap/tidb/server.TestHandleAuthPlugin(0xc000603980)
[2021-11-30T04:23:30.650Z] 	/home/jenkins/agent/workspace/tidb_ghpr_check_2/go/src/github.com/pingcap/tidb/server/conn_test.go:1072 +0x1ef2
[2021-11-30T04:23:30.650Z] testing.tRunner(0xc000603980, 0x3fe78c8)
[2021-11-30T04:23:30.650Z] 	/usr/local/go/src/testing/testing.go:1193 +0xef
[2021-11-30T04:23:30.650Z] created by testing.(*T).Run
[2021-11-30T04:23:30.650Z] 	/usr/local/go/src/testing/testing.go:1238 +0x2b3
[2021-11-30T04:23:30.650Z] FAIL	github.com/pingcap/tidb/server	25.665s

https://ci.pingcap.net/blue/organizations/jenkins/tidb_ghpr_check_2/detail/tidb_ghpr_check_2/49084/pipeline

This is caused by #29738
@djshow832 djshow832 added type/bug The issue is confirmed as a bug. sig/sql-infra SIG: SQL Infra severity/major labels Nov 30, 2021
@djshow832 djshow832 mentioned this issue Nov 30, 2021
Merged
12 tasks
@dveeden
Copy link
Contributor

dveeden commented Nov 30, 2021

Looks stable:

[dvaneeden@dve-carbon server]$ for i in {1..10}; do echo -en "$(date): "; go test -v -run TestHandleAuthPlugin | grep -E '^--- (FAIL|PASS)'; done
Tue 30 Nov 13:23:15 CET 2021: --- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:23:19 CET 2021: --- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:23:23 CET 2021: --- PASS: TestHandleAuthPlugin (0.16s)
Tue 30 Nov 13:23:27 CET 2021: --- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:23:32 CET 2021: --- PASS: TestHandleAuthPlugin (0.18s)
Tue 30 Nov 13:23:36 CET 2021: --- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:23:40 CET 2021: --- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:23:44 CET 2021: --- PASS: TestHandleAuthPlugin (0.18s)
Tue 30 Nov 13:23:48 CET 2021: --- PASS: TestHandleAuthPlugin (0.18s)
Tue 30 Nov 13:23:52 CET 2021: --- PASS: TestHandleAuthPlugin (0.15s)
[dvaneeden@dve-carbon server]$ git rev-parse HEAD
13d0deb7fef7fd7391dce19f320abef4256223bd

@dveeden
Copy link
Contributor

dveeden commented Nov 30, 2021

This seems true for both tests:

[dvaneeden@dve-carbon server]$ for i in {1..10}; do date; go test -v -run '(TestHandleAuthPlugin|TestAuthPlugin2)' | grep -E '^--- (FAIL|PASS)'; done
Tue 30 Nov 13:27:32 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.17s)
Tue 30 Nov 13:27:36 CET 2021
--- PASS: TestAuthPlugin2 (0.16s)
--- PASS: TestHandleAuthPlugin (0.18s)
Tue 30 Nov 13:27:40 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.16s)
Tue 30 Nov 13:27:44 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.17s)
Tue 30 Nov 13:27:48 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.16s)
Tue 30 Nov 13:27:52 CET 2021
--- PASS: TestAuthPlugin2 (0.16s)
--- PASS: TestHandleAuthPlugin (0.19s)
Tue 30 Nov 13:27:56 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.17s)
Tue 30 Nov 13:28:00 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.17s)
Tue 30 Nov 13:28:04 CET 2021
--- PASS: TestAuthPlugin2 (0.16s)
--- PASS: TestHandleAuthPlugin (0.18s)
Tue 30 Nov 13:28:09 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.17s)

@dveeden
Copy link
Contributor

dveeden commented Nov 30, 2021

The PR referenced in the log seems to have this test fail:

[dvaneeden@dve-carbon tidb]$ make failpoint-enable 
[dvaneeden@dve-carbon tidb]$ cd server
[dvaneeden@dve-carbon server]$ git rev-parse HEAD
ddcbb7a458be17c7bf11c1ca70675c12a4036689
[dvaneeden@dve-carbon server]$ for i in {1..10}; do date; go test -v -run '(TestHandleAuthPlugin|TestAuthPlugin2)' | grep -E '^--- (FAIL|PASS)'; done
Tue 30 Nov 13:30:18 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:30:44 CET 2021
--- PASS: TestAuthPlugin2 (0.16s)
--- PASS: TestHandleAuthPlugin (0.16s)
Tue 30 Nov 13:30:48 CET 2021
--- PASS: TestAuthPlugin2 (0.16s)
--- PASS: TestHandleAuthPlugin (0.16s)
Tue 30 Nov 13:30:52 CET 2021
--- FAIL: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:30:56 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:31:01 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- FAIL: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:31:05 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:31:09 CET 2021
--- PASS: TestAuthPlugin2 (0.15s)
--- PASS: TestHandleAuthPlugin (0.15s)
Tue 30 Nov 13:31:13 CET 2021
--- PASS: TestHandleAuthPlugin (0.15s)
--- PASS: TestAuthPlugin2 (0.15s)
Tue 30 Nov 13:31:17 CET 2021
--- FAIL: TestHandleAuthPlugin (0.16s)
--- PASS: TestAuthPlugin2 (0.16s)

I think I might have found what's causing this

@dveeden dveeden mentioned this issue Nov 30, 2021
Merged
12 tasks
@aytrack
Copy link
Contributor

aytrack commented Dec 2, 2021

encountered this again in ci: https://ci.pingcap.net/blue/organizations/jenkins/tidb_ghpr_coverage/detail/tidb_ghpr_coverage/1430/pipeline

2021-12-01T12:46:59.259Z] --- FAIL: TestHandleAuthPlugin (2.39s)

[2021-12-01T12:46:59.259Z] [2021/12/01 20:42:22.561 +08:00] [INFO] [ddl_worker.go:313] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:4, Type:create schema, State:none, SchemaState:queueing, SchemaID:3, TableID:0, RowCount:0, ArgLen:1, start time: 2021-12-01 20:42:22.556 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]

[2021-12-01T12:46:59.259Z] [2021/12/01 20:42:22.561 +08:00] [INFO] [ddl_worker.go:313] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:60, Type:create table, State:none, SchemaState:queueing, SchemaID:57, TableID:59, RowCount:0, ArgLen:1, start time: 2021-12-01 20:42:22.555 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]

[2021-12-01T12:46:59.259Z] panic: runtime error: invalid memory address or nil pointer dereference [recovered]

[2021-12-01T12:46:59.259Z] 	panic: runtime error: invalid memory address or nil pointer dereference

[2021-12-01T12:46:59.259Z] [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x3715f5f]

[2021-12-01T12:46:59.259Z] 

[2021-12-01T12:46:59.259Z] goroutine 474 [running]:

[2021-12-01T12:46:59.259Z] testing.tRunner.func1.2(0x3a5bc40, 0x5c0d590)

[2021-12-01T12:46:59.259Z] 	/usr/local/go/src/testing/testing.go:1143 +0x332

[2021-12-01T12:46:59.259Z] testing.tRunner.func1(0xc000dd8000)

[2021-12-01T12:46:59.259Z] 	/usr/local/go/src/testing/testing.go:1146 +0x4b6

[2021-12-01T12:46:59.259Z] panic(0x3a5bc40, 0x5c0d590)

[2021-12-01T12:46:59.259Z] 	/usr/local/go/src/runtime/panic.go:965 +0x1b9

[2021-12-01T12:46:59.259Z] github.com/pingcap/tidb/server.(*packetIO).readPacket(0xc12b56b340, 0x443dfa0, 0xc000124010, 0x0, 0x0, 0x0)

[2021-12-01T12:46:59.259Z] 	/home/jenkins/agent/workspace/tidb_ghpr_coverage/go/src/github.com/pingcap/tidb/server/packetio.go:113 +0x37f

[2021-12-01T12:46:59.259Z] github.com/pingcap/tidb/server.(*clientConn).readPacket(...)

[2021-12-01T12:46:59.259Z] 	/home/jenkins/agent/workspace/tidb_ghpr_coverage/go/src/github.com/pingcap/tidb/server/conn.go:394

[2021-12-01T12:46:59.259Z] github.com/pingcap/tidb/server.(*clientConn).authSwitchRequest(0xc020c43a78, 0x443dfa0, 0xc000124010, 0xc12e617561, 0x15, 0x0, 0x8, 0xc12b5594d0, 0x27, 0xc03d8f44e0)

[2021-12-01T12:46:59.259Z] 	/home/jenkins/agent/workspace/tidb_ghpr_coverage/go/src/github.com/pingcap/tidb/server/conn.go:236 +0x806

[2021-12-01T12:46:59.259Z] github.com/pingcap/tidb/server.(*clientConn).checkAuthPlugin(0xc020c43a78, 0x443dfa0, 0xc000124010, 0xc020c43408, 0x30, 0x12fc4bc, 0xc020c43100, 0x132aec0, 0xc02970aa80)

[2021-12-01T12:46:59.259Z] 	/home/jenkins/agent/workspace/tidb_ghpr_coverage/go/src/github.com/pingcap/tidb/server/conn.go:911 +0xa3c

[2021-12-01T12:46:59.259Z] github.com/pingcap/tidb/server.(*clientConn).handleAuthPlugin(0xc020c43a78, 0x443dfa0, 0xc000124010, 0xc020c43408, 0x0, 0x0)

[2021-12-01T12:46:59.259Z] 	/home/jenkins/agent/workspace/tidb_ghpr_coverage/go/src/github.com/pingcap/tidb/server/conn.go:715 +0x8c

[2021-12-01T12:46:59.259Z] github.com/pingcap/tidb/server.TestHandleAuthPlugin(0xc000dd8000)

[2021-12-01T12:46:59.259Z] 	/home/jenkins/agent/workspace/tidb_ghpr_coverage/go/src/github.com/pingcap/tidb/server/conn_test.go:1016 +0x1210

[2021-12-01T12:46:59.259Z] testing.tRunner(0xc000dd8000, 0x3fee6f8)

[2021-12-01T12:46:59.259Z] 	/usr/local/go/src/testing/testing.go:1193 +0xef

[2021-12-01T12:46:59.259Z] created by testing.(*T).Run

[2021-12-01T12:46:59.259Z] 	/usr/local/go/src/testing/testing.go:1238 +0x2b3

[2021-12-01T12:46:59.259Z] FAIL	github.com/pingcap/tidb/server	36.656s

@github-actions
Copy link

github-actions bot commented Dec 6, 2021

Please check whether the issue should be labeled with 'affects-x.y' or 'fixes-x.y.z', and then remove 'needs-more-info' label.

@dveeden
Copy link
Contributor

dveeden commented Dec 7, 2021

/label affects-5.3
/unlabel needs-more-info

@ti-chi-bot ti-chi-bot added the affects-5.3 This bug affects 5.3.x versions. label Dec 7, 2021
@ti-srebot ti-srebot mentioned this issue Dec 7, 2021
Closed
12 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dveeden dveeden

Labels
affects-5.3 This bug affects 5.3.x versions. component/test severity/major sig/sql-infra SIG: SQL Infra type/bug The issue is confirmed as a bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

server: Fix unstable tests with FakeAuthSwitch dveeden/tidb
4 participants
@dveeden @aytrack @djshow832 @ti-chi-bot