libpq: another command is already in progress

[Chratho]

Every once in a while I am noting "another command is already in progress" errors from libpq. The respective application manages database connections in a resource pool.

I am now wondering whether the application sometimes puts broken connections (with PGASYNC_BUSY still set) back into the pool, letting a subsequent access to the connection fail.

The implementation of exec contains the following line:

_ <- PQ.consumeInput h -- FIXME?

Is ignoring the result really okay this way? Calling PQgetResult afterwards, you might not be able to decide whether the result indicates that fetching is simply done or an error occurred. If at least something was already received, an application might continue without even noting.

I am not sure whether this really is an issue, but currently its the only reason I could think of causing the above exception.

[lpsmith]

Well, your hypothesis seems quite plausible to me. I don't have any opinion on whether or not this could be caused by ignoring the result of PQconsumeInput. I don't recall what that result is supposed to mean, off the top of my head.

Out of curiosity, does your application use the Database.PostgreSQL.Simple.Internal at all? Also, does it ever use Database.PostgreSQL.Simple.Copy?

[Chratho]

The application does not use Copy at all. It also doens't import Database.PostgreSQL.Simple.Internal directly, but of course we use some of the functions reexported from this module: There are some rare uses of execute_, and of course connectPostgreSQL (using execute_ itself) is called by the pool frequently.

The exception occurs in situations of high load, with lots of concurrent connections.

But to be honest, a bug in postgresql-simple is only one possible explanation. I might very well miss code fragments where exceptions are caught before even reaching the pools withResource handlers - so no chance to throw any resources away. Though I haven't found them yet...

[lpsmith]

Right, I don't care if you are using things from Internal that are exported elsewhere; I just wanted to try to get some feeling for the likelihood that this could be an issue created via use of Internal, especially the withConnection operator and the Connection data constructor. (Though, there are a number of things that are exported there that aren't exported elsewhere that should be perfectly harmless, so importing Internal isn't a necessarily a red flag.)

This might be the error you would get if you started a Copy operation and then attempted to execute something else before the copy operation is complete... but you aren't using copy.

Your second hypothesis also seems quite plausible. And, assuming we are interpreting the error message correctly, I'd be at a loss to come up with a third hypothesis, because possibly other than the copy module, any successfully completed command should leave the connection in the ready state, although as you suggest, some wonky exception handling on your part could result in the attempt to reuse a connection that should have been discarded. (Though, if this is the case, there might be a strong argument that postgresql-simple should be doing something slightly different when it raises the exception.)

