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

pkg/ccl/testccl/sqlccl/sqlccl_test: TestTenantTempTableCleanup failed #92895

Closed
cockroach-teamcity opened this issue Dec 2, 2022 · 7 comments · Fixed by #92993
Closed

pkg/ccl/testccl/sqlccl/sqlccl_test: TestTenantTempTableCleanup failed #92895

cockroach-teamcity opened this issue Dec 2, 2022 · 7 comments · Fixed by #92993
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. T-sql-queries SQL Queries Team
Milestone
23.1

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Dec 2, 2022 •
edited by cockroach-jira-scripts
Loading

pkg/ccl/testccl/sqlccl/sqlccl_test.TestTenantTempTableCleanup failed with artifacts on master @ e7b15ebaed9c14668ade0a7827a5525aedef1ab0:

I221202 08:55:54.135337 21444 server/server_sql.go:1339  [nsql?] 1170  bound sqlinstance: Instance{RegionPrefix: gA==, InstanceID: 2, Addr: 127.0.0.1:33827, SessionID: 010180a67fd4c9e75e45b58ec3c3d800a9eef3, Locality: }
I221202 08:55:54.135562 25499 sql/temporary_schema.go:504  [nsql2] 1171  running temporary object cleanup background job
I221202 08:55:54.135551 25500 sql/sqlstats/persistedsqlstats/provider.go:132  [nsql2] 1172  starting sql-stats-worker with initial delay: 10m14.191449006s
I221202 08:55:54.135821 25541 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1173  settings-watcher: established range feed cache
I221202 08:55:54.136932 21444 upgrade/upgrademanager/manager.go:168  [nsql2] 1174  running permanent upgrades up to version: 1000022.2-10
I221202 08:55:54.137377 25544 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1175  system-config-cache: established range feed cache
I221202 08:55:54.141505 25499 sql/temporary_schema.go:549  [nsql2] 1176  found 1 temporary schemas
I221202 08:55:54.155528 21444 server/server_sql.go:1446  [nsql2] 1177  done ensuring all necessary startup migrations have run
I221202 08:55:54.155774 21444 1@server/server_sql.go:1512  [nsql2] 1178  serving sql connections
I221202 08:55:54.155843 25489 jobs/job_scheduler.go:433  [nsql2] 1179  waiting 4m0s before scheduled jobs daemon start
I221202 08:55:54.157042 25621 2@rpc/context.go:2176  [nsql2,rnode=2,raddr=127.0.0.1:33827,class=default,rpc] 1180  connection is now ready
I221202 08:55:54.186240 25719 sql/table.go:184  [nsql2,intExec=delete-temp-TABLE] 1181  queued new schema-change job 818875446677438466 for table 105, mutation 0
I221202 08:55:54.203501 25499 5@util/log/event_log.go:32  [nsql2] 1182 ={"Timestamp":1669971354158080168,"EventType":"drop_table","Statement":"DROP TABLE defaultdb.pg_temp_1669971354033892964_1.temp_table CASCADE","Tag":"DROP TABLE","User":"root","DescriptorID":105,"ApplicationName":"$ internal-delete-temp-TABLE","TableName":"defaultdb.pg_temp_1669971354033892964_1.temp_table"}
I221202 08:55:54.203649 25599 jobs/adopt.go:245  [nsql2] 1183  job 818875446677438466: resuming execution
I221202 08:55:54.213698 25758 jobs/registry.go:1379  [nsql2] 1184  SCHEMA CHANGE job 818875446677438466: stepping through state running
I221202 08:55:54.220390 25758 sql/schema_changer.go:661  [nsql2,job=SCHEMA CHANGE id=818875446677438466,scExec,id=105] 1185  schema change on "temp_table" (v2) starting execution...
I221202 08:55:54.223511 25758 sql/schema_changer.go:534  [nsql2,job=SCHEMA CHANGE id=818875446677438466,scExec,id=105] 1186  created GC job 818875446789636098
I221202 08:55:54.223838 25863 jobs/adopt.go:245  [nsql2,job=SCHEMA CHANGE id=818875446677438466,scExec,id=105] 1187  job 818875446789636098: resuming execution
I221202 08:55:54.224607 25758 sql/schema_changer.go:1317  [nsql2,job=SCHEMA CHANGE id=818875446677438466,scExec,id=105] 1188  waiting for a single version...
I221202 08:55:54.227225 25758 sql/schema_changer.go:1322  [nsql2,job=SCHEMA CHANGE id=818875446677438466,scExec,id=105] 1189  waiting for a single version... done (at v 2), took 2.618268ms
I221202 08:55:54.227293 25758 jobs/registry.go:1379  [nsql2] 1190  SCHEMA CHANGE job 818875446677438466: stepping through state succeeded
I221202 08:55:54.232246 25866 jobs/registry.go:1379  [nsql2] 1191  SCHEMA CHANGE GC job 818875446789636098: stepping through state running
I221202 08:55:54.234560 25499 jobs/wait.go:154  [nsql2] 1192  waited for 1 [818875446677438466] queued jobs to complete 30.945562ms
I221202 08:55:54.237165 25499 sql/temporary_schema.go:609  [nsql2] 1193  completed temporary object cleanup job
I221202 08:55:54.237208 25499 sql/temporary_schema.go:636  [nsql2] 1194  temporary object cleaner next scheduled to run at 2022-12-02 08:55:55.135526612 +0000 UTC m=+17.769498086
I221202 08:55:54.249833 25866 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1195  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221202 08:55:54.253386 25866 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1196  updated running status: waiting for GC TTL
I221202 08:55:54.258884 25866 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1197  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221202 08:55:54.262884 25866 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1198  updated running status: deleting data
I221202 08:55:54.264377 25866 sql/gcjob/table_garbage_collection.go:205  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1199  deleting data for table 105
I221202 08:55:54.269790 25866 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1200  updated progress payload: tables:<id:105 status:WAITING_FOR_MVCC_GC > ranges_unsplit_done:true
I221202 08:55:54.273801 25866 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=818875446789636098] 1201  updated running status: waiting for MVCC GC
I221202 08:55:54.334489 22966 sql/temporary_schema.go:496  [n2] 1202  skipping temporary object cleanup run as it is not the leaseholder
I221202 08:55:54.334538 22966 sql/temporary_schema.go:497  [n2] 1203  completed temporary object cleanup job
I221202 08:55:54.334553 22966 sql/temporary_schema.go:636  [n2] 1204  temporary object cleaner next scheduled to run at 2022-12-02 08:55:55.334383483 +0000 UTC m=+17.968355040
I221202 08:55:54.459414 23536 sql/temporary_schema.go:496  [n3] 1205  skipping temporary object cleanup run as it is not the leaseholder
I221202 08:55:54.459500 23536 sql/temporary_schema.go:497  [n3] 1206  completed temporary object cleanup job
I221202 08:55:54.459519 23536 sql/temporary_schema.go:636  [n3] 1207  temporary object cleaner next scheduled to run at 2022-12-02 08:55:55.45920241 +0000 UTC m=+18.093173966
I221202 08:55:54.663577 21777 1@gossip/gossip.go:1542  [n1] 1208  node has connected to cluster via gossip
I221202 08:55:54.663783 21777 kv/kvserver/stores.go:281  [n1] 1209  wrote 2 node addresses to persistent storage
    temp_table_clean_test.go:127: query 'SELECT table_name FROM [SHOW TABLES]': expected:
        temp_table
        
        got:
        
