teamcity: failed test: TestDefaultColumns

[cockroach-teamcity]

The following tests appear to have failed on master (testrace): TestDefaultColumns

You may want to check for open issues.

#1366551:

TestDefaultColumns
...90629 05:33:06.487062 5359 sql/event_log.go:130  [n1,client=127.0.0.1:58974,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:108}
I190629 05:33:06.595038 4884 gossip/gossip.go:559  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
gossip connectivity
  n1 [sentinel];
I190629 05:33:06.598740 4887 server/status/runtime.go:498  [n1] runtime stats: 913 MiB RSS, 186 goroutines, 101 MiB/13 MiB/137 MiB GO alloc/idle/total, 40 MiB/79 MiB CGO alloc/total, 2051.3 CGO/sec, 102.1/9.1 %(u/s)time, 0.2 %gc (3x), 1.4 MiB/1.4 MiB (r/w)net
I190629 05:33:06.599700 5359 sql/sqlbase/structured.go:1148  [n1,client=127.0.0.1:58974,user=root] publish: descID=53 (a) version=326 mtime=2019-06-29 05:33:06.547504959 +0000 UTC
I190629 05:33:06.649610 5359 sql/event_log.go:130  [n1,client=127.0.0.1:58974,user=root] Event: "alter_table", target: 53, info: {TableName:t.public.a Statement:ALTER TABLE t.a ADD COLUMN c109 INT8 User:root MutationID:109 CascadeDroppedViews:[]}
I190629 05:33:06.834280 4852 storage/queue.go:525  [n1,s1,r7/1:/Table/1{1-2}] rate limited in MaybeAdd (merge): context canceled
I190629 05:33:06.941300 5359 sql/sqlbase/structured.go:1148  [n1,client=127.0.0.1:58974,user=root,scExec] publish: descID=53 (a) version=327 mtime=2019-06-29 05:33:06.939731205 +0000 UTC
I190629 05:33:07.057727 5359 sql/lease.go:327  [n1,client=127.0.0.1:58974,user=root,scExec] waiting for 1 leases to expire: desc=[{a 53 326}]
I190629 05:33:07.059803 34652 sql/lease.go:916  new lease: 53("a") ver=327:1561786700.503114169,0, refcount=0
I190629 05:33:07.210441 5359 sql/backfill.go:141  [n1,client=127.0.0.1:58974,user=root,scExec] Running backfill for "a", v=327, m=109
I190629 05:33:07.280692 5359 sql/sqlbase/structured.go:1148  [n1,client=127.0.0.1:58974,user=root,scExec] publish: descID=53 (a) version=328 mtime=2019-06-29 05:33:07.276186881 +0000 UTC
I190629 05:33:07.426294 5359 sql/event_log.go:130  [n1,client=127.0.0.1:58974,user=root,scExec] Event: "finish_schema_change", target: 53, info: {MutationID:109}
I190629 05:33:07.472533 34509 sql/lease.go:916  new lease: 53("a") ver=328:1561786700.504114169,0, refcount=0
I190629 05:33:07.485696 5359 sql/lease.go:327  [n1,client=127.0.0.1:58974,user=root,scExec] waiting for 1 leases to expire: desc=[{a 53 327}]
I190629 05:33:14.662321 4640 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] transport racer
1      [async] storage.IntentResolver: cleanup txn records
1      [async] intent_resolver_ir_batcher
1      [async] intent_resolver_gc_batcher
1      [async] closedts-rangefeed-subscriber
I190629 05:33:14.662948 4640 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] transport racer
1      [async] storage.IntentResolver: cleanup txn records
1      [async] intent_resolver_ir_batcher
1      [async] closedts-rangefeed-subscriber
W190629 05:33:14.663167 35287 storage/intentresolver/intent_resolver.go:816  failed to gc transaction record: could not GC completed transaction anchored at /Table/20/1/53/464374949331632129/0: node unavailable; try another peer
I190629 05:33:14.663347 4640 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] transport racer
1      [async] intent_resolver_ir_batcher
1      [async] closedts-rangefeed-subscriber
I190629 05:33:14.663509 4640 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] transport racer
1      [async] closedts-rangefeed-subscriber
I190629 05:33:14.663627 4897 kv/transport_race.go:108  transport race promotion: ran 162 iterations on up to 18327 requests
I190629 05:33:14.677933 4640 util/stop/stopper.go:542  quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
    automatic_stats_test.go:433: query 'SELECT count(*) FROM [SHOW STATISTICS FOR TABLE t.a] WHERE statistics_name = 's'': expected:
        101
        
        got:
        41
        

Please assign, take a look and update the issue accordingly.

[rytaft]

This is very odd. I cannot reproduce this running either make stress PKG=./pkg/sql/stats/... TESTS='TestDefaultColumns' or make stressrace PKG=./pkg/sql/stats/... TESTS='TestDefaultColumns' for a while. If there is a bug I don't think it's in the stats code, since this function is testing something that should be quite deterministic. Any ideas would be appreciated!

[RaduBerinde]

Since we haven't seen it again in a very long time, let's close.