teamcity: show_trace logic test fails due to unexpected txn push

[cockroach-teamcity]

The following tests appear to have failed on master (test): TestLogic/local: TestLogic/local/show_trace, TestLogic/local, TestLogic

You may want to check for open issues.

#1092793:

TestLogic/local: TestLogic/local/show_trace
--- FAIL: test/TestLogic: TestLogic/local: TestLogic/local/show_trace (1.830s)
logic.go:2301: 
	 
	testdata/logic_test/show_trace:280: SELECT operation, regexp_replace(message, '(\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d\.)?\d\d\d\d\d+', '...PK...') as message
	  FROM [SHOW KV TRACE FOR SESSION]
	WHERE message NOT LIKE '%Z/%'
	  AND tag NOT LIKE '%intExec=%'
	  AND tag NOT LIKE '%scExec%'
	  AND tag NOT LIKE '%IndexBackfiller%'
	expected:
	    dist sender send  querying next range at /Table/2/1/53/"kv2"/3/1
	    dist sender send  r6: sending batch 1 Get to (n1,s1):1
	    dist sender send  querying next range at /Table/3/1/55/2/1
	    dist sender send  r6: sending batch 1 Get to (n1,s1):1
	    dist sender send  r7: sending batch 1 EndTxn, 1 QueryIntent to (n1,s1):1
	    sql txn           Scan /Table/55/{1-2}
	    dist sender send  querying next range at /Table/55/1
	    dist sender send  r20: sending batch 1 Scan to (n1,s1):1
	    sql txn           fetched: /kv2/primary/...PK.../k/v -> /1/2
	    sql txn           Put /Table/55/1/...PK.../0 -> /TUPLE/1:1:Int/1/1:2:Int/4
	    sql txn           fetched: /kv2/primary/...PK.../k/v -> /2/3
	    sql txn           Put /Table/55/1/...PK.../0 -> /TUPLE/1:1:Int/2/1:2:Int/5
	    dist sender send  querying next range at /Table/55/1/...PK.../0
	    dist sender send  r20: sending batch 2 Put, 1 EndTxn to (n1,s1):1
	    sql txn           fast path completed
	    sql txn           rows affected: 2
	    
	but found (query options: "") :
	    dist sender send  querying next range at /Table/2/1/53/"kv2"/3/1
	    dist sender send  r6: sending batch 1 Get to (n1,s1):1
	    dist sender send  querying next range at /Table/3/1/55/2/1
	    dist sender send  r6: sending batch 1 Get to (n1,s1):1
	    dist sender send  r7: sending batch 1 EndTxn, 1 QueryIntent to (n1,s1):1
	    sql txn           Scan /Table/55/{1-2}
	    dist sender send  querying next range at /Table/55/1
	    dist sender send  r20: sending batch 1 Scan to (n1,s1):1
	    dist sender send  querying next range at /Table/SystemConfigSpan/Start
	    dist sender send  r6: sending batch 1 PushTxn to (n1,s1):1
	    dist sender send  querying next range at /Table/55/1/...PK.../0
	    dist sender send  r20: sending batch 2 ResolveIntent to (n1,s1):1
	    sql txn           fetched: /kv2/primary/...PK.../k/v -> /1/2
	    sql txn           Put /Table/55/1/...PK.../0 -> /TUPLE/1:1:Int/1/1:2:Int/4
	    sql txn           fetched: /kv2/primary/...PK.../k/v -> /2/3
	    sql txn           Put /Table/55/1/...PK.../0 -> /TUPLE/1:1:Int/2/1:2:Int/5
	    dist sender send  querying next range at /Table/55/1/...PK.../0
	    dist sender send  r20: sending batch 2 Put, 1 EndTxn to (n1,s1):1
	    sql txn           fast path completed
	    sql txn           rows affected: 2
	    
	
logic.go:2333: 
	testdata/logic_test/show_trace:305: error while processing
logic.go:2334: testdata/logic_test/show_trace:305: too many errors encountered, skipping the rest of the input
------- Stdout: -------
=== PAUSE TestLogic/local/show_trace



TestLogic
--- FAIL: test/TestLogic (366.430s)
test_log_scope.go:81: test logs captured to: /tmp/logTestLogic558571843
test_log_scope.go:62: use -show-logs to present logs inline



TestLogic/local
--- FAIL: test/TestLogic: TestLogic/local (0.420s)

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

[jordanlewis]

@nvanbenschoten @andreimatei the problem here is that there's an extra PushTxn. What's the right thing to do?

[andreimatei]

I guess the right thing to do is... start logging to see what that intent is, and then take it from there. As long as all intents are on one range (as I guess they should be for that small table), each commit shouldn't leave intents behind. But maybe the intent that the update is running into is around the schema (which I guess would also be indicated by the preceding querying next range at /Table/SystemConfigSpan/Start line.
Or bisect and see where it started being flaky and blame that loser. I can't say I really want the issue at the moment :)

[tbg]

If the txn isn't 1pc, the intent can be observed by others, and if that's true there can be a push if the txn record is gced before the waiter observes it. I haven't looked at the flake in detail but maybe that explains something.

…

On Tue, Jan 15, 2019, 19:01 Andrei Matei ***@***.*** wrote: I guess the right thing to do is... start logging to see what that intent is, and then take it from there. As long as all intents are on one range (as I guess they should be for that small table), each commit shouldn't leave intents behind. But maybe the intent that the update is running into is around the schema (which I guess would also be indicated by the preceding querying next range at /Table/SystemConfigSpan/Start line. Or bisect and see where it started being flaky and blame that loser. I can't say I really want the issue at the moment :) — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#33720 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AE135LbiKIlbD-EOzxB8ePL-J2YB4p1_ks5vDheEgaJpZM4Z_nn0> .

[knz]

what's the key /Table/SystemConfigSpan/Start? why was there a scan at that key? Is this expected in a txn push scenario?

[andreimatei]

(I don't think we're supposed to change issue titles for test flakes cause then TC will open new issues. Right?)

SystemConfigSpan/Start is the anchor key schema change transactions. So what I think happened here is that the update with the bad trace ran into an intent left over from the previous create table ... as... txn.
And I now realize that that's a multi-range txn (artificially so, since it needs to be anchored at on the SystemConfigSpan since it's a schema change and those need to gossip the SystemConfigSpan and I think they do it in a really bad way) and so I guess it's not unexpected for it to leave intents around since their cleanup is async (I don't know why Tobi brought in the txn record GC; I don't think that plays a role).
And so I think this failure simply tells us that the async cleanup was slow.
Unclear to me what to do about it. Have I told you I hate these trace tests yet? :)

[tbg]

That sounds reasonable (when I wrote my comment, I hadn't looked into the failure mode). The test could run the same query once without the trace to clean up any errant intents, assuming it is guaranteed that the schema change txn is done at that point. Of course that's just a band aid, tests of that kind are bound to be flaky.

[andreimatei]

I don't know what to do here other than delete the test.
passing to @knz