Обсуждение: Connections closing due to "terminating connection due to administrator command"
Connections closing due to "terminating connection due to administrator command"
От
Herouth Maoz
Дата:
Hello everybody.
In the past week, it has happened to us twice already that we got an exception from our Java application, due to PostgreSQL "terminating connection due to administrator command”.
The problem is that I’m the administrator, and I issued no such command.
On the first opportunity that it happened, the PostgreSQL server actually seemed to have spontaneously shut itself down and restarted:
2015-07-21 15:37:59 IDT LOG: received fast shutdown request
2015-07-21 15:37:59 IDT LOG: aborting any active transactions
2015-07-21 15:37:59 IDT FATAL: terminating connection due to administrator command
…
2015-07-21 15:38:01 IDT LOG: shutting down
2015-07-21 15:38:02 IDT LOG: database system is shut down
2015-07-21 15:40:16 IDT LOG: database system was shut down at 2015-07-21 15:38:02 IDT
On today’s occasion, the server seems to be continuing as usual, and there is nothing whatsoever in the log.
So my questions are:
- Given that I did not terminate any backend connection interactively, why did I get a "terminating connection due to administrator command” message? Is there any situation where this message is issued without the administrator being involved?
- What could have caused the shutdown on the 21st of July? Again, I did not issue a shutdown request for that server, and the machine didn’t restart.
The server is running PostgreSQL 9.1.16.
Thank you,
Herouth
Re: Connections closing due to "terminating connection due to administrator command"
От
Adrian Klaver
Дата:
On 07/27/2015 02:16 AM, Herouth Maoz wrote: > Hello everybody. > > In the past week, it has happened to us twice already that we got an > exception from our Java application, due to PostgreSQL "terminating > connection due to administrator command”. > > The problem is that I’m the administrator, and I issued no such command. > > On the first opportunity that it happened, the PostgreSQL server > actually seemed to have spontaneously shut itself down and restarted: > > 2015-07-21 15:37:59 IDT LOG: received fast shutdown request > 2015-07-21 15:37:59 IDT LOG: aborting any active transactions > 2015-07-21 15:37:59 IDT FATAL: terminating connection due to > administrator command > … > 2015-07-21 15:38:01 IDT LOG: shutting down > 2015-07-21 15:38:02 IDT LOG: database system is shut down > 2015-07-21 15:40:16 IDT LOG: database system was shut down at > 2015-07-21 15:38:02 IDT > > On today’s occasion, the server seems to be continuing as usual, and > there is nothing whatsoever in the log. > > So my questions are: > > * Given that I did not terminate any backend connection interactively, > why did I get a "terminating connection due to administrator > command” message? Is there any situation where this message is > issued without the administrator being involved? This error message comes from intervention by a program external to Postgres: http://www.postgresql.org/message-id/4564.1284559661@sss.pgh.pa.us So what OS and version are you running? What does the Java app do besides accessing the database? Do you have other programs that monitor/control the database? > * What could have caused the shutdown on the 21st of July? Again, I > did not issue a shutdown request for that server, and the machine > didn’t restart. Is there anything in logs before the above that might give a clue? > > > The server is running PostgreSQL 9.1.16. > > Thank you, > Herouth > -- Adrian Klaver adrian.klaver@aklaver.com
Re: Connections closing due to "terminating connection due to administrator command"
От
Melvin Davidson
Дата:
If you are running Linux (please ALWAYS give the O/S ), then this could have been caused by the sys admin doing a system shutdown.
Otherwise, anyone that can sudo to postgres could also have potentially issued a ( # %u = user name )
On Mon, Jul 27, 2015 at 9:39 AM, Adrian Klaver <adrian.klaver@aklaver.com> wrote:
On 07/27/2015 02:16 AM, Herouth Maoz wrote:Hello everybody.
In the past week, it has happened to us twice already that we got an
exception from our Java application, due to PostgreSQL "terminating
connection due to administrator command”.
The problem is that I’m the administrator, and I issued no such command.
On the first opportunity that it happened, the PostgreSQL server
actually seemed to have spontaneously shut itself down and restarted:
2015-07-21 15:37:59 IDT LOG: received fast shutdown request
2015-07-21 15:37:59 IDT LOG: aborting any active transactions
2015-07-21 15:37:59 IDT FATAL: terminating connection due to
administrator command
…
2015-07-21 15:38:01 IDT LOG: shutting down
2015-07-21 15:38:02 IDT LOG: database system is shut down
2015-07-21 15:40:16 IDT LOG: database system was shut down at
2015-07-21 15:38:02 IDT
On today’s occasion, the server seems to be continuing as usual, and
there is nothing whatsoever in the log.
So my questions are:
* Given that I did not terminate any backend connection interactively,
why did I get a "terminating connection due to administrator
command” message? Is there any situation where this message is
issued without the administrator being involved?
This error message comes from intervention by a program external to Postgres:
http://www.postgresql.org/message-id/4564.1284559661@sss.pgh.pa.us
So what OS and version are you running?
What does the Java app do besides accessing the database?
Do you have other programs that monitor/control the database?* What could have caused the shutdown on the 21st of July? Again, I
did not issue a shutdown request for that server, and the machine
didn’t restart.
Is there anything in logs before the above that might give a clue?
The server is running PostgreSQL 9.1.16.
Thank you,
Herouth
--
Adrian Klaver
adrian.klaver@aklaver.com
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
--
Melvin Davidson
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.![](http://us.i1.yimg.com/us.yimg.com/i/mesg/tsmileys2/01.gif)
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.
![](http://us.i1.yimg.com/us.yimg.com/i/mesg/tsmileys2/01.gif)
Re: Connections closing due to "terminating connection due to administrator command"
От
Herouth Maoz
Дата:
> On 27 ביולי 2015, at 16:39, Adrian Klaver <adrian.klaver@aklaver.com> wrote: >> >> * Given that I did not terminate any backend connection interactively, >> why did I get a "terminating connection due to administrator >> command” message? Is there any situation where this message is >> issued without the administrator being involved? > > This error message comes from intervention by a program external to Postgres: > > http://www.postgresql.org/message-id/4564.1284559661@sss.pgh.pa.us > > So what OS and version are you running? OK, that’s a miss on my part, sorry: The OS is Debian GNU/Linux 7. > > What does the Java app do besides accessing the database? Well, it’s a message-passing application that basically up all the time, processing information sent in by our clients anddistributing it. It is not running on the same machine as the database, it is not using a privileged database account(the user is the database’s owner, but not a super-user), and it’s not even running very complex queries. If moredetailed information is needed, I’ll provide it as needed, as a full description of the system is going to be very lengthy,and I doubt it will be helpful, given that it’s not really capable of sending signals over to the database process,being on a separate machine. > > Do you have other programs that monitor/control the database? We have a backup script that runs at 4:02AM every day. Other than that, we just monitor the java program, so if the databasefails, it shows up in that program’s log. > > >> * What could have caused the shutdown on the 21st of July? Again, I >> did not issue a shutdown request for that server, and the machine >> didn’t restart. > > Is there anything in logs before the above that might give a clue? No, that’s the thing. It’s the first entry in the log for days - the previous log entry is from July 8th. NEW INFORMATION: I believe that today’s mishap is related to the July 21 shutdown problem, based on the logs of our Javaprogram and an inquiry into the way it handles messages that go through a particular path. It seems that one of the moduleshas a bug and retains stale connections, and since messages that arrive through that path are rare, the first timeone came after the July 21st shutdown was today. So I’m left with the question of what caused the shutdown on July 21st. Thank you, Herouth
Re: Connections closing due to "terminating connection due to administrator command"
От
Adrian Klaver
Дата:
On 07/27/2015 07:45 AM, Herouth Maoz wrote: > >> On 27 ביולי 2015, at 16:39, Adrian Klaver <adrian.klaver@aklaver.com> wrote: >>> >>> * Given that I did not terminate any backend connection interactively, >>> why did I get a "terminating connection due to administrator >>> command” message? Is there any situation where this message is >>> issued without the administrator being involved? >> >> This error message comes from intervention by a program external to Postgres: >> >> http://www.postgresql.org/message-id/4564.1284559661@sss.pgh.pa.us >> >> So what OS and version are you running? > > OK, that’s a miss on my part, sorry: The OS is Debian GNU/Linux 7. > >> >> What does the Java app do besides accessing the database? > > Well, it’s a message-passing application that basically up all the time, processing information sent in by our clientsand distributing it. It is not running on the same machine as the database, it is not using a privileged databaseaccount (the user is the database’s owner, but not a super-user), and it’s not even running very complex queries.If more detailed information is needed, I’ll provide it as needed, as a full description of the system is going tobe very lengthy, and I doubt it will be helpful, given that it’s not really capable of sending signals over to the databaseprocess, being on a separate machine. Well what we are talking about is system users not database users, as the error is an indication that some other program then Postgres is shutting down the Postgres server. > >> >> Do you have other programs that monitor/control the database? > > We have a backup script that runs at 4:02AM every day. Other than that, we just monitor the java program, so if the databasefails, it shows up in that program’s log. > >> >> >>> * What could have caused the shutdown on the 21st of July? Again, I >>> did not issue a shutdown request for that server, and the machine >>> didn’t restart. >> >> Is there anything in logs before the above that might give a clue? > > No, that’s the thing. It’s the first entry in the log for days - the previous log entry is from July 8th. Not sure what yo have set up for logging, but you might to crank it up. 13 days between entries for a system that is in use all the time seems sort of light to me. > > NEW INFORMATION: I believe that today’s mishap is related to the July 21 shutdown problem, based on the logs of our Javaprogram and an inquiry into the way it handles messages that go through a particular path. It seems that one of the moduleshas a bug and retains stale connections, and since messages that arrive through that path are rare, the first timeone came after the July 21st shutdown was today. So what is the module doing? Or more the point what is the application doing to deal with the stale connections? > > So I’m left with the question of what caused the shutdown on July 21st. > > Thank you, > Herouth > -- Adrian Klaver adrian.klaver@aklaver.com
Re: Connections closing due to "terminating connection due to administrator command"
От
Herouth Maoz
Дата:
> On 27 ביולי 2015, at 16:55, Melvin Davidson <melvin6925@gmail.com> wrote: > > If you are running Linux (please ALWAYS give the O/S ), then this could have been caused by the sys admin doing a systemshutdown. Yes, sorry about that, as I previously answered Adrian Klaver, the OS is Debian Gnu/Linux 7. But I did mention that the machine has not been restarted (it currently has a 45 day uptime). And the sysadmin says he didn’tdo anything on that machine on that day. > > Otherwise, anyone that can sudo to postgres could also have potentially issued a > pg_ctl stop. The only people with access to that machine are myself (through ssh to the postgres account) and the sysadmin. That machineis basically a dedicated database server. > > I strongly suggest you review the _system_ logs for a possible hint as to whom could have done that. Also, consider addingthe user name into the log prefix > ( # %u = user name ) I’ve asked the sysadmin to look at the system logs. I’ll consider the user name suggestion. Thank you. Herouth
Herouth Maoz <herouth@unicell.co.il> writes: > So I’m left with the question of what caused the shutdown on July 21st. Well, you had 2015-07-21 15:37:59 IDT LOG: received fast shutdown request There is exactly one place in the Postgres code that prints that message, and it is the postmaster's SIGINT handler. 2015-07-21 15:37:59 IDT LOG: aborting any active transactions This is just the postmaster noting that it's about to send SIGTERM signals to all its child processes ... 2015-07-21 15:37:59 IDT FATAL: terminating connection due to administrator command ... and here is a child acknowledging receipt of SIGTERM. This is all as-expected once the postmaster's received a shutdown signal. So something sent the postmaster a SIGINT, and it's hard to believe that the source wasn't external to the database. If your application is running on a different machine then it couldn't have been the application's fault. If you didn't issue "pg_ctl stop -m fast" then we can eliminate that. There has to have been some other software on the database server machine that sent the signal, and it had to have privileges to do so which means it was either running as the postgres O/S user or as root. One thing worth considering is the possibility that the postmaster had been started in such a way that it was still associated with a controlling terminal; then any control-C typed on that terminal would have resulted in a SIGINT. regards, tom lane
Re: Connections closing due to "terminating connection due to administrator command"
От
Adrian Klaver
Дата:
On 07/27/2015 08:07 AM, Herouth Maoz wrote: > >> On 27 ביולי 2015, at 16:55, Melvin Davidson <melvin6925@gmail.com> wrote: >> >> If you are running Linux (please ALWAYS give the O/S ), then this could have been caused by the sys admin doing a systemshutdown. > > Yes, sorry about that, as I previously answered Adrian Klaver, the OS is Debian Gnu/Linux 7. > > But I did mention that the machine has not been restarted (it currently has a 45 day uptime). And the sysadmin says hedidn’t do anything on that machine on that day. > >> >> Otherwise, anyone that can sudo to postgres could also have potentially issued a >> pg_ctl stop. > > The only people with access to that machine are myself (through ssh to the postgres account) and the sysadmin. That machineis basically a dedicated database server. > >> >> I strongly suggest you review the _system_ logs for a possible hint as to whom could have done that. Also, consider addingthe user name into the log prefix >> ( # %u = user name ) > > I’ve asked the sysadmin to look at the system logs. I’ll consider the user name suggestion. Thank you. Something about this thread rang a bell. Doing some searching I found: http://www.postgresql.org/message-id/6A94A18E-4A2D-4179-83CD-FDBBDF856C55@unicell.co.il So how did you deal with the thread topic? > > Herouth > -- Adrian Klaver adrian.klaver@aklaver.com
Re: Connections closing due to "terminating connection due to administrator command"
От
Herouth Maoz
Дата:
> On 27 ביולי 2015, at 18:01, Adrian Klaver <adrian.klaver@aklaver.com> wrote: > Not sure what yo have set up for logging, but you might to crank it up. 13 days between entries for a system that is inuse all the time seems sort of light to me. Most of the log settings are just the Debian default (except the log prefix). This system is one of several we have, butit’s intended for quick processing of messages by some of our customers that send low volumes but need quick response.As such, it processes around 50,000 messages a day, which boils down to around 200,000 or so database requests aday. It’s very light load, so we don’t get many timeouts or other load-related log entries. I don’t want to log each query,though, as that seems wasteful to me. > >> >> NEW INFORMATION: I believe that today’s mishap is related to the July 21 shutdown problem, based on the logs of our Javaprogram and an inquiry into the way it handles messages that go through a particular path. It seems that one of the moduleshas a bug and retains stale connections, and since messages that arrive through that path are rare, the first timeone came after the July 21st shutdown was today. > > So what is the module doing? > > Or more the point what is the application doing to deal with the stale connections? The module keeps a connection pool available to the threads that call it, one connection per thread. It runs a JDBC preparedstatement. If that prepared statement hits an SQLException, it then logs it in two places and attempts to recreatethe connection, which is where the bug is. But that bug is just the reason why I didn’t get a fresh connection afterwards,it’s not the reason why the SQLException happened to begin with (which is that the connection kept for this particularthread was from before the shut down). I hope this information helps, Herouth
Re: Connections closing due to "terminating connection due to administrator command"
От
Adrian Klaver
Дата:
On 07/27/2015 08:42 AM, Herouth Maoz wrote: > >> On 27 ביולי 2015, at 18:01, Adrian Klaver <adrian.klaver@aklaver.com> wrote: >> Not sure what yo have set up for logging, but you might to crank it up. 13 days between entries for a system that is inuse all the time seems sort of light to me. > > Most of the log settings are just the Debian default (except the log prefix). This system is one of several we have, butit’s intended for quick processing of messages by some of our customers that send low volumes but need quick response.As such, it processes around 50,000 messages a day, which boils down to around 200,000 or so database requests aday. It’s very light load, so we don’t get many timeouts or other load-related log entries. I don’t want to log each query,though, as that seems wasteful to me. I am not sure that logging every query is necessary. I was thinking more on the lines of connect/disconnect, more info in the log line prefix, moving the log_min_messages down. Anything to provide a little more context. It seems this actual shut down is coming from an external source, but it would be helpful to see if there was a correlation with what is happening in the database and use that to get to causation. > >> >>> >>> NEW INFORMATION: I believe that today’s mishap is related to the July 21 shutdown problem, based on the logs of our Javaprogram and an inquiry into the way it handles messages that go through a particular path. It seems that one of the moduleshas a bug and retains stale connections, and since messages that arrive through that path are rare, the first timeone came after the July 21st shutdown was today. >> >> So what is the module doing? >> >> Or more the point what is the application doing to deal with the stale connections? > > The module keeps a connection pool available to the threads that call it, one connection per thread. It runs a JDBC preparedstatement. If that prepared statement hits an SQLException, it then logs it in two places and attempts to recreatethe connection, which is where the bug is. But that bug is just the reason why I didn’t get a fresh connection afterwards,it’s not the reason why the SQLException happened to begin with (which is that the connection kept for this particularthread was from before the shut down). So how are the stale connections dealt with? > > > I hope this information helps, > Herouth > -- Adrian Klaver adrian.klaver@aklaver.com
> On 27 ביולי 2015, at 18:20, Tom Lane <tgl@sss.pgh.pa.us> wrote: > > Herouth Maoz <herouth@unicell.co.il> writes: >> So I’m left with the question of what caused the shutdown on July 21st. > > Well, you had > > 2015-07-21 15:37:59 IDT LOG: received fast shutdown request > > There is exactly one place in the Postgres code that prints that message, > and it is the postmaster's SIGINT handler. > > 2015-07-21 15:37:59 IDT LOG: aborting any active transactions > > This is just the postmaster noting that it's about to send SIGTERM signals > to all its child processes ... > > 2015-07-21 15:37:59 IDT FATAL: terminating connection due to administrator command > > ... and here is a child acknowledging receipt of SIGTERM. This is all > as-expected once the postmaster's received a shutdown signal. > > So something sent the postmaster a SIGINT, and it's hard to believe that > the source wasn't external to the database. OK, that was straight to the point, so I started looking for anything that could have done that in the system logs. As it turns out, it was human error. That is, the sysadmin ran "apt-get upgrade", not being aware that if one of the packagesupgraded was PostgreSQL, it would cause a database restart. Thanks everybody for your time. Herouth