libpq is a bit opaque regarding the correct use of it's async interface, so it's quite possibly a bug with postgresql-simple. (Not to mention that several of the postgresql core developers seem to think that async is old technology that's no longer relevant in the face of threads, argh.)

So, I agree with your reasoning so far. Keep me updated if you learn something more.

As for some experiments, you might try changing this line to #if 1 if you aren't overly dependent on the async functionality. (Some of my projects need async for timeouts and whatnot. Though, I am curious about the relative performance of async on highly loaded servers, which I haven't really tested as I don't need that right now.)

Another experiment whose results could be much more interesting, is to modify exec to not ignore the result of PQconsumeInput. The documentation suggests that the most appropriate thing to do if it returns true would probably be to throw an exception with the results of PQerrorMessage. It may also make sense to throw away the connection. You may want to create your own exception type to make the exception easier to find in your logs.

[hesselink]

I'm running into this message. It could be that I'm doing something wrong, so let me first describe what I'm doing:

I'm using postgresql-simple (through opaleye) to run a query, essentially coming down to withTransaction conn (queryWith_ rp conn q). The connection comes from a connection pool (using resource-pool). This query is potentially long-running, and it wrapped in timeout. If this timeout fires, I get the error.

I've added some logging to postgresql-simple, and the error occurs when trying to roll back the transaction (in withTransactionMode). I've tried both your experiments above. Switching off the async functionality fixes the issue. The call to consumeInput returns True, so ignoring it there isn't the issue, it seems.

Am I doing something wrong in my implementation? If not, how can I dig deeper to find and fix this issue?

Here's a minimal example reproducing the problem for me with the latest git master:

{-# LANGUAGE OverloadedStrings, ScopedTypeVariables #-}
import Database.PostgreSQL.Simple
import System.Timeout

main :: IO ()
main = do
  conn <- connectPostgreSQL "dbname='foo' user='bar' password='xxxx'"
  res <- timeout 1000000 $ withTransaction conn (query_ conn "select pg_sleep(5)")
  case res of
    Just [Only x] -> putStrLn "Done." >> return x
    Just _ -> error "Impossible."
    Nothing -> putStrLn "Timed out."

For me (on OS X 10.10.5, running postgresql 9.3.4.1, GHC 7.10.3 and postgresql-simple commit 74b2f4a) this prints:

*** Exception: libpq: failed (another command is already in progress
)

I'd expect it to print "Timed out." instead.

[lpsmith]

Yeah, I'd expect it to print "Timed out." as well. It certainly seems like a bug to me.

[hesselink]

OK, that's good to know. I've worked around it for now by using postgres' statement_timeout instead and catching the resulting exception in Haskell. Let me know if I can help find and/or fix the bug.

[lpsmith]

Ok, so the issue is kinda obvious once I think about it: the async exception from timeout is causing the execution of query_ to be abandoned, then the onException handler of withTransaction attempts to roll back the query. (essentially by issing another query_ when the connection object has been left in an unusable state.)

Probably the most straightforward "solution" would be to modify withTransaction to ignore exceptions generated from the rollback attempt. Though, that does raise the question if there are additional cases where the onException rollback attempt could lead to deadlock, or lead to unresponsiveness for several seconds or longer.

(So, a variant of withTransaction that closes the connection instead of attempting to rollback might well be useful here. And, even with the current semantics, perhaps we could be more intelligent about not attempting rollback and possibly even closing the connection when that's the sensible thing to do.)

Async exceptions are a massive PITA. On the other hand, they are at times indispensible. Even so, in my own code I'm increasingly trying to get away from using timeout in favor of registerDelay (from STM). postgresql-simple could offer some stm integration as well, at least on ghc-7.8 and later.

Incidentally, is Silk using a modified version of the postgresql-libpq binding? I'm highly surprised that timeout is working when you switch off the async functionality; unless of course it isn't timing out until after the 5 second postgresql sleep statement finishes. (And indeed, not being able to timeout blocking C calls to libpq's exec is precisely the reason I personally implemented the async functionality in the first place... but my particular use cases don't use withTransaction.)

However, there is another potential solution to making timeout work in a timely fashion: to modify the ffi binding for PQexec to be an interruptible foreign call. Of course, this requires GHC 7.8 and Windows Vista or later (or unix). It might be interesting to see what this would do in this particular example.

[hesselink]

Ah, that sounds very plausible. Ignoring exceptions from the rollback sounds a bit dangerous, like you say. Is there a way to detect if the connection is in an unusable state beforehand and not do the rollback in those cases?

I didn't know about registerDelay, that sounds very useful, although in this case you'd need cooperation from postgresql-simple, as you say.

We're not using a modified version, just the latest master. You're right about the synchronous version, by the way: it didn't throw, and returned "Timed out.", but only after 5 seconds.

As for your "interruptible FFI" solution, doesn't that have the same problem as the current code: query_ would be interrupted, withTransaction would catch the exception and try to rollback, causing a new exception?

[lpsmith]

Well, I don't think ignoring exceptions from the rollback attempt is that dangerous, after all, the only reason why postgresql-simple is trying to rollback is because there's an exception. So there will be an exception, always, it's just a question of which exception it will be.

My musings about deadlock/ temporary unresponsiveness was more along the lines of, let's say the network starts misbehaving, and that somehow leads to an exception inside a withTransaction block, and then the rollback attempt doesn't complete in a timely fashion because hey, the network isn't cooperating and doesn't even have the courtesy to inform you that it's not working right now.

Admittedly, this scenario isn't fully formed in my mind, so there are many details I can't really plausibly fill in in this sketch of a scenario.

As for how an interruptible exec would behave in this scenario, I'm not sure. You are right in that it should (indeed, must) behave similarly, but there might be some differences. I just don't know how libpq's exec would respond to being interrupted, and what kind of state(s) that could leave the connection object in.

But even in the "best case" scenario (for some (possibly weird) definition of "best"), where an interrupted exec leaves the connection in a usable state, then the backend would still be executing the sleep statement. And with the current state of postgres, a query cannot be interrupted by the client on the same connection: you would have to interrupt that over another connection. (Indeed, PQcancel creates a temporary connection to issue the cancel.)

So the rollback attempt would have to block until after the sleep statement finishes, unless it can error out before that. (In which case, it would be quite difficult to recover the connection, so should we close the connection object in that case, perhaps?)

[lpsmith]

As an aside, my rule of thumb is that most resources that could have possibly been touched by a block of code that has been System.timeout-ed should be treated as junk. Unfortunately, even things like timeout (readChan chan) can result in lost messages, because the async exception can kill the readChan after it's removed the element from the channel but before it's been returned to the caller.

So yeah, I've long been slightly uncomfortable with the rollback behavior of withTransaction, but at this point a lot of people are depending on it. And there's probably a good debate to be had over the use and misuse of exceptions and what's appropriate (and not) to have in an exception handler. But I digress.

[lpsmith]

@Chratho You don't happen to be using withTransaction in the presence of async exceptions? I am curious if this fixes your problem.

[reiddraper]

We are hitting this issue, too. Adding some information about our situation:

• We always use withTransaction (we use postgresql-transactional)
• A cursory investigation into our exception-tracking database shows no other exceptions that are occurring within a similar time-frame
• We do use System.timeout in two transactions. I'll try and narrow the exceptions down and see if they're corresponding to this timeout being hit.