Thread: Connections closing due to "terminating connection due to administrator command"

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

> 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

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

> 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

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

> 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

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