{"action":"created","issue":{"url":"https://api.github.com/repos/StackExchange/StackExchange.Redis/issues/237","labels_url":"https://api.github.com/repos/StackExchange/StackExchange.Redis/issues/237/labels{/name}","comments_url":"https://api.github.com/repos/StackExchange/StackExchange.Redis/issues/237/comments","events_url":"https://api.github.com/repos/StackExchange/StackExchange.Redis/issues/237/events","html_url":"https://github.com/StackExchange/StackExchange.Redis/issues/237","id":95986812,"number":237,"title":"OnDisconnected corrupts state of ResultBox<bool>.store when PING on top of the message queue","user":{"login":"bencican","id":12614802,"avatar_url":"https://avatars.githubusercontent.com/u/12614802?v=3","gravatar_id":"","url":"https://api.github.com/users/bencican","html_url":"https://github.com/bencican","followers_url":"https://api.github.com/users/bencican/followers","following_url":"https://api.github.com/users/bencican/following{/other_user}","gists_url":"https://api.github.com/users/bencican/gists{/gist_id}","starred_url":"https://api.github.com/users/bencican/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bencican/subscriptions","organizations_url":"https://api.github.com/users/bencican/orgs","repos_url":"https://api.github.com/users/bencican/repos","events_url":"https://api.github.com/users/bencican/events{/privacy}","received_events_url":"https://api.github.com/users/bencican/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2015-07-20T04:52:02Z","updated_at":"2015-09-14T12:58:25Z","closed_at":null,"body":"Hi Mark,\r\n\r\nI was chasing down a race today where seemingly put transaction Commits returned false even though these went through just fine from redis server logs.\r\n\r\nDebugging further into it PhysicalBridge.OnDisconnect turned out to be the root cause as when a PING message is on the top of the queue it will get completed twice. I marked them in the code snippet below but basically what happens is that it gets completed the first time because it's a ping... and then second time as part of ChangeState(State.Disconnected) -> AbortUnsent().\r\n\r\nThis is consistent with the scenario I was encountering where we had a transaction on a disconnected multiplexer which failed and subsequent transaction on a connected multiplexer which succeeded but returned result as though it failed too.\r\n\r\n        internal void OnDisconnected(ConnectionFailureType failureType, PhysicalConnection connection, out bool isCurrent, out State oldState)\r\n        {\r\n            Trace(\"OnDisconnected\");\r\n\r\n            // if the next thing in the pipe is a PING, we can tell it that we failed (this really helps spot doomed connects)\r\n            // note that for simplicity we haven't removed it from the queue; that's OK\r\n            int count;\r\n            var ping = queue.PeekPing(out count);\r\n            if (ping != null)\r\n            {\r\n                Trace(\"Marking PING as failed (queue length: \" + count + \")\");\r\n                ping.Fail(failureType, null);\r\n\r\n                // First completion <--------------------------------------------\r\n                CompleteSyncOrAsync(ping);\r\n            }\r\n            oldState = default(State); // only defined when isCurrent = true\r\n            if (isCurrent = (physical == connection))\r\n            {\r\n                Trace(\"Bridge noting disconnect from active connection\" + (isDisposed ? \" (disposed)\" : \"\"));\r\n\r\n                // Second completion <--------------------------------------------\r\n                oldState = ChangeState(State.Disconnected);\r\n                physical = null;\r\n\r\n                if (!isDisposed && Interlocked.Increment(ref failConnectCount) == 1)\r\n                {\r\n                    GetConnection(null); // try to connect immediately\r\n                }\r\n            }\r\n\r\n\r\nTwo completions cause the PING message to be completed twice which in turn completes the underlying ResultBox<bool> twice adding a duplicate to the ResultBox<bool>.store and thus corrupting the state of the store and upcoming messages based on how unlucky you get since now a single ResultBox<bool> will be potentially updated completed from more than one message callback at any given time.\r\n\r\nPlease let me know if there's any more info needed. I don't have a clean repro atm but I think the issue is easy enough to follow and understand. "},"comment":{"url":"https://api.github.com/repos/StackExchange/StackExchange.Redis/issues/comments/140062795","html_url":"https://github.com/StackExchange/StackExchange.Redis/issues/237#issuecomment-140062795","issue_url":"https://api.github.com/repos/StackExchange/StackExchange.Redis/issues/237","id":140062795,"user":{"login":"kylestittleburg","id":1778640,"avatar_url":"https://avatars.githubusercontent.com/u/1778640?v=3","gravatar_id":"","url":"https://api.github.com/users/kylestittleburg","html_url":"https://github.com/kylestittleburg","followers_url":"https://api.github.com/users/kylestittleburg/followers","following_url":"https://api.github.com/users/kylestittleburg/following{/other_user}","gists_url":"https://api.github.com/users/kylestittleburg/gists{/gist_id}","starred_url":"https://api.github.com/users/kylestittleburg/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kylestittleburg/subscriptions","organizations_url":"https://api.github.com/users/kylestittleburg/orgs","repos_url":"https://api.github.com/users/kylestittleburg/repos","events_url":"https://api.github.com/users/kylestittleburg/events{/privacy}","received_events_url":"https://api.github.com/users/kylestittleburg/received_events","type":"User","site_admin":false},"created_at":"2015-09-14T12:58:25Z","updated_at":"2015-09-14T12:58:25Z","body":"+1 on this issue, I think we're seeing it during out load tests.  #275 has a relatively reliable repro test, for me at least, especially if I bump the number of threads up.\r\n\r\nIs the intent of `store` in `ResultBox<T>` to be a performance optimization to save on construction/cleanup costs for `ResultBox` objects?"}}