ccl/serverccl: TestTenantGRPCServices failed

[cockroach-teamcity]

ccl/serverccl.TestTenantGRPCServices failed with artifacts on master @ 2a7ef521a38d923cca9ec96e229237bbedc0c5fa:

=== RUN   TestTenantGRPCServices
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestTenantGRPCServices943530077
    test_log_scope.go:74: use -show-logs to present logs inline
=== CONT  TestTenantGRPCServices
    tenant_grpc_test.go:170: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestTenantGRPCServices943530077
--- FAIL: TestTenantGRPCServices (5.66s)
=== RUN   TestTenantGRPCServices/statements_endpoint_fans_out_request_to_multiple_pods
    tenant_grpc_test.go:109: 
        	Error Trace:	tenant_grpc_test.go:109
        	Error:      	"{\n  \"statements\": [\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"SELECT * FROM system.scheduled_jobs WHERE schedule_id = _\",\n          \"app\": \"$ internal-lookup-schedule\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": false,\n          \"vec\": true,\n          \"fullScan\": false,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"15237859555065754932\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0.000039374,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.000265146,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.000601961,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.000910496,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.000004015000000000008,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"scan\",\n            \"attrs\": [\n              {\n                \"key\": \"missing stats\",\n                \"value\": \"\"\n              },\n              {\n                \"key\": \"table\",\n                \"value\": \"scheduled_jobs@primary\"\n              },\n              {\n                \"key\": \"spans\",\n                \"value\": \"1 span\"\n              }\n            ],\n            \"children\": [\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.385578505Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 264,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 10240,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.385578788Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"SELECT EXISTS (SELECT job_id FROM [SHOW AUTOMATIC JOBS] WHERE (job_type = '_') AND (status IN ('_', '_', __more4__)))\",\n          \"app\": \"$ internal-check-if-reconciliation-job-already-exists\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": false,\n          \"vec\": true,\n          \"fullScan\": false,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"13960861399300800844\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0.000198793,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.001518983,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.006740566,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.008463795,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.000005452999999999014,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"root\",\n            \"attrs\": [\n            ],\n            \"children\": [\n              {\n                \"name\": \"values\",\n                \"attrs\": [\n                  {\n                    \"key\": \"size\",\n                    \"value\": \"1 column, 1 row\"\n                  }\n                ],\n                \"children\": [\n                ]\n              },\n              {\n                \"name\": \"subquery\",\n                \"attrs\": [\n                  {\n                    \"key\": \"id\",\n                    \"value\": \"@S1\"\n                  },\n                  {\n                    \"key\": \"original sql\",\n                    \"value\": \"EXISTS (SELECT job_id FROM [SHOW AUTOMATIC JOBS] WHERE (job_type = 'AUTO SPAN CONFIG RECONCILIATION') AND (status IN ('running', 'pending', 'cancel-requested', 'pause-requested', 'reverting', 'paused')))\"\n                  },\n                  {\n                    \"key\": \"exec mode\",\n                    \"value\": \"exists\"\n                  }\n                ],\n                \"children\": [\n                  {\n                    \"name\": \"limit\",\n                    \"attrs\": [\n                      {\n                        \"key\": \"count\",\n                        \"value\": \"_\"\n                      }\n                    ],\n                    \"children\": [\n                      {\n                        \"name\": \"filter\",\n                        \"attrs\": [\n                          {\n                            \"key\": \"filter\",\n                            \"value\": \"(((finished IS NULL) OR (finished \\u003e _)) AND (job_type = _)) AND (status IN _)\"\n                          }\n                        ],\n                        \"children\": [\n                          {\n                            \"name\": \"virtual table\",\n                            \"attrs\": [\n                              {\n                                \"key\": \"table\",\n                                \"value\": \"jobs@primary\"\n                              }\n                            ],\n                            \"children\": [\n                            ]\n                          }\n                        ]\n                      }\n                    ]\n                  }\n                ]\n              }\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.395020401Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 30720,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.395020632Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"SELECT id, statement_fingerprint FROM system.statement_diagnostics_requests WHERE completed = _\",\n          \"app\": \"$ internal-stmt-diag-poll\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": true,\n          \"vec\": true,\n          \"fullScan\": false,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"4104049045071304794\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0.000154026,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.006650353,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.001375122,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.008188401,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.000008899999999999186,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"scan\",\n            \"attrs\": [\n              {\n                \"key\": \"missing stats\",\n                \"value\": \"\"\n              },\n              {\n                \"key\": \"table\",\n                \"value\": \"statement_diagnostics_requests@completed_idx\"\n              },\n              {\n                \"key\": \"spans\",\n                \"value\": \"1 span\"\n              }\n            ],\n            \"children\": [\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.394347566Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 10240,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.394347838Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"UPDATE system.jobs SET claim_session_id = _ WHERE claim_session_id IN (SELECT claim_session_id WHERE ((claim_session_id != $1) AND (status IN ('_', '_', __more3__))) AND (NOT crdb_internal.sql_liveness_is_alive(claim_session_id)) LIMIT $2)\",\n          \"app\": \"$ internal-expire-sessions\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": true,\n          \"vec\": true,\n          \"fullScan\": false,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"5582459872449769942\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.000494848,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.00098705,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.001485128,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.0000032300000000001165,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"update\",\n            \"attrs\": [\n              {\n                \"key\": \"table\",\n                \"value\": \"jobs\"\n              },\n              {\n                \"key\": \"set\",\n                \"value\": \"claim_session_id\"\n              }\n            ],\n            \"children\": [\n              {\n                \"name\": \"render\",\n                \"attrs\": [\n                ],\n                \"children\": [\n                  {\n                    \"name\": \"filter\",\n                    \"attrs\": [\n                      {\n                        \"key\": \"filter\",\n                        \"value\": \"NOT crdb_internal.sql_liveness_is_alive(claim_session_id)\"\n                      }\n                    ],\n                    \"children\": [\n                      {\n                        \"name\": \"scan\",\n                        \"attrs\": [\n                          {\n                            \"key\": \"missing stats\",\n                            \"value\": \"\"\n                          },\n                          {\n                            \"key\": \"table\",\n                            \"value\": \"jobs@jobs_run_stats_idx (partial index)\"\n                          },\n                          {\n                            \"key\": \"spans\",\n                            \"value\": \"2 spans\"\n                          }\n                        ],\n                        \"children\": [\n                        ]\n                      }\n                    ]\n                  }\n                ]\n              }\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.395572420Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 172,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 30720,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.395572664Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"SELECT \\\"descID\\\", version, expiration FROM system.public.lease AS OF SYSTEM TIME _ WHERE \\\"nodeID\\\" = _\",\n          \"app\": \"$ internal-read orphaned leases\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": true,\n          \"vec\": true,\n          \"fullScan\": true,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"18133561983020926484\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0.000193742,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.002054211,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.000663521,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.002917029,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.00000555499999999997,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"filter\",\n            \"attrs\": [\n              {\n                \"key\": \"filter\",\n                \"value\": \"\\\"nodeID\\\" = _\"\n              }\n            ],\n            \"children\": [\n              {\n                \"name\": \"scan\",\n                \"attrs\": [\n                  {\n                    \"key\": \"missing stats\",\n                    \"value\": \"\"\n                  },\n                  {\n                    \"key\": \"table\",\n                    \"value\": \"lease@primary\"\n                  },\n                  {\n                    \"key\": \"spans\",\n                    \"value\": \"FULL SCAN\"\n                  }\n                ],\n                \"children\": [\n                ]\n              }\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.391069335Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 504,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 12,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 10240,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.391069649Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"SELECT id, status, created, payload, progress, claim_session_id, claim_instance_id, last_run, COALESCE(num_runs, _), COALESCE(last_run, created) + least(IF((args.initial_delay * (power(_, least(_, COALESCE(num_runs, _))) - _)::FLOAT8) \\u003e= _, args.initial_delay * (power(_, least(_, COALESCE(num_runs, _))) - _)::FLOAT8, args.max_delay), args.max_delay)::INTERVAL AS next_run FROM system.jobs, (SELECT $1::FLOAT8 AS initial_delay, $2::FLOAT8 AS max_delay) AS args\",\n          \"app\": \"$ internal-crdb-internal-jobs-table\",\n          \"distSQL\": false,\n          \"failed\": true,\n          \"opt\": true,\n          \"implicitTxn\": false,\n          \"vec\": true,\n          \"fullScan\": true,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"8087194200239979783\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.000267178,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.000856371,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.001132314,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.000008764999999999988,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"context canceled\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"render\",\n            \"attrs\": [\n            ],\n            \"children\": [\n              {\n                \"name\": \"scan\",\n                \"attrs\": [\n                  {\n                    \"key\": \"missing stats\",\n                    \"value\": \"\"\n                  },\n                  {\n                    \"key\": \"table\",\n                    \"value\": \"jobs@primary\"\n                  },\n                  {\n                    \"key\": \"spans\",\n                    \"value\": \"FULL SCAN\"\n                  }\n                ],\n                \"children\": [\n                ]\n              }\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.394862263Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 20480,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.394862521Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"SELECT schedule_id FROM system.scheduled_jobs WHERE schedule_name = $1\",\n          \"app\": \"$ internal-load-sql-stats-scheduled-job\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": false,\n          \"vec\": true,\n          \"fullScan\": true,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"1879849972839045049\",\n      \"stats\": {\n        \"count\": \"1\",\n        \"firstAttemptCount\": \"1\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"planLat\": {\n          \"mean\": 0.000140147,\n          \"squaredDiffs\": 0\n        },\n        \"runLat\": {\n          \"mean\": 0.000581848,\n          \"squaredDiffs\": 0\n        },\n        \"serviceLat\": {\n          \"mean\": 0.00072678,\n          \"squaredDiffs\": 0\n        },\n        \"overheadLat\": {\n          \"mean\": 0.000004784999999999989,\n          \"squaredDiffs\": 0\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"filter\",\n            \"attrs\": [\n              {\n                \"key\": \"filter\",\n                \"value\": \"schedule_name = _\"\n              }\n            ],\n            \"children\": [\n              {\n                \"name\": \"scan\",\n                \"attrs\": [\n                  {\n                    \"key\": \"missing stats\",\n                    \"value\": \"\"\n                  },\n                  {\n                    \"key\": \"table\",\n                    \"value\": \"scheduled_jobs@primary\"\n                  },\n                  {\n                    \"key\": \"spans\",\n                    \"value\": \"FULL SCAN\"\n                  }\n                ],\n                \"children\": [\n                ]\n              }\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.384519027Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 264,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 10240,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.384519281Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    },\n    {\n      \"key\": {\n        \"keyData\": {\n          \"query\": \"INSERT INTO system.public.lease(\\\"descID\\\", version, \\\"nodeID\\\", expiration) VALUES (_, _, __more2__)\",\n          \"app\": \"$ internal-lease-insert\",\n          \"distSQL\": false,\n          \"failed\": false,\n          \"opt\": true,\n          \"implicitTxn\": false,\n          \"vec\": true,\n          \"fullScan\": false,\n          \"database\": \"\",\n          \"planHash\": \"0\"\n        },\n        \"nodeId\": 2,\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\"\n      },\n      \"id\": \"13261298787718179465\",\n      \"stats\": {\n        \"count\": \"3\",\n        \"firstAttemptCount\": \"3\",\n        \"maxRetries\": \"0\",\n        \"legacyLastErr\": \"\",\n        \"legacyLastErrRedacted\": \"\",\n        \"numRows\": {\n          \"mean\": 1,\n          \"squaredDiffs\": 0\n        },\n        \"parseLat\": {\n          \"mean\": 0.00002376,\n          \"squaredDiffs\": 1.5310562e-11\n        },\n        \"planLat\": {\n          \"mean\": 0.0014876493333333333,\n          \"squaredDiffs\": 1.3106120000266667e-7\n        },\n        \"runLat\": {\n          \"mean\": 0.000727714,\n          \"squaredDiffs\": 7.3104835358e-8\n        },\n        \"serviceLat\": {\n          \"mean\": 0.002242239,\n          \"squaredDiffs\": 2.783045912e-7\n        },\n        \"overheadLat\": {\n          \"mean\": 0.000003115666666666609,\n          \"squaredDiffs\": 1.0713946666663318e-12\n        },\n        \"sensitiveInfo\": {\n          \"lastErr\": \"\",\n          \"mostRecentPlanDescription\": {\n            \"name\": \"insert\",\n            \"attrs\": [\n              {\n                \"key\": \"into\",\n                \"value\": \"lease(descID, version, nodeID, expiration)\"\n              }\n            ],\n            \"children\": [\n              {\n                \"name\": \"values\",\n                \"attrs\": [\n                  {\n                    \"key\": \"size\",\n                    \"value\": \"4 columns, 1 row\"\n                  }\n                ],\n                \"children\": [\n                ]\n              }\n            ]\n          },\n          \"mostRecentPlanTimestamp\": \"2021-09-09T05:23:09.382596622Z\"\n        },\n        \"bytesRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"rowsRead\": {\n          \"mean\": 0,\n          \"squaredDiffs\": 0\n        },\n        \"execStats\": {\n          \"count\": \"1\",\n          \"networkBytes\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxMemUsage\": {\n            \"mean\": 10240,\n            \"squaredDiffs\": 0\n          },\n          \"contentionTime\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"networkMessages\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"maxDiskUsage\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          }\n        },\n        \"sqlType\": \"TypeDML\",\n        \"lastExecTimestamp\": \"2021-09-09T05:23:09.391374430Z\",\n        \"nodes\": [\n          \"2\"\n        ]\n      }\n    }\n  ],\n  \"lastReset\": \"2021-09-09T05:23:09.376865535Z\",\n  \"internalAppNamePrefix\": \"$ internal\",\n  \"transactions\": [\n    {\n      \"statsData\": {\n        \"statementFingerprintIds\": [\n          \"4104049045071304794\"\n        ],\n        \"app\": \"$ internal-stmt-diag-poll\",\n        \"stats\": {\n          \"count\": \"1\",\n          \"maxRetries\": \"0\",\n          \"numRows\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"serviceLat\": {\n            \"mean\": 0.008437937,\n            \"squaredDiffs\": 0\n          },\n          \"retryLat\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"commitLat\": {\n            \"mean\": 0.000033088,\n            \"squaredDiffs\": 0\n          },\n          \"bytesRead\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"rowsRead\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"execStats\": {\n            \"count\": \"0\",\n            \"networkBytes\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"maxMemUsage\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"contentionTime\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"networkMessages\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"maxDiskUsage\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            }\n          }\n        },\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\",\n        \"transactionFingerprintId\": \"10923269310096879493\"\n      },\n      \"nodeId\": 2\n    },\n    {\n      \"statsData\": {\n        \"statementFingerprintIds\": [\n          \"5582459872449769942\"\n        ],\n        \"app\": \"$ internal-expire-sessions\",\n        \"stats\": {\n          \"count\": \"1\",\n          \"maxRetries\": \"0\",\n          \"numRows\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"serviceLat\": {\n            \"mean\": 0.009384089,\n            \"squaredDiffs\": 0\n          },\n          \"retryLat\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"commitLat\": {\n            \"mean\": 0.000031541,\n            \"squaredDiffs\": 0\n          },\n          \"bytesRead\": {\n            \"mean\": 172,\n            \"squaredDiffs\": 0\n          },\n          \"rowsRead\": {\n            \"mean\": 1,\n            \"squaredDiffs\": 0\n          },\n          \"execStats\": {\n            \"count\": \"0\",\n            \"networkBytes\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"maxMemUsage\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"contentionTime\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"networkMessages\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"maxDiskUsage\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            }\n          }\n        },\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\",\n        \"transactionFingerprintId\": \"16292718201605457417\"\n      },\n      \"nodeId\": 2\n    },\n    {\n      \"statsData\": {\n        \"statementFingerprintIds\": [\n          \"18133561983020926484\"\n        ],\n        \"app\": \"$ internal-read orphaned leases\",\n        \"stats\": {\n          \"count\": \"1\",\n          \"maxRetries\": \"0\",\n          \"numRows\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"serviceLat\": {\n            \"mean\": 0.003217082,\n            \"squaredDiffs\": 0\n          },\n          \"retryLat\": {\n            \"mean\": 0,\n            \"squaredDiffs\": 0\n          },\n          \"commitLat\": {\n            \"mean\": 0.000055377,\n            \"squaredDiffs\": 0\n          },\n          \"bytesRead\": {\n            \"mean\": 504,\n            \"squaredDiffs\": 0\n          },\n          \"rowsRead\": {\n            \"mean\": 12,\n            \"squaredDiffs\": 0\n          },\n          \"execStats\": {\n            \"count\": \"0\",\n            \"networkBytes\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"maxMemUsage\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"contentionTime\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"networkMessages\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            },\n            \"maxDiskUsage\": {\n              \"mean\": 0,\n              \"squaredDiffs\": 0\n            }\n          }\n        },\n        \"aggregatedTs\": \"0001-01-01T00:00:00Z\",\n        \"transactionFingerprintId\": \"6108261809536119243\"\n      },\n      \"nodeId\": 2\n    }\n  ]\n}" does not contain "CREATE TABLE test"
        	Test:       	TestTenantGRPCServices/statements_endpoint_fans_out_request_to_multiple_pods
    --- FAIL: TestTenantGRPCServices/statements_endpoint_fans_out_request_to_multiple_pods (3.01s)

