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

sql/scheduledlogging: TestCaptureIndexUsageStats failed #110617

Closed
cockroach-teamcity opened this issue Sep 14, 2023 · 0 comments · Fixed by #110639
Closed

sql/scheduledlogging: TestCaptureIndexUsageStats failed #110617

cockroach-teamcity opened this issue Sep 14, 2023 · 0 comments · Fixed by #110639
Assignees
@maryliag
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. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked.
Milestone
23.2

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Sep 14, 2023 •
edited by cockroach-jira-scripts
Loading

sql/scheduledlogging.TestCaptureIndexUsageStats failed with artifacts on master @ 746273784cd809442ca65dc50012c58794e39cc8:

    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719104000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719103638,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":2,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.580922 +0000 UTC","SchemaName":"public"} nsql1 16 true TELEMETRY 326 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719086000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719085452,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":1,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.108553 +0000 UTC","SchemaName":"public"} nsql1 15 true TELEMETRY 334 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719068000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719067745,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":2,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.137695 +0000 UTC","SchemaName":"public"} nsql1 14 true TELEMETRY 323 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719053000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719052449,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":1,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.094073 +0000 UTC","SchemaName":"public"} nsql1 13 true TELEMETRY 331 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719037000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719036489,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":2,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"IdX✏","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.886968 +0000 UTC","SchemaName":"public"} nsql1 12 true TELEMETRY 329 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719014000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719013028,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":1,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"sPe-CiAl✔_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.118176 +0000 UTC","SchemaName":"public"} nsql1 11 true TELEMETRY 353 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600718981000 4732 util/log/event_log.go 32 {"Timestamp":1694649600718980537,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":2,"DatabaseName":"index","TableName":"index","IndexName":"index","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:53.217158 +0000 UTC","SchemaName":"public"} nsql1 10 true TELEMETRY 303 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600718934000 4732 util/log/event_log.go 32 {"Timestamp":1694649600718930174,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":1,"DatabaseName":"index","TableName":"index","IndexName":"index_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.127195 +0000 UTC","SchemaName":"public"} nsql1 9 true TELEMETRY 322 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589118000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589117604,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":2,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.580922 +0000 UTC","SchemaName":"public"} nsql1 8 true TELEMETRY 326 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589110000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589110571,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":1,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.108553 +0000 UTC","SchemaName":"public"} nsql1 7 true TELEMETRY 334 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589103000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589103581,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":2,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.137695 +0000 UTC","SchemaName":"public"} nsql1 6 true TELEMETRY 323 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589098000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589097865,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":1,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.094073 +0000 UTC","SchemaName":"public"} nsql1 5 true TELEMETRY 331 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589092000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589091563,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":2,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"IdX✏","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.886968 +0000 UTC","SchemaName":"public"} nsql1 4 true TELEMETRY 329 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589083000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589082880,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":1,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"sPe-CiAl✔_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.118176 +0000 UTC","SchemaName":"public"} nsql1 3 true TELEMETRY 353 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589059000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589053158,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":2,"DatabaseName":"index","TableName":"index","IndexName":"index","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:53.217158 +0000 UTC","SchemaName":"public"} nsql1 2 true TELEMETRY 303 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649595661827000 4732 util/log/event_log.go 32 {"Timestamp":1694649595661822893,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":1,"DatabaseName":"index","TableName":"index","IndexName":"index_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.127195 +0000 UTC","SchemaName":"public"} nsql1 1 true TELEMETRY 322 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:342: found index counts: map[IdX✏:2 index:2 index_pkey:2 sPe-CiAl✔_pkey:2 test2_table_letter_idx:2 test2_table_pkey:2 test_table_letter_idx:2 test_table_pkey:2]
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447272000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447271735,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":2,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.580922 +0000 UTC","SchemaName":"public"} nsql1 24 true TELEMETRY 326 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447256000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447255897,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":1,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.108553 +0000 UTC","SchemaName":"public"} nsql1 23 true TELEMETRY 334 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447239000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447239109,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":2,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.137695 +0000 UTC","SchemaName":"public"} nsql1 22 true TELEMETRY 323 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447227000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447226536,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":1,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.094073 +0000 UTC","SchemaName":"public"} nsql1 21 true TELEMETRY 331 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447214000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447213731,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":2,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"IdX✏","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.886968 +0000 UTC","SchemaName":"public"} nsql1 20 true TELEMETRY 329 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447199000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447197573,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":1,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"sPe-CiAl✔_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.118176 +0000 UTC","SchemaName":"public"} nsql1 19 true TELEMETRY 353 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447181000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447180601,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":2,"DatabaseName":"index","TableName":"index","IndexName":"index","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:53.217158 +0000 UTC","SchemaName":"public"} nsql1 18 true TELEMETRY 303 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649604447143000 4732 util/log/event_log.go 32 {"Timestamp":1694649604447138889,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":1,"DatabaseName":"index","TableName":"index","IndexName":"index_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.127195 +0000 UTC","SchemaName":"public"} nsql1 17 true TELEMETRY 322 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719104000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719103638,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":2,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.580922 +0000 UTC","SchemaName":"public"} nsql1 16 true TELEMETRY 326 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719086000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719085452,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":1,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.108553 +0000 UTC","SchemaName":"public"} nsql1 15 true TELEMETRY 334 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719068000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719067745,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":2,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.137695 +0000 UTC","SchemaName":"public"} nsql1 14 true TELEMETRY 323 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719053000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719052449,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":1,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.094073 +0000 UTC","SchemaName":"public"} nsql1 13 true TELEMETRY 331 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719037000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719036489,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":2,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"IdX✏","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.886968 +0000 UTC","SchemaName":"public"} nsql1 12 true TELEMETRY 329 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600719014000 4732 util/log/event_log.go 32 {"Timestamp":1694649600719013028,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":1,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"sPe-CiAl✔_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.118176 +0000 UTC","SchemaName":"public"} nsql1 11 true TELEMETRY 353 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600718981000 4732 util/log/event_log.go 32 {"Timestamp":1694649600718980537,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":2,"DatabaseName":"index","TableName":"index","IndexName":"index","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:53.217158 +0000 UTC","SchemaName":"public"} nsql1 10 true TELEMETRY 303 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649600718934000 4732 util/log/event_log.go 32 {"Timestamp":1694649600718930174,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":1,"DatabaseName":"index","TableName":"index","IndexName":"index_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.127195 +0000 UTC","SchemaName":"public"} nsql1 9 true TELEMETRY 322 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589118000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589117604,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":2,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.580922 +0000 UTC","SchemaName":"public"} nsql1 8 true TELEMETRY 326 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589110000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589110571,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":113,"IndexID":1,"DatabaseName":"test2","TableName":"test2_table","IndexName":"test2_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.108553 +0000 UTC","SchemaName":"public"} nsql1 7 true TELEMETRY 334 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589103000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589103581,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":2,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_letter_idx","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.137695 +0000 UTC","SchemaName":"public"} nsql1 6 true TELEMETRY 323 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589098000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589097865,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":112,"IndexID":1,"DatabaseName":"test","TableName":"test_table","IndexName":"test_table_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.094073 +0000 UTC","SchemaName":"public"} nsql1 5 true TELEMETRY 331 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589092000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589091563,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":2,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"IdX✏","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:52.886968 +0000 UTC","SchemaName":"public"} nsql1 4 true TELEMETRY 329 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589083000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589082880,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":114,"IndexID":1,"DatabaseName":"\"mIxEd-CaSe\"\"woo☃\"","TableName":"sPe-CiAl✔","IndexName":"sPe-CiAl✔_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.118176 +0000 UTC","SchemaName":"public"} nsql1 3 true TELEMETRY 353 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649596589059000 4732 util/log/event_log.go 32 {"Timestamp":1694649596589053158,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":2,"DatabaseName":"index","TableName":"index","IndexName":"index","IndexType":"secondary","CreatedAt":"2023-09-13 23:59:53.217158 +0000 UTC","SchemaName":"public"} nsql1 2 true TELEMETRY 303 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:326: checking entry: {INFO 1694649595661827000 4732 util/log/event_log.go 32 {"Timestamp":1694649595661822893,"EventType":"captured_index_usage_stats","LastRead":"0001-01-01 00:00:00 +0000 UTC","TableID":115,"IndexID":1,"DatabaseName":"index","TableName":"index","IndexName":"index_pkey","IndexType":"primary","IsUnique":true,"CreatedAt":"2023-09-13 23:59:52.127195 +0000 UTC","SchemaName":"public"} nsql1 1 true TELEMETRY 322 0 0 10 tenant-10}
    captured_index_usage_stats_test.go:342: found index counts: map[IdX✏:3 index:3 index_pkey:3 sPe-CiAl✔_pkey:3 test2_table_letter_idx:3 test2_table_pkey:3 test_table_letter_idx:3 test_table_pkey:3]
    captured_index_usage_stats_test.go:288: 
        	Error Trace:	github.com/cockroachdb/cockroach/pkg/sql/scheduledlogging/captured_index_usage_stats_test.go:288
        	Error:      	"1s" is not greater than "1.057107s"
        	Test:       	TestCaptureIndexUsageStats
        	Messages:   	1s <= 5.057107s-4s
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/69cc8b5ff8b35dcd9569961cf48105ef/logTestCaptureIndexUsageStats354847578
--- FAIL: TestCaptureIndexUsageStats (17.02s)
Help

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

/cc @cockroachdb/cluster-observability

This test on roachdash | Improve this report!

Jira issue: CRDB-31526
@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. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-cluster-observability labels Sep 14, 2023
@cockroach-teamcity cockroach-teamcity added this to the 23.2 milestone Sep 14, 2023
maryliag added a commit to maryliag/cockroach that referenced this issue Sep 14, 2023
@maryliag
sql: increase buffer on TestCaptureIndexUsageStats
f774b6d 
Tests can take longer to be completed, so a bigger time buffer
would be required to accomodate for the non-determinism in
the logging timings. This time buffer has been increasing every
couple of months and it would have to change to 5s now, which is
a big buffer compared to the actual value of 1s. The time it takes
is not really relevant for this test, as long as the schedules
are happening one after the other. So instead of increasing
the time buffer even more, this commit updates the test to confirm
that both the expected (which is calculated) and the actual value
are great or equal 0. This way the test is no longer flaky or would need
to be adjusted every few months, and we keep all the actual checks
important for the test.

Fixes cockroachdb#110617

Release note: None
@maryliag maryliag self-assigned this Sep 14, 2023
@maryliag maryliag mentioned this issue Sep 14, 2023
Merged
craig bot pushed a commit that referenced this issue Sep 15, 2023
@maryliag
Merge #110639
c3e6bb2 
110639: sql: fix TestCaptureIndexUsageStats r=maryliag a=maryliag

Tests can take longer to be completed, so a bigger time buffer
would be required to accomodate for the non-determinism in
the logging timings. This time buffer has been increasing every
couple of months and it would have to change to 5s now, which is
a big buffer compared to the actual value of 1s. The time it takes
is not really relevant for this test, as long as the schedules
are happening one after the other.
So instead of increasing the time buffer even more, this commit
removes those checks. This way the test is no longer flaky or would need
to be adjusted every few months, and we keep all the actual checks
important for the test.

Fixes #110617

Release note: None

Co-authored-by: maryliag <[email protected]>
@craig craig bot closed this as completed in b45ba50 Sep 15, 2023
@blathers-crl blathers-crl bot mentioned this issue Sep 15, 2023
Merged
blathers-crl bot pushed a commit that referenced this issue Sep 15, 2023
@maryliag
sql: fix TestCaptureIndexUsageStats
1ebfb93 
Tests can take longer to be completed, so a bigger time buffer
would be required to accomodate for the non-determinism in
the logging timings. This time buffer has been increasing every
couple of months and it would have to change to 5s now, which is
a big buffer compared to the actual value of 1s. The time it takes
is not really relevant for this test, as long as the schedules
are happening one after the other.
So instead of increasing the time buffer even more, this commit
removes those checks. This way the test is no longer flaky or would need
to be adjusted every few months, and we keep all the actual checks
important for the test.

Fixes #110617

Release note: None
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@maryliag maryliag

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. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked.
Projects
None yet
Milestone
23.2
Development

Successfully merging a pull request may close this issue.

sql: fix TestCaptureIndexUsageStats maryliag/cockroach
2 participants
@maryliag @cockroach-teamcity