Failed reading: takeWith causes problems when retrying request

[wuzzeb]

Hi,

I have been working on a hard to track down bug in couchdb-enumerator (see https://bitbucket.org/wuzzeb/couchdb-enumerator/issue/2/quickcheck-tests-fail) that we thought for a while was a problem in our test code. But with the patch below to http-enumerator, I found the real error.

All of this has been tested with 0.7.2 and the tip of the master branch here on github.

Essentially, there are two problems and one masked the other :( Here is the sequence of events.

• Create one manager
• Several hundred successful requests go back and forth
• A HEAD request is given to http-enumerator
• A DELETE request is given http-enumerator
• A PUT request is given to http-enumerator
  • The PUT fails with ParseError {errorContexts = ["HTTP status line"], errorMessage = "Failed reading: takeWith"}
  • This error is because the previous DELETE request did not clean up after itself somehow, I am still unsure why.
  • Unfortunately, the code at the end of withManagedConn function in http-enumerator catches this error, closes the port, and recalls itself with a new port. Since this isn't reported to the user, it took me a long time to figure out what was going on.
  • The PUT request is sent a second time. This is a problem because the first PUT request was successful. http-enumerator just had problems parsing the response. The server does not like a second PUT request since the first succeeded.

There are two fixes needed:

• The end of withManagedConn should only recall itself if the method is a GET or HEAD. For PUT, POST, DELETE, etc it should not execute the request a second time and instead report the error to the caller.
• Figure out why the Failed Reading: takeWith is called in the first place. I have been trying to strip down the couchdb test code to a small test case, but can't seem to reproduce it. I will keep working on this, trying to add enough prints to see what happens.

Patch I used to finally track down the error.

diff -r 4cf15746fbe8 Network/HTTP/Enumerator.hs
--- a/Network/HTTP/Enumerator.hs    Tue Dec 13 00:11:46 2011 -0800
+++ b/Network/HTTP/Enumerator.hs    Thu Dec 22 01:27:52 2011 -0600
@@ -227,15 +227,19 @@
             Just ci -> return (ci, True)
     catchError
         (do
+            liftIO $ putStrLn "Startting enumerator"
             (toPut, a) <- withCI ci req step
+            liftIO $ putStrLn "Enumerator completed"
             liftIO $ if toPut
                 then putInsecureSocket man key ci
                 else TLS.connClose ci
             return a)
         (\se -> liftIO (TLS.connClose ci) >>
-                if isManaged
-                    then withManagedConn man key open req step
-                    else throwError se)
+                liftIO (putStrLn $ "Error during enum: " ++ show se) >>
+                throwError se)
+                --if isManaged
+                --    then withManagedConn man key open req step
+                --   else throwError se)

 withSslConn :: MonadIO m
             => ([X509] -> IO TLS.TLSCertificateUsage)

~/couchdb-enumerator$ ./dist/build/test/test -t conflict
Basic:
  DB:
Startting enumerator
Enumerator completed
Startting enumerator
Enumerator completed
Startting enumerator
Error during enum: ParseError {errorContexts = ["HTTP status line"], errorMessage = "Failed reading: takeWith"}
    conflict: [Failed]
ERROR: ParseError {errorContexts = ["HTTP status line"], errorMessage = "Failed reading: takeWith"}

         Test Cases  Total      
 Passed  0           0          
 Failed  1           1          
 Total   1           1          

[wuzzeb]

Ok, I think I made some progress with the help of the extra code to parseStatus from Ticket #24

Basic:
  DB:
Error during enum: ParseError {errorContexts = ["HTTP status line"], errorMessage = "Failed reading: Before status: 123 34 111 107 34 58 116 114 117 101 44 34 105 100 34 58 34 99 111 110 102 108 105 99 116 116 101 115 116 34 44 34 114 101 118 34 58 34 50 48 54 45 100 99 53 50 54 99 98 56 98 57 50 52 53 53 97 56 102 53 101 48 101 53 53 55 50 50 101 56 97 102 52 56 34 125 10"}
    conflict: [Failed]
ERROR: ParseError {errorContexts = ["HTTP status line"], errorMessage = "Failed reading: Before status: 123 34 111 107 34 58 116 114 117 101 44 34 105 100 34 58 34 99 111 110 102 108 105 99 116 116 101 115 116 34 44 34 114 101 118 34 58 34 50 48 54 45 100 99 53 50 54 99 98 56 98 57 50 52 53 53 97 56 102 53 101 48 101 53 53 55 50 50 101 56 97 102 52 56 34 125 10"}

