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)