{"action":"created","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/5559","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/5559/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/5559/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/5559/events","html_url":"https://github.com/cockroachdb/cockroach/issues/5559","id":143386335,"number":5559,"title":"timeout in sql TestLogic, txn:197","user":{"login":"RaduBerinde","id":16544120,"avatar_url":"https://avatars.githubusercontent.com/u/16544120?v=3","gravatar_id":"","url":"https://api.github.com/users/RaduBerinde","html_url":"https://github.com/RaduBerinde","followers_url":"https://api.github.com/users/RaduBerinde/followers","following_url":"https://api.github.com/users/RaduBerinde/following{/other_user}","gists_url":"https://api.github.com/users/RaduBerinde/gists{/gist_id}","starred_url":"https://api.github.com/users/RaduBerinde/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/RaduBerinde/subscriptions","organizations_url":"https://api.github.com/users/RaduBerinde/orgs","repos_url":"https://api.github.com/users/RaduBerinde/repos","events_url":"https://api.github.com/users/RaduBerinde/events{/privacy}","received_events_url":"https://api.github.com/users/RaduBerinde/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2016-03-24T23:24:08Z","updated_at":"2016-03-25T03:53:04Z","closed_at":null,"body":"https://circleci.com/gh/cockroachdb/cockroach/15215\r\n\r\nhttps://circle-artifacts.com/gh/cockroachdb/cockroach/15215/artifacts/0/tmp/circle-artifacts.EVY4hXL/test.log\r\nDelays in this test: https://github.com/cockroachdb/cockroach/blob/master/sql/testdata/txn\r\n\r\nWe have a transaction that apparently gets stuck due to an earlier, aborted txn.\r\n```\r\nBEGIN TRANSACTION\r\nUPDATE kv SET v = 'b' WHERE k in ('a')\r\nBEGIN TRANSACTION    <-- error here as expected\r\n...\r\nROLLBACK TRANSACTION\r\n... some unrelated stuff ...\r\n\r\nBEGIN TRANSACTION\r\nUPDATE kv SET v = 'b' WHERE k in ('a')      <--- this gets stuck until the test times out some 40 seconds later\r\n```\r\n\r\n\r\n\r\n```\r\ntestdata/txn:197 root: UPDATE kv SET v = 'b' WHERE k in ('a')\r\nI160324 22:11:13.051400 storage/replica_command.go:1086  failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nW160324 22:11:13.051738 kv/dist_sender.go:676  failed to invoke PushTxn [/Table/51/1/\"a\"/2/1,/Min): txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.02541374 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nI160324 22:11:13.051869 client/db.go:457  failed batch: txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.08630948 iso=SERIALIZABLE stat=PENDING epo=1 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nI160324 22:11:13.051924 storage/intent_resolver.go:99  [node=1,store=1,range=1] on Scan: txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.08630948 iso=SERIALIZABLE stat=PENDING epo=1 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nW160324 22:11:13.051983 storage/store.go:1671  conflicting intents on [/Table/51/1/\"a\"/2/1]: resolved? false\r\nI160324 22:11:13.102662 storage/replica_command.go:1086  failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nW160324 22:11:13.103171 kv/dist_sender.go:676  failed to invoke PushTxn [/Table/51/1/\"a\"/2/1,/Min): txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.02541374 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nI160324 22:11:13.103354 client/db.go:457  failed batch: txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.03228220 iso=SERIALIZABLE stat=PENDING epo=1 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nI160324 22:11:13.103453 storage/intent_resolver.go:99  [node=1,store=1,range=1] on Scan: txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.03228220 iso=SERIALIZABLE stat=PENDING epo=1 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nW160324 22:11:13.103514 storage/store.go:1671  conflicting intents on [/Table/51/1/\"a\"/2/1]: resolved? false\r\nI160324 22:11:13.210310 storage/replica_command.go:1086  failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\nW160324 22:11:13.210829 kv/dist_sender.go:676  failed to invoke PushTxn [/Table/51/1/\"a\"/2/1,/Min): txn \"sql/executor.go:380 sql txn\" id=e4cfa1bb key=/Min rw=false pri=0.02541374 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.050232167,0 orig=1458857473.050232167,0 max=1458857473.050232167,0 wto=false failed to push \"sql/executor.go:380 sql txn\" id=c82252c9 key=/Table/51/1/\"a\"/2/1 rw=true pri=0.03126385 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458857473.046150991,0 orig=1458857473.046150991,0 max=1458857473.046150991,0 wto=false\r\n```\r\n\r\n\r\nThis is the same issue noticed in https://github.com/cockroachdb/cockroach/issues/5376#issuecomment-198805820"},"comment":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/comments/201125021","html_url":"https://github.com/cockroachdb/cockroach/issues/5559#issuecomment-201125021","issue_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/5559","id":201125021,"user":{"login":"spencerkimball","id":6147149,"avatar_url":"https://avatars.githubusercontent.com/u/6147149?v=3","gravatar_id":"","url":"https://api.github.com/users/spencerkimball","html_url":"https://github.com/spencerkimball","followers_url":"https://api.github.com/users/spencerkimball/followers","following_url":"https://api.github.com/users/spencerkimball/following{/other_user}","gists_url":"https://api.github.com/users/spencerkimball/gists{/gist_id}","starred_url":"https://api.github.com/users/spencerkimball/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/spencerkimball/subscriptions","organizations_url":"https://api.github.com/users/spencerkimball/orgs","repos_url":"https://api.github.com/users/spencerkimball/repos","events_url":"https://api.github.com/users/spencerkimball/events{/privacy}","received_events_url":"https://api.github.com/users/spencerkimball/received_events","type":"User","site_admin":false},"created_at":"2016-03-25T03:53:04Z","updated_at":"2016-03-25T03:53:04Z","body":"The problem is that the SQL layer is never sending an `EndTransaction` for the transaction it does start, which then conflicts with statements later in the test. I'll illustrate what the KV layer is receiving and leave it to someone else to figure out why we're not handling the \"there is already a transaction in progress error\":\r\n\r\n```\r\n# BEGIN in the middle of a transaction is an error.\r\n\r\nstatement ok\r\nBEGIN TRANSACTION\r\n\r\nstatement ok\r\nUPDATE kv SET v = 'b' WHERE k in ('a')\r\n\r\nI160324 23:40:16.519851 storage/replica_command.go:185  *roachpb.ScanRequest request from txn 218f2dea: %!s(<nil>)\r\nI160324 23:40:16.521117 storage/replica_command.go:185  *roachpb.BeginTransactionRequest request from txn 218f2dea: %!s(<nil>)\r\nI160324 23:40:16.521215 storage/replica_command.go:185  *roachpb.PutRequest request from txn 218f2dea: %!s(<nil>)\r\n\r\nstatement error there is already a transaction in progress\r\nBEGIN TRANSACTION\r\n\r\nstatement error current transaction is aborted, commands ignored until end of transaction block\r\nSELECT * FROM kv\r\n----\r\n\r\n*Nothing executed here*\r\n\r\nstatement ok\r\nROLLBACK TRANSACTION\r\n\r\n# An empty transaction is allowed.\r\n\r\nstatement ok\r\nBEGIN; COMMIT\r\n\r\n# END is same as commit\r\nstatement ok\r\nBEGIN; END\r\n\r\n# COMMIT/ROLLBACK without a transaction are errors.\r\n\r\nstatement error there is no transaction in progress\r\nCOMMIT TRANSACTION\r\n\r\nstatement error there is no transaction in progress\r\nROLLBACK TRANSACTION\r\n\r\n# Set isolation level without a transaction is an error.\r\n\r\nstatement error there is no transaction in progress\r\nSET TRANSACTION ISOLATION LEVEL SNAPSHOT\r\n\r\nstatement ok\r\nBEGIN TRANSACTION ISOLATION LEVEL SNAPSHOT; COMMIT\r\n\r\nstatement ok\r\nBEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE; COMMIT\r\n\r\nstatement ok\r\nBEGIN TRANSACTION; SET TRANSACTION ISOLATION LEVEL SNAPSHOT; COMMIT\r\n\r\nstatement ok\r\nBEGIN TRANSACTION; SET TRANSACTION ISOLATION LEVEL SERIALIZABLE; COMMIT\r\n\r\n# It is an error to change the isolation level of a running transaction.\r\n\r\nstatement ok\r\nBEGIN TRANSACTION\r\n\r\nstatement ok\r\nUPDATE kv SET v = 'b' WHERE k in ('a')\r\n\r\n(Here's where things go south)\r\nI160324 23:40:16.529026 storage/replica_command.go:185  *roachpb.ScanRequest request from txn 62ddaca1: conflicting intents on [/Table/51/1/\"a\"/2/1]: resolved? false\r\nI160324 23:40:16.529856 storage/replica_command.go:147  62ddaca1: PUSH TXN: p=148308,t=1458877216.527538209,0,o=1458877216.527538209,0 pushes 218f2dea-407b-4696-a157-74810490a13f t=1458877216.518477630,0: failed to push \"sql/executor.go:380 sql txn\" id=218f2dea key=/Table/51/1/\"a\"/2/1 rw=true pri=0.02411930 iso=SERIALIZABLE stat=PENDING epo=0 ts=1458877216.518477630,0 orig=1458877216.518477630,0 max=1458877216.518477630,0 wto=false lhb=1458877216.518477630,0\r\n```"}}