From wireshark, I can see that couch db is returning the DELETE response in two packets. First, in one packet is returned the HTTP 1.1 200 OK plus the headers. Then couchdb returns the actual body in a second packet.

But the way we implement the DELETE call is with the iteratee (yield () EOF) passed to http because we do not care about the response. What I suspect is happening is that the delete is split across two packets, the yield () EOF correctly reads to the end of the first packet (this is what we fixed in Ticket #24) but the iteratee returns before consuming the second packet, leaving it to blow up the next response.

So I changed the (yield () EOF) to (EL.dropWhile (const True)) Now the tests get farther (DELETE followed by PUT no longer is a problem), but it still fails if the underlying iteratee throws an error. So now the bad sequence is

• HEAD which returns 404, causing an error to be thrown out the iteratee before consuming anything
• Next request is a PUT which causes a ParseError. But this time, the error is different: ParseError {errorContexts = ["HTTP status line","demandInput"], errorMessage = "not enough bytes"}

It is on the demandInput part... hmm

[snoyberg]

Since I don't have a couchdb setup, I don't think I'll be much help in debugging this one. Is there anything in particular I can do to assist on this?

Also, since it's slightly relevant, I've started a new branch of this repo, which will be http-conduit. When conduits are released/stabilized, I will likely be deprecating http-enumerator, unless someone wants to take over maintainership.

[wuzzeb]

Ok, I got it working now with the following hackish patch. Not sure if this type of approach is ok but here is what happens.

• A yield () EOF passed to http does not always consume the entire input. I "fixed" this by changing parseStatus to skip bytes until it reaches HTTP/ Somewhat of a hack.... I can change couchdb-enumerator to use EL.dropWhile (const True) and then not need this hack
• After fixing that, occasionally the demandInput error from the last comment showed up. I tracked it down to parseStatus having a stream with an EOF (see the code I added to the top of parseStatus)
• The EOF came about because the server closed the connection (seen with wireshark). Don't know why couchdb closed the connection, but it was closed by the server directly after http-enumerator sends a request.
• Since I had removed the code from withManagedConn which retrys the request, the server reseting the connection caused connEnum in TLS.Client.Enumerator to stop reading and send an EOF
• The EOF eventually blew up parseStatus
• I fixed this by making withManagedConn retry the request if the server resets the connection.

After the patch below, the tests run. But there are a huge number of resets (over 600) by the couchdb server when running just a single test. Not sure why the couchdb server is reseting so much, but now http-enumerator correctly handles it.

diff -r 4cf15746fbe8 Network/HTTP/Enumerator.hs
--- a/Network/HTTP/Enumerator.hs    Tue Dec 13 00:11:46 2011 -0800
+++ b/Network/HTTP/Enumerator.hs    Thu Dec 22 11:37:53 2011 -0600
@@ -2,6 +2,7 @@
 {-# LANGUAGE RecordWildCards #-}
 {-# LANGUAGE DeriveDataTypeable #-}
 {-# LANGUAGE FlexibleContexts #-}
+{-# LANGUAGE ScopedTypeVariables #-}
 {-# LANGUAGE CPP #-}
 -- | This module contains everything you need to initiate HTTP connections.  If
 -- you want a simple interface based on URLs, you can use 'simpleHttp'. If you
@@ -114,7 +115,7 @@
     )
 import qualified Data.Enumerator.List as EL
 import Network.HTTP.Enumerator.HttpParser
-import Control.Exception (Exception, bracket, throwIO, SomeException, try)
+import Control.Exception (Exception, bracket, throwIO, SomeException, try, fromException)
 import Control.Arrow (first)
 import Control.Monad.IO.Class (MonadIO (liftIO))
 import Control.Monad.Trans.Class (lift)
@@ -209,6 +210,13 @@
     withManagedConn man (host', port', False) $
         fmap TLS.socketConn $ getSocket host' port'

+checkReset :: SomeException -> Bool
+checkReset e = isReset || isIOReset
+    where isReset = case fromException e of
+                      Just TLS.ConnectionReset -> True
+                      _ -> False
+          isIOReset = show e == "recv: resource vanished (Connection reset by peer)"
+
 withManagedConn
     :: MonadIO m
     => Manager
@@ -233,9 +241,11 @@
                 else TLS.connClose ci
             return a)
         (\se -> liftIO (TLS.connClose ci) >>
-                if isManaged
-                    then withManagedConn man key open req step
-                    else throwError se)
+                liftIO (putStrLn $ "Error during enum: " ++ show se) >>
+                if checkReset se && isManaged
+                   then withManagedConn man key open req step
+                   else throwError se
+        )

 withSslConn :: MonadIO m
             => ([X509] -> IO TLS.TLSCertificateUsage)
diff -r 4cf15746fbe8 Network/HTTP/Enumerator/HttpParser.hs
--- a/Network/HTTP/Enumerator/HttpParser.hs Tue Dec 13 00:11:46 2011 -0800
+++ b/Network/HTTP/Enumerator/HttpParser.hs Thu Dec 22 11:37:53 2011 -0600
@@ -13,6 +13,7 @@
 import qualified Data.ByteString as S
 import qualified Data.ByteString.Char8 as S8
 import Control.Applicative
+import Control.Monad (when)
 import Data.Word (Word8)

 type Header = (S.ByteString, S.ByteString)
@@ -61,12 +62,13 @@
 parserHeadersFromByteString :: Monad m => S.ByteString -> m (Either String (Status, [Header]))
 parserHeadersFromByteString s = return $ parseOnly parseHeaders s

-
 type Status = (S.ByteString, Int, S.ByteString)

 parseStatus :: Parser Status
 parseStatus = do
-    _ <- string "HTTP/"
+    end <- atEnd
+    when end $ fail "EOF reached"
+    _ <- manyTill (take 1 >> return ()) (try $ string "HTTP/") <?> "HTTP/"
     ver <- takeWhile1 $ not . isSpace
     _ <- word8 32 -- space
     statCode <- takeWhile1 $ not . isSpace
diff -r 4cf15746fbe8 Network/TLS/Client/Enumerator.hs
--- a/Network/TLS/Client/Enumerator.hs  Tue Dec 13 00:11:46 2011 -0800
+++ b/Network/TLS/Client/Enumerator.hs  Thu Dec 22 11:37:53 2011 -0600
@@ -1,6 +1,8 @@
 {-# LANGUAGE ScopedTypeVariables #-}
+{-# LANGUAGE DeriveDataTypeable #-}
 module Network.TLS.Client.Enumerator
     ( ConnInfo
+    , ConnectionReset(..)
     , connClose
     , connIter
     , connEnum
@@ -10,9 +12,11 @@
     , TLSCertificateUsage(..)
     ) where

+import Control.Exception (Exception)
 import Data.ByteString (ByteString)
 import qualified Data.ByteString as S
 import qualified Data.ByteString.Lazy as L
+import Data.Typeable (Typeable)
 import System.IO (Handle, hClose)
 import Network.Socket (Socket, sClose)
 import Network.Socket.ByteString (recv, sendAll)
@@ -21,7 +25,7 @@
 import Control.Monad.Trans.Class (lift)
 import Data.Enumerator
     ( Iteratee (..), Enumerator, Step (..), Stream (..), continue, returnI
-    , tryIO
+    , tryIO, throwError
     )
 import Data.Certificate.X509 (X509)
 import Network.TLS.Extra (ciphersuite_all)
@@ -33,6 +37,10 @@
     , connClose :: IO ()
     }

+data ConnectionReset = ConnectionReset
+    deriving (Show,Typeable)
+instance Exception ConnectionReset
+
 connIter :: MonadIO m => ConnInfo -> Iteratee ByteString m ()
 connIter ConnInfo { connWrite = write } =
     continue go
@@ -49,7 +57,7 @@
     go (Continue k) = do
         bs <- tryIO read'
         if all S.null bs
-            then continue k
+            then throwError ConnectionReset
             else do
                 step <- lift $ runIteratee $ k $ Chunks bs
                 go step

[snoyberg]

New version released, let me know if you're still having issues. Also, in the future, could you send a pull request?

Thanks

[wuzzeb]

Yeah, I didn't send a pull request because I didn't know if this was the right approach, and in addition the patch I posted still had some debug code left in. The debug code is still in the released version, but perhaps it is helpful since it prints a message when an error occurs, which will perhaps help the next person track down similar errors.

Probably doesn't make a big difference, since I plan on switching to conduit and switching couchdb-enumerator over to conduit and http-conduit sometime soon, so perhaps it doesn't pay to put too much effort or thought into http-enumerator.

[snoyberg]

I'm glad you'll be moving over. Of course, if the same bugs exist in http-conduit, we'll have problems ;).