explain_generate_column_substitute explain test failure

[mjonss]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

checkout tidb and run:

(cd cmd/explaintest/ ; TZ='Europe/Amsterdam' ./run-tests.sh -t explain_generate_column_substitute)
(cd cmd/explaintest/ ; TZ='Europe/Amsterdam' ./run-tests.sh -r explain_generate_column_substitute)
git diff

Notice that I also filed bug #29475 which allowed this to be introduced.

2. What did you expect to see? (Required)

No test failure and no diff

3. What did you see instead (Required)

Test error and resulting diff

~/repos/tidb$ (cd cmd/explaintest/ ; ./run-tests.sh -t explain_generate_column_substitute)
extracting statistics: s
building tidb-server binary: ./explaintest_tidb-server
building portgenerator binary: ./portgenerator
building explain-test binary: ./explain_test
start tidb-server, log file: ./explain-test.out
tidb-server(PID: 1000973) started
run explain test cases: explain_generate_column_substitute
[2021/11/04 16:38:12.111 +01:00] [FATAL] [main.go:711] ["run test"] [test=explain_generate_column_substitute] [error="sql:drop table if exists t;: run \"drop table if exists t;\" at line 215 err, we need:\n2021-01-02\t2021-03-30 08\nbut got:\ndrop table if exists t;\n\n"] [errorVerbose="run \"drop table if exists t;\" at line 215 err, we need:\n2021-01-02\t2021-03-30 08\nbut got:\ndrop table if exists t;\n\n\nmain.(*tester).execute\n\trepos/tidb/cmd/explaintest/main.go:380\nmain.(*tester).Run\n\trepos/tidb/cmd/explaintest/main.go:169\nmain.main\n\trepos/tidb/cmd/explaintest/main.go:710\nruntime.main\n\t/usr/lib/go-1.16/src/runtime/proc.go:225\nruntime.goexit\n\t/usr/lib/go-1.16/src/runtime/asm_amd64.s:1371\nsql:drop table if exists t;"] [stack="main.main\n\trepos/tidb/cmd/explaintest/main.go:711\nruntime.main\n\t/usr/lib/go-1.16/src/runtime/proc.go:225"]
~/repos/tidb$ (cd cmd/explaintest/ ; ./run-tests.sh -r explain_generate_column_substitute)
extracting statistics: s
building tidb-server binary: ./explaintest_tidb-server
building portgenerator binary: ./portgenerator
building explain-test binary: ./explain_test
start tidb-server, log file: ./explain-test.out
tidb-server(PID: 1001490) started
record result for case: "explain_generate_column_substitute"
explaintest end
~/repos/tidb$ git diff
diff --git a/cmd/explaintest/r/explain_generate_column_substitute.result b/cmd/explaintest/r/explain_generate_column_substitute.result
index 4046fa494c..a54bf09b5f 100644
--- a/cmd/explaintest/r/explain_generate_column_substitute.result
+++ b/cmd/explaintest/r/explain_generate_column_substitute.result
@@ -485,7 +485,6 @@ a   b       c       d       e
 2021-01-02     2021-03-30 08:10:00     12:01:03        2021-08-13 04:10:44     2021
 select * from t ignore index(expression_index3) where d+ timestamp'0000-00-00 00:00:00.00001' = timestamp'2021-08-13 04:10:44'+ timestamp'0000-00-00 00:00:00.00001';
 a      b       c       d       e
-2021-01-02     2021-03-30 08:10:00     12:01:03        2021-08-13 04:10:44     2021
 drop table if exists t;
 create table t(a int, b int as (a+1), key((a+1)), key(b));
 desc format = 'brief' select a+1 from t;
~/repos/tidb$ 

4. What is your TiDB version? (Required)

Current master as of d80efa5

[mjonss]

@wjhuang2016 Please take a look.

[wjhuang2016]

@mjonss I can't reproduce it.

[mjonss]

I have two machines I can reproduce it on (my normal dev machines) and did not manage to reproduce on an older non-dev machine. I will troubleshoot locally and see where the issue might be... No need to look into this bug until I know what is happening on my side...

[mjonss]

@wjhuang2016 could you try with a different time zone:

(cd cmd/explaintest/ ; TZ='Europe/Amsterdam' ./run-tests.sh -t explain_generate_column_substitute)
(cd cmd/explaintest/ ; TZ='Europe/Amsterdam' ./run-tests.sh -r explain_generate_column_substitute)
git diff

[wjhuang2016]

TZ='Europe/Amsterdam

Yeah, I can reproduce it now.

[wjhuang2016]

I can reproduce it in MySQL too.

mysql>  select * from t use index(expression_index3) where d+ timestamp'0000-00-00 00:00:00.00001' = timestamp'2021-08-13 04:10:44'+ timestamp'0000-00-00 00:00:00.00001';
+------------+---------------------+----------+---------------------+------+
| a          | b                   | c        | d                   | e    |
+------------+---------------------+----------+---------------------+------+
| 2021-01-02 | 2021-03-30 08:10:00 | 12:01:03 | 2021-08-12 23:10:44 | 2021 |
+------------+---------------------+----------+---------------------+------+
1 row in set (0.00 sec)

mysql>  select * from t ignore index(expression_index3) where d+ timestamp'0000-00-00 00:00:00.00001' = timestamp'2021-08-13 04:10:44'+ timestamp'0000-00-00 00:00:00.00001';
Empty set (0.00 sec)

mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.20    |
+-----------+
1 row in set (0.01 sec)

[mjonss]

/assign

[mjonss]

/cc @wjhuang2016 @morgo

[morgo]

I have hit many such issues like this :(

#27956
#9787

[wjhuang2016]

I think it's the bug of expression index, we shouldn't hide it by setting the timezone.

[mjonss]

I think it's the bug of expression index, we shouldn't hide it by setting the timezone.

I think this is two bugs then, unstable testing environment (this issue) and a bug in expression index. I will create a new issue for that.

[wjhuang2016]

ok

[mjonss]

I think it's the bug of expression index, we shouldn't hide it by setting the timezone.

I think this is two bugs then, unstable testing environment (this issue) and a bug in expression index. I will create a new issue for that.

Reported the bug as #29817

[github-actions]

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