sql: hang during prepared query within a transaction

[jordanlewis]

In certain circumstances, CockroachDB hangs in the prepare phase of a prepared query issued within a transaction with the following message:

W170207 15:58:47.927343 474 storage/intent_resolver.go:338  [n1,s1,r2/1:/Table/{0-11}]: failed to push during intent resolution: failed to push "sql txn" id=238f76c2 key=/Table/0/0 rw=true pri=0.00448213 iso=SERIALIZABLE stat=PENDING epo=0 ts=1486501122.920946180,0 orig=1486501122
.920946180,0 max=1486501122.920946180,0 wto=false rop=false

This was discovered while investigating ActiveRecord compatibility, which issues several such queries. A complete log of a hang of this sort caused by ActiveRecord is in this gist.

I've created a test that reliably reproduces the hang here. In summary, the test issues the following statements outside of a transaction:

CREATE TABLE "schema_migrations" ("version" character varying NOT NULL);
CREATE UNIQUE INDEX  "unique_schema_migrations" ON "schema_migrations" ("version");

And then, within a transaction, prepares and immediately executes the statement and query below:

CREATE TABLE "test" ("created_at" timestamp NOT NULL, "updated_at" timestamp NOT NULL);
SELECT attr.attname
    FROM pg_attribute attr
    INNER JOIN pg_constraint cons
    ON attr.attrelid = cons.conrelid AND attr.attnum = any(cons.conkey)
    WHERE cons.conrelid = 'schema_migrations'::regclass;

The hang occurs during the preparation of the SELECT query before it is executed or the transaction is committed.

This is more or less a minimal reproduction - removing either of the fields in the table or reducing the join conditions or filter further prevents the hang from occurring.

[andreimatei]

Does it hang forever, or does something keep being retried?
Do you know / can you find out what the intent push txn is doing (and also the pushee, for that matter)? If it's in the prepare phase, I'm guessing it has to do with getting a table descriptor.

--verbosity=3 might help.

[jordanlewis]

The failure message I included does repeat ad infinitum.

I'm not quite sure what I'm looking at, but the relevant logs from --verbosity=3 seem to be the following. Is this helpful?

I170207 16:53:40.802637 116 storage/replica_command.go:1418  [n1,s1,r2/1:/Table/{0-11},@c42049c900] failed to push "sql txn" id=64e94f3e key=/Table/0/0 rw=true pri=0.02787802 iso=SERIALIZABLE stat=PENDING epo=0 ts=1486504390.775641649,0 orig=1486504390.775641649,0 max=1486504390.775641649,0 wto=false rop=false
I170207 16:53:40.802810 116 storage/replica_command.go:203  [n1,s1,r2/1:/Table/{0-11},@c42049c900] executed PushTxn command header:<key:"\210\210" > pusher_txn:<meta:<isolation:SERIALIZABLE epoch:0 timestamp:<wall_time:0 logical:0 > priority:97009 sequence:0 batch_index:0 > name:"" status:PENDING orig_timestamp:<wall_time:0 logical:0 > max_timestamp:<wall_time:0 logical:0 > writing:false write_too_old:false retry_on_push:false > pushee_txn:<id:<64e94f3e-6934-4a09-b3ac-04af229713db> isolation:SERIALIZABLE key:"\210\210" epoch:0 timestamp:<wall_time:1486504390775641649 logical:0 > priority:598676 sequence:7 batch_index:0 > push_to:<wall_time:1486504420801479813 logical:0 > now:<wall_time:1486504420801560007 logical:0 > push_type:PUSH_TOUCH : header:<num_keys:0 > pushee_txn:<meta:<id:<64e94f3e-6934-4a09-b3ac-04af229713db> isolation:SERIALIZABLE key:"\210\210" epoch:0 timestamp:<wall_time:1486504390775641649 logical:0 > priority:598676 sequence:6 batch_index:0 > name:"sql txn" status:PENDING last_heartbeat:<wall_time:1486504420791854889 logical:0 > orig_timestamp:<wall_time:1486504390775641649 logical:0 > max_timestamp:<wall_time:1486504390775641649 logical:0 > observed_timestamps:<key:1 value:<wall_time:1486504390775641649 logical:0 > > writing:true write_too_old:false retry_on_push:false > , err=failed to push "sql txn" id=64e94f3e key=/Table/0/0 rw=true pri=0.02787802 iso=SERIALIZABLE stat=PENDING epo=0 ts=1486504390.775641649,0 orig=1486504390.775641649,0 max=1486504390.775641649,0 wto=false rop=false
I170207 16:53:40.803507 619 kv/dist_sender.go:1175  [n1] RPC reply: (err: failed to push "sql txn" id=64e94f3e key=/Table/0/0 rw=true pri=0.02787802 iso=SERIALIZABLE stat=PENDING epo=0 ts=1486504390.775641649,0 orig=1486504390.775641649,0 max=1486504390.775641649,0 wto=false rop=false)
I170207 16:53:40.803549 619 internal/client/db.go:524  failed batch: failed to push "sql txn" id=64e94f3e key=/Table/0/0 rw=true pri=0.02787802 iso=SERIALIZABLE stat=PENDING epo=0 ts=1486504390.775641649,0 orig=1486504390.775641649,0 max=1486504390.775641649,0 wto=false rop=false
W170207 16:53:40.803874 619 storage/intent_resolver.go:338  [n1,s1,r2/1:/Table/{0-11}]: failed to push during intent resolution: failed to push "sql txn" id=64e94f3e key=/Table/0/0 rw=true pri=0.02787802 iso=SERIALIZABLE stat=PENDING epo=0 ts=1486504390.775641649,0 orig=1486504390.775641649,0 max=1486504390.775641649,0 wto=false rop=false

[vivekmenezes]

This issue seems similar to #14548 . assigning to @jordanlewis to close

[jordanlewis]

Yes, this is fixed now.