Thread: Cryptic error message in low-memory conditions
Hello list, This is something that I've only recently somewhat pinned down to a cause... Some Postgres servers will error out for a while with the following error message: "expected authentication request from server, but received c" If one uses Their Favorite Search Engine, this message is scattered around the internet, all in reference to Postgres, I think, but none of the top results seem to have any lucid responses or cause listed. We've seen this reproduce -- sometimes for minutes at a time -- and after catching one in the act I am reasonably confident that one common cause of this is systems that are low on memory, which I confirmed by looking at postgres logs and matching them up against our monitoring system. Critical statistics first: the systems run Linux with overcommit off, so malloc returns NULL now and again. There is no OOM killer activity.SSL is the transport, and SQL role password authenticationis in use.There is no swap. Here's an example of the various kinds of failure one can get from connecting to a system that is low on memory: 2011-08-26 16:03:06 | INFO "psql? failed with exception #<PGError: FATAL: out of memory DETAIL: Failed on request of size 488. >" 2011-08-26 16:02:27 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 16:01:51 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 16:01:15 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 16:00:39 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 16:00:01 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 15:59:25 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 15:58:48 | INFO "psql? failed with exception #<PGError: expected authentication request from server, but received c >" 2011-08-26 15:58:12 | INFO "psql? failed with exception #<PGError: FATAL: out of memory >" On the backend side, one can see that often there is a failure to fork, which is basically expected in this condition. Various statements will be reporting OOM also. The commonality of an error message that does not say anything about being out of memory is representative of the norm, and nominally one does not get any express indication that the system is out of memory, but otherwise responsive. This puts someone doing monitoring (like us) in a tricky position: the utilizer of the database is free to use their memory -- that's what it's for -- but the problem is we cannot determine that the server is basically online, if fully utilized. This defeats the ever-common "authenticate and run SELECT 1;" basic monitoring style frequently used to determine the most basic levels of uptime. Should the 'out of memory' conditions were delivered most of the time we could act differently, but for now we basically have to assume that postgres is offline and poke around. It's also interesting to note that the systems are basically responsive (ssh can always seem to fork, as I'm poking around tools like 'ls' et al seem to be fine), and sometimes the load average isn't even extreme -- a leaky application with too many connections can cause this, so it's not like every tiny last scrap of memory has been consumed. -- fdr
Daniel Farina <daniel@heroku.com> writes: > Some Postgres servers will error out for a while with the following > error message: > "expected authentication request from server, but received c" > [ and this seems to be triggered by fork failures in the server ] <spock>Fascinating.</spock> I poked at this for awhile by the expedient of hot-wiring postmaster.c to always fail the fork request: *** src/backend/postmaster/postmaster.c.orig Tue Aug 23 17:13:09 2011 --- src/backend/postmaster/postmaster.c Fri Aug 26 19:08:25 2011 *************** *** 3182,3188 **** #ifdef EXEC_BACKEND pid = backend_forkexec(port); #else /* !EXEC_BACKEND*/ ! pid = fork_process(); if (pid == 0) /* child */ { free(bn); --- 3182,3189 ---- #ifdef EXEC_BACKEND pid = backend_forkexec(port); #else /* !EXEC_BACKEND*/ ! pid = -1; // fork_process(); ! errno = ENOMEM; if (pid == 0) /* child */ { free(bn); The basic case did what I was expecting: $ psql "dbname=regression" psql: could not fork new process for connection: Cannot allocate memory which was unsurprising since I'm quite sure that code path got tested in basically this fashion, back in the dark ages. But sure enough, over a TCP connection with SSL support turned on, it fails as described. strace shows the postmaster is sending what it's supposed to. I eventually figured out the problem: libpq sees the "E" response, thinks it must be talking to a postmaster too old to understand NEGOTIATE_SSL_CODE, and closes the socket and tries again. But *it forgets to clear out its input buffer*, so the body of the error message is still there waiting to be read, and the next connection sees the "c" as the first byte of the first postmaster response. The fix for this is *** src/interfaces/libpq/fe-connect.c.orig Thu Jul 28 10:39:57 2011 --- src/interfaces/libpq/fe-connect.c Fri Aug 26 18:52:18 2011 *************** *** 2064,2069 **** --- 2064,2072 ---- conn->allow_ssl_try = false; /* Assume it ain't gonnahandle protocol 3, either */ conn->pversion = PG_PROTOCOL(2, 0); + /* Discard any unread/unsent data */ + conn->inStart = conn->inCursor = conn->inEnd = 0; + conn->outCount = 0; /* Must drop the old connection */ closesocket(conn->sock); conn->sock = -1; and similarly in the other places in fe-connect.c where we're abandoning an open connection (not sure every one of those has to have it, but it seems a good safety practice). That gets us to the right place in the default SSL mode: $ psql "host=localhost sslmode=prefer dbname=regression" psql: could not fork new process for connection: Cannot allocate memory but we're still not there if you're trying to force SSL: $ psql "host=localhost sslmode=require dbname=regression" psql: server does not support SSL, but SSL was required The reason for this is that that same bit of code supposes that any "E" response must mean that the postmaster didn't recognize NEGOTIATE_SSL_CODE. It doesn't (and of course shouldn't) pay any attention to the actual textual error message. Now, seeing as how NEGOTIATE_SSL_CODE has been understood by every build since PG 7.0, I believe that this is dead code and we could remove it; it seems exceedingly unlikely that any modern build of libpq will ever be used to talk to a server that responds to that with "E". In fact it's worse than just delivering a misleading error message in the "require" case, because if you're not doing "require" then what happens next is that the code forces the protocol level down to 2 and tries again, supposing that it must be dealing with an ancient server. In the normal case where you are talking to a server under load rather than a deliberately-broken one, it's entirely possible that the second connection attempt succeeds. And what you've got then is that the connection is operating in protocol 2 rather than what the user probably expected, disabling assorted functionality that he may well be depending on. I don't recall having seen reports that could match that syndrome, but then again Daniel's complaint is a new one on me too. So I'm thinking we'd be well advised to eliminate the assumption that an "E" response could be fixed by downgrading to protocol 2, and instead just make this code report the error message it got from the postmaster. That's more than a one-liner so I don't have a patch for it yet. Lastly, I noticed that if I tried this repeatedly on a Unix socket, I sometimes got psql: server closed the connection unexpectedly This probably means the server terminated abnormally before orwhile processing the request. could not send startup packet: Broken pipe rather than the expected results. I think what is happening here is a race condition, such that if the postmaster closes the socket without having read the startup packet, the client might not have actually gotten to its send() yet, and then it will get EPIPE from send() before it gets to the point of reading the error response. I tried to fix this by having report_fork_failure_to_client eat any pending data before responding: *** src/backend/postmaster/postmaster.c.orig Tue Aug 23 17:13:09 2011 --- src/backend/postmaster/postmaster.c Fri Aug 26 19:08:25 2011 *************** *** 3262,3276 **** char buffer[1000]; int rc; /* Format the error message packet (always V2protocol) */ snprintf(buffer, sizeof(buffer), "E%s%s\n", _("could not fork new process for connection:"), strerror(errnum)); - /* Set port to non-blocking. Don't do send() if this fails */ - if (!pg_set_noblock(port->sock)) - return; - /* We'll retry after EINTR, but ignore all other failures */ do { --- 3262,3291 ---- char buffer[1000]; int rc; + /* Set port to non-blocking. Don't do anything if this fails */ + if (!pg_set_noblock(port->sock)) + return; + + /* + * Try to read the startup packet, if it's available which it likely is. + * The reason for doing this is that when the client is connected via Unix + * socket, if we close the socket without having read data it already + * sent, many kernels will report EPIPE instead of letting the client + * read whatever we sent. That will likely result in an unhelpful + * "server closed the connection unexpectedly" report instead of what + * we are trying to tell them. So read and discard any already-available + * data. We already set nonblock mode, so we won't block here. + */ + do + { + rc = recv(port->sock, buffer, sizeof(buffer), 0); + } while (rc > 0 || (rc < 0 && errno == EINTR)); + /* Format the error message packet (always V2 protocol) */ snprintf(buffer, sizeof(buffer), "E%s%s\n", _("could not fork new process for connection: "), strerror(errnum)); /* We'll retry after EINTR,but ignore all other failures */ do { This seems to get rid of the problem on my Fedora box, but my old HPUX box still does it some of the time. I'm inclined to recommend applying this patch anyway --- the only alternative I can see is to try to rejigger the libpq code to temporarily ignore EPIPE during startup, which seems both messy and fragile. Comments? regards, tom lane
On Sat, Aug 27, 2011 at 01:59, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Daniel Farina <daniel@heroku.com> writes: >> Some Postgres servers will error out for a while with the following >> error message: >> "expected authentication request from server, but received c" >> [ and this seems to be triggered by fork failures in the server ] > > <spock>Fascinating.</spock> Agreed. <snip> > The reason for this is that that same bit of code supposes that any > "E" response must mean that the postmaster didn't recognize > NEGOTIATE_SSL_CODE. It doesn't (and of course shouldn't) pay any > attention to the actual textual error message. > > Now, seeing as how NEGOTIATE_SSL_CODE has been understood by every build > since PG 7.0, I believe that this is dead code and we could remove it; > it seems exceedingly unlikely that any modern build of libpq will ever > be used to talk to a server that responds to that with "E". What will be the result if you do use the modern libpq against that? Anyway - that's 5 *unsupported* versions back. So even if people do use that, I say they have to downgrade libpq as well ;) +1 for removing it. In fact, when do we reach the point that we can remove all the support for the v2 protocol completely? (this would obviously not be as a bugfix, but perhaps in 9.2)? Is there any particular reason we need to support both anymore? At least in the client? -- Magnus Hagander Me: http://www.hagander.net/ Work: http://www.redpill-linpro.com/
Magnus Hagander <magnus@hagander.net> writes: > On Sat, Aug 27, 2011 at 01:59, Tom Lane <tgl@sss.pgh.pa.us> wrote: >> Now, seeing as how NEGOTIATE_SSL_CODE has been understood by every build >> since PG 7.0, I believe that this is dead code and we could remove it; >> it seems exceedingly unlikely that any modern build of libpq will ever >> be used to talk to a server that responds to that with "E". > What will be the result if you do use the modern libpq against that? I'll check it after I write the patch, but what I'd expect to happen is that libpq would fail the connection and report the server's error message, which would be something like "unrecognized protocol version number". Anybody who did complain of this could be told to use sslmode=disable when talking to the ancient server. > Anyway - that's 5 *unsupported* versions back. More to the point, it's been a very very long time since we've heard of anyone using a server older than 7.2. (And there's a good reason for that, which is that 7.2 was the first version that wouldn't go belly-up at 4 billion transactions.) > In fact, when do we reach the point that we can remove all the support > for the v2 protocol completely? (this would obviously not be as a > bugfix, but perhaps in 9.2)? Is there any particular reason we need to > support both anymore? At least in the client? Fair question. We *have* still heard of people using 7.2/7.3, I think. Another point here is that there are JDBC people intentionally forcing protocol version 2 as a means of controlling prepared-statement plan lifespan. I hope that the auto-replan code that I intend to get into 9.2 will provide a better answer for those folks, but removing the workaround at the same time might be a tad premature. So my feeling is "not quite yet, maybe in a couple more years". regards, tom lane
I wrote: > Lastly, I noticed that if I tried this repeatedly on a Unix socket, > I sometimes got > psql: server closed the connection unexpectedly > This probably means the server terminated abnormally > before or while processing the request. > could not send startup packet: Broken pipe > rather than the expected results. I think what is happening here is a > race condition, such that if the postmaster closes the socket without > having read the startup packet, the client might not have actually > gotten to its send() yet, and then it will get EPIPE from send() before > it gets to the point of reading the error response. I tried to fix this > by having report_fork_failure_to_client eat any pending data before > responding: I've applied patches for the other two issues, but I'm having second thoughts about trying to hack around this one. The proposed patch doesn't really eliminate the problem, and in any case the message is not totally off base: the server did close the connection unexpectedly. It'd be nicer if users didn't have to look in the server log to find out why, but we can't guarantee that. However, I've developed a second concern about report_fork_failure_to_client, which is its habit of sending the fork failure message formatted according to 2.0 protocol. This causes libpq (and possibly other clients) to suppose that it's talking to a pre-7.4 server and try again in 2.0 protocol. So if the fork failure is transient, you have the problem of being unexpectedly and silently downgraded to 2.0 protocol. We could fix that by changing the function to send the message in 3.0 protocol always --- it would take more code but it's certainly doable. The trouble with that is that a pre-7.4 libpq would see the error message as garbage; and I'm not sure how pleasantly the JDBC driver handles it either, if it is trying to use 2.0 protocol. A more long-range point about it is that the next time we make a protocol version bump that affects the format of error messages, the problem comes right back. It'd be better if the message somehow indicated that the server hadn't made any attempt to match the client protocol version. I guess if we went up to 3.0 protocol, we could include a SQLSTATE value in the message and libpq could test that before making assumptions. Thoughts? regards, tom lane
I wrote: > Magnus Hagander <magnus@hagander.net> writes: >> On Sat, Aug 27, 2011 at 01:59, Tom Lane <tgl@sss.pgh.pa.us> wrote: >>> Now, seeing as how NEGOTIATE_SSL_CODE has been understood by every build >>> since PG 7.0, I believe that this is dead code and we could remove it; >>> it seems exceedingly unlikely that any modern build of libpq will ever >>> be used to talk to a server that responds to that with "E". >> What will be the result if you do use the modern libpq against that? > I'll check it after I write the patch, but what I'd expect to happen is > that libpq would fail the connection and report the server's error > message, which would be something like "unrecognized protocol version > number". Anybody who did complain of this could be told to use > sslmode=disable when talking to the ancient server. Just for the archives' sake, what happens with the committed patch is either a successful non-SSL connection: $ psql "dbname=template1 sslmode=prefer host=localhost" NOTICE: Unrecognized variable client_encoding psql (9.2devel, server 6.5.3) WARNING: psql version 9.2, server version 6.5. Some psql features might not work. Type "help" for help. or if you tried to force SSL usage, you get this: $ psql "dbname=template1 sslmode=require host=localhost" psql: Unsupported frontend protocol. Unsupported frontend protocol.$ The reason for the repeated message is that libpq tries twice and appends the error messages to its buffer both times. I didn't think this was important enough to try to fix; and anyway I seem to recall that it's intentional that we append the messages from multiple connection attempts. BTW, this response starting with "U", together with the buffer flush bug, seems to explain some of the old reports in the archives, such as http://archives.postgresql.org/pgsql-hackers/2005-09/msg01106.php regards, tom lane
On Sat, Aug 27, 2011 at 1:51 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > A more long-range point about it is that the next time we make a > protocol version bump that affects the format of error messages, > the problem comes right back. It'd be better if the message somehow > indicated that the server hadn't made any attempt to match the client > protocol version. I guess if we went up to 3.0 protocol, we could > include a SQLSTATE value in the message and libpq could test that before > making assumptions. Hmm. What do you think about the way ssh handles support and negotiation of cipher methods between client and server: in that case, I believe both client and server advertise what ciphers they are willing to accept. Changing the format of that negotiation procedure would be a pain, but hopefully that could be gotten pretty much right the first time. Right now, my understanding is libpq sends a version to the server, but doesn't really receive a list of supported formats in response, from this thread it seems what happens is if an old-style message is returned then it's presumed the server can't handle the new versions, which is not necessarily true. The server seems to written with the sensible assumption that it should use the oldest sensible message format to get the idea across to libpq of as many versions as possible, but libpq is taking a byproduct of the *way* the message/error is sent to learn something about the server's supported versions, and using that to affect more behavior. So perhaps one solution for the distant future is to respond with protocol versions so that libpq need not rely on guessing based on a particular message style it receives. Alternatively, could it make sense to just always report fork failure in the newest libpq version and broadcast failures in each protocol version's format, one after another? This presumes that old libpqs are forward-compatible to skip un-understood messages forever, though, which is saying a lot about the future...and that seems to be affecting ancient libpqs, as per your message. Please correct me; my understandings of the of the startup process have been hastily acquired from the documentation. -- fdr
Daniel Farina <daniel@heroku.com> writes: > On Sat, Aug 27, 2011 at 1:51 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: >> A more long-range point about it is that the next time we make a >> protocol version bump that affects the format of error messages, >> the problem comes right back. �It'd be better if the message somehow >> indicated that the server hadn't made any attempt to match the client >> protocol version. �I guess if we went up to 3.0 protocol, we could >> include a SQLSTATE value in the message and libpq could test that before >> making assumptions. > Hmm. What do you think about the way ssh handles support and > negotiation of cipher methods between client and server: in that case, > I believe both client and server advertise what ciphers they are > willing to accept. The difficulty here is that, having failed to fork off a subprocess from the postmaster, we really can't do much of anything beyond blasting out a predetermined failure message. We can *not* have the postmaster wait to see what protocol the client asked for, or we risk denial-of-service problems from malfunctioning or malicious clients. So there's basically no solution to be found by altering what it is that the client sends. > Alternatively, could it make sense to just always report fork failure > in the newest libpq version and broadcast failures in each protocol > version's format, one after another? This presumes that old libpqs > are forward-compatible to skip un-understood messages forever, though, > which is saying a lot about the future...and that seems to be > affecting ancient libpqs, as per your message. Yeah. We could possibly hope that the current format of error messages is sufficiently general that it'll never be obsoleted, or at least will always be a valid subset of future formats. regards, tom lane
On Sat, Aug 27, 2011 at 3:30 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Daniel Farina <daniel@heroku.com> writes: >> On Sat, Aug 27, 2011 at 1:51 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: >>> A more long-range point about it is that the next time we make a >>> protocol version bump that affects the format of error messages, >>> the problem comes right back. It'd be better if the message somehow >>> indicated that the server hadn't made any attempt to match the client >>> protocol version. I guess if we went up to 3.0 protocol, we could >>> include a SQLSTATE value in the message and libpq could test that before >>> making assumptions. > >> Hmm. What do you think about the way ssh handles support and >> negotiation of cipher methods between client and server: in that case, >> I believe both client and server advertise what ciphers they are >> willing to accept. > > The difficulty here is that, having failed to fork off a subprocess from > the postmaster, we really can't do much of anything beyond blasting out > a predetermined failure message. We can *not* have the postmaster wait > to see what protocol the client asked for, or we risk denial-of-service > problems from malfunctioning or malicious clients. So there's basically > no solution to be found by altering what it is that the client sends. Hmm. Well, for this requirement I don't think it's necessary to have the postmaster wait, luckily: the missing information on the client side is "what protocols does this postmaster support", and it's sniffing that out of the format a received message. Instead, the postmaster could send something as simple as a quite small static string burned in at compile-time that advertises to the receiving libpq what is supported, that way it doesn't have to guess. Other than a tiny amount of outbound traffic per bogus connection attempt (which I think is spent anyway to say "authentication denied" or in some cases "out of memory" for example) I think this avoids a problem with malicious clients. Such a versions-supported string probably has a smaller complexity that is vulnerable to change vs. the error protocol, and is explicit: libpq guessworking the supported messages on the server based on traffic sniffing seems pretty tortured. SSL might throw a small wrench into everything, though: does one want to send the supported protocol information when the channel is susceptible to MITM attacks, and *then* move to a secure channel? This seems like a pretty slim vulnerability (the ability for an attacker to poke at the protocol versions supported string, which presumably would give them all sorts of other nasty power already) as long as all other communications are SSLified. One could probably get around this by sending the version information twice, once before and once after SSL negotiation so the client has an opportunity to spot icky things going on. (Embellishment: if one has policy in pg_hba.conf as to what protocols are supported it may need to be a dynamic string influenced by the conf on startup or whatever, but I think this is a comparatively small detail.) -- fdr