I221202 08:55:54.730167 24201 sql/temporary_schema.go:504  [nsql1] 1210  running temporary object cleanup background job
I221202 08:55:54.734629 24201 sql/temporary_schema.go:549  [nsql1] 1211  found 0 temporary schemas
I221202 08:55:54.734683 24201 sql/temporary_schema.go:552  [nsql1] 1212  early exiting temporary schema cleaner as no temporary schemas were found
I221202 08:55:54.734701 24201 sql/temporary_schema.go:553  [nsql1] 1213  completed temporary object cleanup job
--- FAIL: TestTenantTempTableCleanup (2.04s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/sql-queries

This test on roachdash | Improve this report!

Jira issue: CRDB-22030
@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 Dec 2, 2022
@cockroach-teamcity cockroach-teamcity added this to the 23.1 milestone Dec 2, 2022
@blathers-crl blathers-crl bot added the T-sql-queries SQL Queries Team label Dec 2, 2022
@ajwerner
Copy link
Contributor

ajwerner commented Dec 2, 2022

bors run https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_UnitTests_BazelUnitTests/7812964?showRootCauses=false&expandBuildChangesSection=true&expandBuildProblemsSection=true&expandBuildTestsSection=true

@ajwerner
Copy link
Contributor

ajwerner commented Dec 2, 2022

I bisected this to #92787.

@ajwerner
Copy link
Contributor

ajwerner commented Dec 2, 2022

I don't think that's right.

@cockroach-teamcity
Copy link
Member Author

pkg/ccl/testccl/sqlccl/sqlccl_test.TestTenantTempTableCleanup failed with artifacts on master @ ca079ac1fc8a8f7a5360f5b1f4fa210c14dc8410:

I221203 08:52:19.690749 20290 ccl/kvccl/kvtenantccl/connector.go:195  [nsql?] 1072  kv connector gossip subscription started
I221203 08:52:19.698313 23945 2@rpc/context.go:2176  [nsql?,rnode=1,raddr=127.0.0.1:43025,class=default,rpc] 1073  connection is now ready
I221203 08:52:19.699222 20290 sql/sqlliveness/slinstance/slinstance.go:407  [nsql?] 1074  starting SQL liveness instance
I221203 08:52:19.700141 24215 sql/sqlliveness/slstorage/slstorage.go:471  [nsql?] 1075  inserted sqlliveness session 010180c3e82027074c4e6695dc12018ceab901
I221203 08:52:19.700191 24215 sql/sqlliveness/slinstance/slinstance.go:245  [nsql?] 1076  created new SQL liveness session 010180c3e82027074c4e6695dc12018ceab901
I221203 08:52:19.700226 20290 sql/sqlinstance/instancestorage/instancestorage.go:206  [nsql?] 1077  assigning instance id to addr 127.0.0.1:38945
I221203 08:52:19.701481 20290 server/server_sql.go:1369  [nsql?] 1078  bound sqlinstance: Instance{RegionPrefix: gA==, InstanceID: 2, Addr: 127.0.0.1:38945, SessionID: 010180c3e82027074c4e6695dc12018ceab901, Locality: }
I221203 08:52:19.701825 24229 sql/sqlstats/persistedsqlstats/provider.go:132  [nsql2] 1079  starting sql-stats-worker with initial delay: 8m35.047582459s
I221203 08:52:19.701936 24248 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1081  settings-watcher: established range feed cache
I221203 08:52:19.701870 24228 sql/temporary_schema.go:504  [nsql2] 1080  running temporary object cleanup background job
I221203 08:52:19.703076 20290 upgrade/upgrademanager/manager.go:168  [nsql2] 1082  running permanent upgrades up to version: 1000022.2-10
I221203 08:52:19.703587 24200 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1083  system-config-cache: established range feed cache
I221203 08:52:19.706046 24228 sql/temporary_schema.go:549  [nsql2] 1084  found 1 temporary schemas
I221203 08:52:19.714073 24339 2@rpc/context.go:2176  [nsql2,rnode=2,raddr=127.0.0.1:38945,class=default,rpc] 1085  connection is now ready
I221203 08:52:19.717892 20290 server/server_sql.go:1476  [nsql2] 1086  done ensuring all necessary startup migrations have run
I221203 08:52:19.717964 20290 1@server/server_sql.go:1542  [nsql2] 1087  serving sql connections
I221203 08:52:19.718492 24423 jobs/job_scheduler.go:433  [nsql2] 1088  waiting 4m0s before scheduled jobs daemon start
I221203 08:52:19.734885 24409 sql/table.go:184  [nsql2,intExec=delete-temp-TABLE] 1089  queued new schema-change job 819157859483254786 for table 105, mutation 0
I221203 08:52:19.744705 24228 5@util/log/event_log.go:32  [nsql2] 1090 ={"Timestamp":1670057539716407393,"EventType":"drop_table","Statement":"DROP TABLE defaultdb.pg_temp_1670057539596211306_1.temp_table CASCADE","Tag":"DROP TABLE","User":"root","DescriptorID":105,"ApplicationName":"$ internal-delete-temp-TABLE","TableName":"defaultdb.pg_temp_1670057539596211306_1.temp_table"}
I221203 08:52:19.744829 24548 jobs/adopt.go:245  [nsql2] 1091  job 819157859483254786: resuming execution
I221203 08:52:19.754895 24551 jobs/registry.go:1373  [nsql2] 1092  SCHEMA CHANGE job 819157859483254786: stepping through state running
I221203 08:52:19.762358 24551 sql/schema_changer.go:661  [nsql2,job=SCHEMA CHANGE id=819157859483254786,scExec,id=105] 1093  schema change on "temp_table" (v2) starting execution...
I221203 08:52:19.765391 24551 sql/schema_changer.go:534  [nsql2,job=SCHEMA CHANGE id=819157859483254786,scExec,id=105] 1094  created GC job 819157859573530626
I221203 08:52:19.765575 24629 jobs/adopt.go:245  [nsql2,job=SCHEMA CHANGE id=819157859483254786,scExec,id=105] 1095  job 819157859573530626: resuming execution
I221203 08:52:19.766797 24551 sql/schema_changer.go:1317  [nsql2,job=SCHEMA CHANGE id=819157859483254786,scExec,id=105] 1096  waiting for a single version...
I221203 08:52:19.769499 24551 sql/schema_changer.go:1322  [nsql2,job=SCHEMA CHANGE id=819157859483254786,scExec,id=105] 1097  waiting for a single version... done (at v 2), took 2.701209ms
I221203 08:52:19.769564 24551 jobs/registry.go:1373  [nsql2] 1098  SCHEMA CHANGE job 819157859483254786: stepping through state succeeded
I221203 08:52:19.772398 24678 jobs/registry.go:1373  [nsql2] 1099  SCHEMA CHANGE GC job 819157859573530626: stepping through state running
I221203 08:52:19.776334 24228 jobs/wait.go:154  [nsql2] 1100  waited for 1 [819157859483254786] queued jobs to complete 31.53272ms
I221203 08:52:19.778807 24228 sql/temporary_schema.go:609  [nsql2] 1101  completed temporary object cleanup job
I221203 08:52:19.778847 24228 sql/temporary_schema.go:636  [nsql2] 1102  temporary object cleaner next scheduled to run at 2022-12-03 08:52:20.701807939 +0000 UTC m=+16.811492982
I221203 08:52:19.787770 24678 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1103  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221203 08:52:19.791138 24678 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1104  updated running status: waiting for GC TTL
I221203 08:52:19.796852 24678 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1105  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221203 08:52:19.800313 24678 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1106  updated running status: deleting data
I221203 08:52:19.801881 24678 sql/gcjob/table_garbage_collection.go:205  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1107  deleting data for table 105
I221203 08:52:19.806973 24678 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1108  updated progress payload: tables:<id:105 status:WAITING_FOR_MVCC_GC > ranges_unsplit_done:true
I221203 08:52:19.813508 24678 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819157859573530626] 1109  updated running status: waiting for MVCC GC
I221203 08:52:19.828969 21791 sql/temporary_schema.go:496  [n2] 1110  skipping temporary object cleanup run as it is not the leaseholder
I221203 08:52:19.829012 21791 sql/temporary_schema.go:497  [n2] 1111  completed temporary object cleanup job
I221203 08:52:19.829037 21791 sql/temporary_schema.go:636  [n2] 1112  temporary object cleaner next scheduled to run at 2022-12-03 08:52:20.828935001 +0000 UTC m=+16.938620046
I221203 08:52:19.961249 22334 sql/temporary_schema.go:496  [n3] 1113  skipping temporary object cleanup run as it is not the leaseholder
I221203 08:52:19.961319 22334 sql/temporary_schema.go:497  [n3] 1114  completed temporary object cleanup job
I221203 08:52:19.961331 22334 sql/temporary_schema.go:636  [n3] 1115  temporary object cleaner next scheduled to run at 2022-12-03 08:52:20.961180285 +0000 UTC m=+17.070865402
    temp_table_clean_test.go:127: query 'SELECT table_name FROM [SHOW TABLES]': expected:
        temp_table
        
        got:
        