Reproduce

To reproduce, try:

make stressrace TESTS=TestTenantGRPCServices PKG=./pkg/ccl/serverccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

• GOFLAGS=-parallel=4

/cc @cockroachdb/server dhartunian

This test on roachdash | Improve this report!

Jira issue: CRDB-9872

[knz]

cc @dhartunian for triage

[dhartunian]

From reading the logs, the key moment seems to be this gap of time:

I210909 05:23:09.617581 32089 1@gossip/gossip.go:1505 â‹® [n2] 3426  node has connected to cluster via gossip
I210909 05:23:09.617730 32089 kv/kvserver/stores.go:269 â‹® [n2] 3427  wrote 2 node addresses to persistent storage
W210909 05:23:12.391015 36789 server/tenant_status.go:253 ⋮ [tenant=‹10›,tenant-status] 3428  fan out statements request recorded error from node ‹1›: failed to dial into node ‹1›: ‹operation "dial instance" timed out after 3s›: context deadline exceeded

The nodes seem OK around 05:23:09 and then 05:23:12 3 seconds later we have a "dial instance" timeout error.

[dhartunian]

@Azhng I saw this PR #69346 which set the SQLStatsKnobs on one of the tenants in tenant_grpc_test.go. However, the test starts a second tenant later in the test (without this knob set) and runs the stats request against it. Could it possibly cause the timeout I'm seeing here? Either way, it seems like I should set this knob for tenant2, right?
(https://github.com/cockroachdb/cockroach/blob/7b3dba066d35574db1eddc1b8a4a9171a4d5ea27/pkg/ccl/serverccl/tenant_grpc_test.go)

[Azhng]

Ah yes, the knobs should be set for each tenant. Though I doubt it would be the source of the error. If it is caused by SQL Stats, you would usually see logs messages like "descriptor not found" etc, which is missing from the logs artifacts as far as i can tell.

[dhartunian]

Fixed by #70231