--- FAIL: TestTenantTempTableCleanup (2.04s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

@ajwerner
Copy link
Contributor

ajwerner commented Dec 3, 2022

Bisected again to e90c549.

@ajwerner ajwerner mentioned this issue Dec 3, 2022
Merged
@cockroach-teamcity
Copy link
Member Author

pkg/ccl/testccl/sqlccl/sqlccl_test.TestTenantTempTableCleanup failed with artifacts on master @ 859e1e1f26d79af43cce16519f9ba984baaa495c:

I221204 08:44:57.231125 20452 sql/sqlinstance/instancestorage/instancestorage.go:206  [nsql?] 1087  assigning instance id to addr 127.0.0.1:40869
I221204 08:44:57.232666 20452 server/server_sql.go:1369  [nsql?] 1088  bound sqlinstance: Instance{RegionPrefix: gA==, InstanceID: 2, Addr: 127.0.0.1:40869, SessionID: 010180da6c3f5f598e40cc87963fd5d2e6b13b, Locality: }
I221204 08:44:57.232865 24447 sql/temporary_schema.go:504  [nsql2] 1089  running temporary object cleanup background job
I221204 08:44:57.233052 24483 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1090  settings-watcher: established range feed cache
I221204 08:44:57.233264 24448 sql/sqlstats/persistedsqlstats/provider.go:132  [nsql2] 1091  starting sql-stats-worker with initial delay: 9m45.209017156s
I221204 08:44:57.234239 20452 upgrade/upgrademanager/manager.go:168  [nsql2] 1092  running permanent upgrades up to version: 1000022.2-10
I221204 08:44:57.236586 24394 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1093  system-config-cache: established range feed cache
I221204 08:44:57.237550 24447 sql/temporary_schema.go:549  [nsql2] 1094  found 1 temporary schemas
I221204 08:44:57.264185 20452 server/server_sql.go:1476  [nsql2] 1095  done ensuring all necessary startup migrations have run
I221204 08:44:57.264269 20452 1@server/server_sql.go:1542  [nsql2] 1096  serving sql connections
I221204 08:44:57.264412 24584 jobs/job_scheduler.go:433  [nsql2] 1097  waiting 4m0s before scheduled jobs daemon start
I221204 08:44:57.266891 24521 2@rpc/context.go:2176  [nsql2,rnode=2,raddr=127.0.0.1:40869,class=default,rpc] 1098  connection is now ready
I221204 08:44:57.266909 24385 2@rpc/context.go:2176  [nsql2,rnode=1,raddr=127.0.0.1:44143,class=rangefeed,rpc] 1099  connection is now ready
I221204 08:44:57.290540 24621 sql/table.go:184  [nsql2,intExec=delete-temp-TABLE] 1100  queued new schema-change job 819439525201608706 for table 105, mutation 0
I221204 08:44:57.301459 24447 5@util/log/event_log.go:32  [nsql2] 1101 ={"Timestamp":1670143497267619711,"EventType":"drop_table","Statement":"DROP TABLE defaultdb.pg_temp_1670143497098797439_1.temp_table CASCADE","Tag":"DROP TABLE","User":"root","DescriptorID":105,"ApplicationName":"$ internal-delete-temp-TABLE","TableName":"defaultdb.pg_temp_1670143497098797439_1.temp_table"}
I221204 08:44:57.301593 24837 jobs/adopt.go:245  [nsql2] 1102  job 819439525201608706: resuming execution
I221204 08:44:57.312088 24822 jobs/registry.go:1373  [nsql2] 1103  SCHEMA CHANGE job 819439525201608706: stepping through state running
I221204 08:44:57.318567 24822 sql/schema_changer.go:661  [nsql2,job=SCHEMA CHANGE id=819439525201608706,scExec,id=105] 1104  schema change on "temp_table" (v2) starting execution...
I221204 08:44:57.321725 24822 sql/schema_changer.go:534  [nsql2,job=SCHEMA CHANGE id=819439525201608706,scExec,id=105] 1105  created GC job 819439525293654018
I221204 08:44:57.321891 24832 jobs/adopt.go:245  [nsql2,job=SCHEMA CHANGE id=819439525201608706,scExec,id=105] 1106  job 819439525293654018: resuming execution
I221204 08:44:57.322694 24822 sql/schema_changer.go:1317  [nsql2,job=SCHEMA CHANGE id=819439525201608706,scExec,id=105] 1107  waiting for a single version...
I221204 08:44:57.325058 24822 sql/schema_changer.go:1322  [nsql2,job=SCHEMA CHANGE id=819439525201608706,scExec,id=105] 1108  waiting for a single version... done (at v 2), took 2.363572ms
I221204 08:44:57.325121 24822 jobs/registry.go:1373  [nsql2] 1109  SCHEMA CHANGE job 819439525201608706: stepping through state succeeded
I221204 08:44:57.328282 24931 jobs/registry.go:1373  [nsql2] 1110  SCHEMA CHANGE GC job 819439525293654018: stepping through state running
I221204 08:44:57.332311 24447 jobs/wait.go:154  [nsql2] 1111  waited for 1 [819439525201608706] queued jobs to complete 30.743168ms
I221204 08:44:57.334847 24447 sql/temporary_schema.go:609  [nsql2] 1112  completed temporary object cleanup job
I221204 08:44:57.334896 24447 sql/temporary_schema.go:636  [nsql2] 1113  temporary object cleaner next scheduled to run at 2022-12-04 08:44:58.232837046 +0000 UTC m=+16.444727408
I221204 08:44:57.344696 24931 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1114  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221204 08:44:57.348559 24931 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1115  updated running status: waiting for GC TTL
I221204 08:44:57.359350 24931 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1116  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221204 08:44:57.362734 24931 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1117  updated running status: deleting data
I221204 08:44:57.364923 24931 sql/gcjob/table_garbage_collection.go:205  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1118  deleting data for table 105
I221204 08:44:57.380089 24931 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1119  updated progress payload: tables:<id:105 status:WAITING_FOR_MVCC_GC > ranges_unsplit_done:true
I221204 08:44:57.383588 24931 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819439525293654018] 1120  updated running status: waiting for MVCC GC
I221204 08:44:57.482063 21989 sql/temporary_schema.go:496  [n2] 1121  skipping temporary object cleanup run as it is not the leaseholder
I221204 08:44:57.482110 21989 sql/temporary_schema.go:497  [n2] 1122  completed temporary object cleanup job
I221204 08:44:57.482126 21989 sql/temporary_schema.go:636  [n2] 1123  temporary object cleaner next scheduled to run at 2022-12-04 08:44:58.481957685 +0000 UTC m=+16.693848057
I221204 08:44:57.595466 22594 sql/temporary_schema.go:496  [n3] 1124  skipping temporary object cleanup run as it is not the leaseholder
I221204 08:44:57.595516 22594 sql/temporary_schema.go:497  [n3] 1125  completed temporary object cleanup job
I221204 08:44:57.595529 22594 sql/temporary_schema.go:636  [n3] 1126  temporary object cleaner next scheduled to run at 2022-12-04 08:44:58.595339325 +0000 UTC m=+16.807229692
    temp_table_clean_test.go:127: query 'SELECT table_name FROM [SHOW TABLES]': expected:
        temp_table
        
        got:
        
I221204 08:44:57.828955 23267 sql/temporary_schema.go:504  [nsql1] 1127  running temporary object cleanup background job
I221204 08:44:57.833448 23267 sql/temporary_schema.go:549  [nsql1] 1128  found 0 temporary schemas
I221204 08:44:57.833497 23267 sql/temporary_schema.go:552  [nsql1] 1129  early exiting temporary schema cleaner as no temporary schemas were found
I221204 08:44:57.833515 23267 sql/temporary_schema.go:553  [nsql1] 1130  completed temporary object cleanup job
--- FAIL: TestTenantTempTableCleanup (1.95s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

pkg/ccl/testccl/sqlccl/sqlccl_test.TestTenantTempTableCleanup failed with artifacts on master @ 8a5cb5109d6b7e122e996a44f940bfd61698cd81:

I221205 08:39:02.520777 20072 sql/sqlliveness/slinstance/slinstance.go:407  [nsql?] 1093  starting SQL liveness instance
I221205 08:39:02.521781 24141 sql/sqlliveness/slstorage/slstorage.go:471  [nsql?] 1094  inserted sqlliveness session 010180089a62a6280c47999bbd1ed770fd773f
I221205 08:39:02.521824 24141 sql/sqlliveness/slinstance/slinstance.go:245  [nsql?] 1095  created new SQL liveness session 010180089a62a6280c47999bbd1ed770fd773f
I221205 08:39:02.521853 20072 sql/sqlinstance/instancestorage/instancestorage.go:206  [nsql?] 1096  assigning instance id to addr 127.0.0.1:37495
I221205 08:39:02.523108 20072 server/server_sql.go:1369  [nsql?] 1097  bound sqlinstance: Instance{RegionPrefix: gA==, InstanceID: 2, Addr: 127.0.0.1:37495, SessionID: 010180089a62a6280c47999bbd1ed770fd773f, Locality: }
I221205 08:39:02.523470 24125 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1098  settings-watcher: established range feed cache
I221205 08:39:02.523853 24146 sql/temporary_schema.go:504  [nsql2] 1099  running temporary object cleanup background job
I221205 08:39:02.524389 24147 sql/sqlstats/persistedsqlstats/provider.go:132  [nsql2] 1100  starting sql-stats-worker with initial delay: 9m32.599891931s
I221205 08:39:02.524526 20072 upgrade/upgrademanager/manager.go:168  [nsql2] 1101  running permanent upgrades up to version: 1000022.2-10
I221205 08:39:02.525314 24163 kv/kvclient/rangefeed/rangefeedcache/watcher.go:320  [nsql2] 1102  system-config-cache: established range feed cache
I221205 08:39:02.527599 24146 sql/temporary_schema.go:549  [nsql2] 1103  found 1 temporary schemas
I221205 08:39:02.535504 24231 2@rpc/context.go:2172  [nsql2,rnode=2,raddr=127.0.0.1:37495,class=default,rpc] 1104  connection is now ready
I221205 08:39:02.538055 20072 server/server_sql.go:1476  [nsql2] 1105  done ensuring all necessary startup migrations have run
I221205 08:39:02.538114 20072 1@server/server_sql.go:1542  [nsql2] 1106  serving sql connections
I221205 08:39:02.538138 24323 jobs/job_scheduler.go:433  [nsql2] 1107  waiting 4m0s before scheduled jobs daemon start
I221205 08:39:02.553848 24331 sql/table.go:184  [nsql2,intExec=delete-temp-TABLE] 1108  queued new schema-change job 819721478320422914 for table 105, mutation 0
I221205 08:39:02.562622 24146 5@util/log/event_log.go:32  [nsql2] 1109 ={"Timestamp":1670229542536454830,"EventType":"drop_table","Statement":"DROP TABLE defaultdb.pg_temp_1670229542441480764_1.temp_table CASCADE","Tag":"DROP TABLE","User":"root","DescriptorID":105,"ApplicationName":"$ internal-delete-temp-TABLE","TableName":"defaultdb.pg_temp_1670229542441480764_1.temp_table"}
I221205 08:39:02.562741 24350 jobs/adopt.go:245  [nsql2] 1110  job 819721478320422914: resuming execution
I221205 08:39:02.571029 24437 jobs/registry.go:1373  [nsql2] 1111  SCHEMA CHANGE job 819721478320422914: stepping through state running
I221205 08:39:02.576700 24437 sql/schema_changer.go:661  [nsql2,job=SCHEMA CHANGE id=819721478320422914,scExec,id=105] 1112  schema change on "temp_table" (v2) starting execution...
I221205 08:39:02.579347 24437 sql/schema_changer.go:534  [nsql2,job=SCHEMA CHANGE id=819721478320422914,scExec,id=105] 1113  created GC job 819721478395527170
I221205 08:39:02.579530 24399 jobs/adopt.go:245  [nsql2,job=SCHEMA CHANGE id=819721478320422914,scExec,id=105] 1114  job 819721478395527170: resuming execution
I221205 08:39:02.580298 24437 sql/schema_changer.go:1317  [nsql2,job=SCHEMA CHANGE id=819721478320422914,scExec,id=105] 1115  waiting for a single version...
I221205 08:39:02.582504 24437 sql/schema_changer.go:1322  [nsql2,job=SCHEMA CHANGE id=819721478320422914,scExec,id=105] 1116  waiting for a single version... done (at v 2), took 2.205823ms
I221205 08:39:02.582557 24437 jobs/registry.go:1373  [nsql2] 1117  SCHEMA CHANGE job 819721478320422914: stepping through state succeeded
I221205 08:39:02.586211 24522 jobs/registry.go:1373  [nsql2] 1118  SCHEMA CHANGE GC job 819721478395527170: stepping through state running
I221205 08:39:02.589365 24146 jobs/wait.go:154  [nsql2] 1119  waited for 1 [819721478320422914] queued jobs to complete 26.649424ms
I221205 08:39:02.591884 24146 sql/temporary_schema.go:609  [nsql2] 1120  completed temporary object cleanup job
I221205 08:39:02.591924 24146 sql/temporary_schema.go:636  [nsql2] 1121  temporary object cleaner next scheduled to run at 2022-12-05 08:39:03.523829329 +0000 UTC m=+15.738151960
I221205 08:39:02.600161 24522 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1122  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221205 08:39:02.603205 24522 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1123  updated running status: waiting for GC TTL
I221205 08:39:02.608071 24522 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1124  updated progress payload: tables:<id:105 > ranges_unsplit_done:true
I221205 08:39:02.611129 24522 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1125  updated running status: deleting data
I221205 08:39:02.612654 24522 sql/gcjob/table_garbage_collection.go:205  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1126  deleting data for table 105
I221205 08:39:02.616737 24522 sql/gcjob/gc_job_utils.go:289  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1127  updated progress payload: tables:<id:105 status:WAITING_FOR_MVCC_GC > ranges_unsplit_done:true
I221205 08:39:02.619699 24522 sql/gcjob/gc_job_utils.go:296  [nsql2,job=SCHEMA CHANGE GC id=819721478395527170] 1128  updated running status: waiting for MVCC GC
I221205 08:39:02.701884 20786 sql/temporary_schema.go:504  [n1] 1129  running temporary object cleanup background job
I221205 08:39:02.703410 20786 sql/temporary_schema.go:549  [n1] 1130  found 0 temporary schemas
I221205 08:39:02.703453 20786 sql/temporary_schema.go:552  [n1] 1131  early exiting temporary schema cleaner as no temporary schemas were found
I221205 08:39:02.703466 20786 sql/temporary_schema.go:553  [n1] 1132  completed temporary object cleanup job
I221205 08:39:02.703475 20786 sql/temporary_schema.go:636  [n1] 1133  temporary object cleaner next scheduled to run at 2022-12-05 08:39:03.701734264 +0000 UTC m=+15.916056891
I221205 08:39:02.933911 21693 sql/temporary_schema.go:496  [n2] 1134  skipping temporary object cleanup run as it is not the leaseholder
I221205 08:39:02.933954 21693 sql/temporary_schema.go:497  [n2] 1135  completed temporary object cleanup job
I221205 08:39:02.933965 21693 sql/temporary_schema.go:636  [n2] 1136  temporary object cleaner next scheduled to run at 2022-12-05 08:39:03.93387343 +0000 UTC m=+16.148196060
    temp_table_clean_test.go:127: query 'SELECT table_name FROM [SHOW TABLES]': expected:
        temp_table
        
        got:
        
--- FAIL: TestTenantTempTableCleanup (1.55s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

craig bot pushed a commit that referenced this issue Dec 5, 2022
@ajwerner
Merge #92993
d1c95d5 
92993: server,sql: ensure that temp tables wait to know about other instances r=ajwerner a=ajwerner

In #92666 we stopped waiting for the sqlinstance.Reader to know about all the other instances synchronously at startup. Waiting for this information requires out-of-region RPCs. The hazard here is that in the temp table tests which lower the grace period for temp tables dramatically, we might delete temp tables which should not be deleted. By waiting for these instances, we deflake the test.

Epic: none
Fixes: #92895

Release note: None

Co-authored-by: Andrew Werner <[email protected]>
@craig craig bot closed this as completed in 12fce39 Dec 5, 2022
@mgartner mgartner moved this to Done in SQL Queries Jul 24, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
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. T-sql-queries SQL Queries Team
Projects
SQL Queries
Archived in project
Milestone
23.1
Development

Successfully merging a pull request may close this issue.

server,sql: ensure that temp tables wait to know about other instances ajwerner/cockroach
2 participants
@ajwerner @cockroach-teamcity