Thread: "No transaction in progress" warning

Hello.

We've recently discovered a bug in our code that resulted in COMMITs
without BEGINs, and our client saw "no transaction in progress" warnings
in his log file. What worries me is that we didn't discover this problem
during development - the warning doesn't show up in our logs. We're both
using 8.3, and the settings in both postgresql.conf files are similar
(except for memory settings and file locations).

SHOW log_min_messages;
 log_min_messages
------------------
 notice
(1 row)

I thought this would cause all warnings to be logged automatically. When
I enter "COMMIT" in psql, I do get the warning, but I don't see it in
the log file. What could be the problem?


Thanks,
  - Conrad

On Thursday 07 May 2009 3:33:09 am Conrad Lender wrote:
> Hello.
>
> We've recently discovered a bug in our code that resulted in COMMITs
> without BEGINs, and our client saw "no transaction in progress" warnings
> in his log file. What worries me is that we didn't discover this problem
> during development - the warning doesn't show up in our logs. We're both
> using 8.3, and the settings in both postgresql.conf files are similar
> (except for memory settings and file locations).
>
> SHOW log_min_messages;
>  log_min_messages
> ------------------
>  notice
> (1 row)
>
> I thought this would cause all warnings to be logged automatically. When
> I enter "COMMIT" in psql, I do get the warning, but I don't see it in
> the log file. What could be the problem?

Are you certain you are looking at the correct log file? One way I test is to
run 'select 1/0;' this yields an ERROR.

>
>
> Thanks,
>   - Conrad



--
Adrian Klaver
aklaver@comcast.net

Conrad Lender <crlender@gmail.com> writes:
> SHOW log_min_messages;
>  log_min_messages
> ------------------
>  notice
> (1 row)

> I thought this would cause all warnings to be logged automatically.

Yup.

> When
> I enter "COMMIT" in psql, I do get the warning, but I don't see it in
> the log file. What could be the problem?

What seems most likely is that you're looking at the wrong log file.
Recheck the "where to log" settings.

            regards, tom lane

On 07/05/09 15:58, Tom Lane wrote:
> What seems most likely is that you're looking at the wrong log file.
> Recheck the "where to log" settings.

Thanks, Adrian and Tom,

you were right, I wasn't looking at the correct file.
My postgresql.conf has:

log_directory = '/var/log/postgresql'
log_filename = 'postgresql-8.3-main.log'

The server startup messages were in this file (which is why I assumed it
was the correct one), but for some reason after a restart the logs were
created as

/var/log/postgresql/postgresql-8.3-main.log.1241706461

I've moved away all the old files, but every time I restart (using the
/etc/init.d/postgres script), new log files with a timestamp are
created. AFAICS, there are no open filehandles or locks left pointing to
'/var/log/postgresql/postgresql-8.3-main.log'.

Well, at least now I know where to look for the warnings.


Thanks,
  - Conrad

On Thursday 07 May 2009 7:42:40 am Conrad Lender wrote:
> On 07/05/09 15:58, Tom Lane wrote:
> > What seems most likely is that you're looking at the wrong log file.
> > Recheck the "where to log" settings.
>
> Thanks, Adrian and Tom,
>
> you were right, I wasn't looking at the correct file.
> My postgresql.conf has:
>
> log_directory = '/var/log/postgresql'
> log_filename = 'postgresql-8.3-main.log'
>
> The server startup messages were in this file (which is why I assumed it
> was the correct one), but for some reason after a restart the logs were
> created as
>
> /var/log/postgresql/postgresql-8.3-main.log.1241706461
>
> I've moved away all the old files, but every time I restart (using the
> /etc/init.d/postgres script), new log files with a timestamp are
> created. AFAICS, there are no open filehandles or locks left pointing to
> '/var/log/postgresql/postgresql-8.3-main.log'.

From the manual
http://www.postgresql.org/docs/8.3/interactive/runtime-config-logging.html
Emphasis added.

log_filename (string)

    When logging_collector is enabled, this parameter sets the file names of the
created log files. The value is treated as a strftime pattern, so %-escapes can
be used to specify time-varying file names. (Note that if there are any
time-zone-dependent %-escapes, the computation is done in the zone specified by
log_timezone.) <<If no %-escapes are present, PostgreSQL will append the epoch
of the new log file's creation time. For example, if log_filename were
server_log, then the chosen file name would be server_log.1093827753 for a log
starting at Sun Aug 29 19:02:33 2004 MST.>> This parameter can only be set in
the postgresql.conf file or on the server command line.

    If CSV-format output is enabled in log_destination, .csv will be appended to
the timestamped log file name to create the file name for CSV-format output.
(If log_filename ends in .log, the suffix is replaced instead.) In the case of
the example above, the CSV file name will be server_log.1093827753.csv.


>
> Well, at least now I know where to look for the warnings.
>
>
> Thanks,
>   - Conrad



--
Adrian Klaver
aklaver@comcast.net

On 07/05/09 16:56, Adrian Klaver wrote:
>> The server startup messages were in this file (which is why I
>> assumed it was the correct one), but for some reason after a
>> restart the logs were created as
>>
>> /var/log/postgresql/postgresql-8.3-main.log.1241706461
[...]
> is done in the zone specified by log_timezone.) <<If no %-escapes are
> present, PostgreSQL will append the epoch of the new log file's
> creation time. For example, if log_filename were server_log, then the
> chosen file name would be server_log.1093827753 for a log starting at
> Sun Aug 29 19:02:33 2004 MST.>> This parameter can only be set in the
> postgresql.conf file or on the server command line.

Thanks, I had missed that in the manual.

I'm beginning to feel incredibly dense now, but this actually brought my
original problem back. When I do specify log_filename and log_directory,
and restart Postgres, the test you suggested ('select 1/0;') shows up as
an error in the log file

/var/log/postgresql/postgresql-8.3-main.log.{timestamp}

When I leave both log_directory and log_filename commented out (my
original settings), then restart postgres, it creates the file

/var/log/postgresql/postgresql-8.3-main.log

This contains three lines about SSL certificates, but the warning from
'select 1/0' will instead be written to this file:

/var/lib/postgresql/8.3/main/pg_log/postgresql-2009-05-07_170932.log

So there are two log files :-|

Is there any way to configure Postgres to always append to the same file
(/var/log/postgresql/postgresql-8.3-main.log), even if it doesn't
contain strftime escapes? I guess it must be possible, because that's
the way it used to work (before I screwed up my kernel memory settings
in an unrelated SNAFU, preventing Postgres from starting on boot).


Thanks for your patience.
  - Conrad

Scott Mead <scott.lists@enterprisedb.com> writes:
> On Thu, May 7, 2009 at 11:29 AM, Conrad Lender <crlender@gmail.com> wrote:
>> When I leave both log_directory and log_filename commented out (my
>> original settings), then restart postgres, it creates the file
>>
>> /var/log/postgresql/postgresql-8.3-main.log
>>
>> This contains three lines about SSL certificates, but the warning from
>> 'select 1/0' will instead be written to this file:
>>
>> /var/lib/postgresql/8.3/main/pg_log/postgresql-2009-05-07_170932.log
>>
>> So there are two log files :-|

> How did you restart postgres?  I'm guessing that you're using a distribution
> provided package.  If you're using the /etc/init.d scripts from that
> package, it's likely that the startup script is redirecting stderr and that
> the system is configured to use syslog for the rest of the logging.

Right.  There are a number of messages that can appear at startup before
the postmaster reads and adopts the "where to log" settings in
postgresql.conf.  Those early messages are going to go to postmaster's
stderr.  What it sounds like is you're using a start script that points
postmaster stderr to /var/log/postgresql/postgresql-8.3-main.log.
I don't find that to be a tremendously good idea --- in my RPMs the
early-startup messages go to a fixed file (/var/lib/pgsql/pgstartup.log)
that's not dependent on what the "where to log" configuration settings
are.

            regards, tom lane

On 07/05/09 18:26, Tom Lane wrote:
> Scott Mead <scott.lists@enterprisedb.com> writes:
>> How did you restart postgres?  I'm guessing that you're using a
>> distribution provided package.  If you're using the /etc/init.d
>> scripts from that package, it's likely that the startup script is
>> redirecting stderr and that the system is configured to use syslog
>> for the rest of the logging.
>
> Right.  There are a number of messages that can appear at startup
> before the postmaster reads and adopts the "where to log" settings in
>  postgresql.conf.  Those early messages are going to go to
> postmaster's stderr.  What it sounds like is you're using a start
> script that points postmaster stderr to
> /var/log/postgresql/postgresql-8.3-main.log. I don't find that to be
> a tremendously good idea --- in my RPMs the early-startup messages go
> to a fixed file (/var/lib/pgsql/pgstartup.log) that's not dependent
> on what the "where to log" configuration settings are.

I looked into the startup scripts that are used here (Ubuntu 8.10): the
/etc/init.d script calls a Perl script and redirects that command's
stderr to stdin to capture warnings and errors:

ERRMSG=$(pg_ctlcluster 8.3 main start 2>&1)

The pg_ctlcluster script parses postgresql.conf and, if log_filename and
log_directory aren't defined there, adds '-l
/var/log/postgresql/postgresql-8.3-main.log' as an option for pg_ctl.
This file is created with the appropriate permissions if necessary.
The script then forks, and the child detaches itself from the terminal
and redirects stdout and stderr to /dev/null:

  setsid;
  dup2(POSIX::open('/dev/null', POSIX::O_WRONLY), 1);
  dup2(POSIX::open('/dev/null', POSIX::O_WRONLY), 2);
  exec $pg_ctl @options;

That doesn't look too bad to me, or at least it's how I would write a
daemon script, too. If I understand you correctly, stderr should be left
intact?

If this is not the preferred way to handle logging with Postgres, maybe
I should ask pg_ctlcluster's maintainer about it.


Regards,
  - Conrad

On 08/05/09 16:43, Conrad Lender wrote:
> stderr to stdin to capture warnings and errors:

That should be "stderr to stdout", of course.

  - Conrad

Conrad Lender <crlender@gmail.com> writes:
> I looked into the startup scripts that are used here (Ubuntu 8.10):
> ...
> The pg_ctlcluster script parses postgresql.conf and, if log_filename and
> log_directory aren't defined there, adds '-l
> /var/log/postgresql/postgresql-8.3-main.log' as an option for pg_ctl.
> This file is created with the appropriate permissions if necessary.
> The script then forks, and the child detaches itself from the terminal
> and redirects stdout and stderr to /dev/null:

>   setsid;
>   dup2(POSIX::open('/dev/null', POSIX::O_WRONLY), 1);
>   dup2(POSIX::open('/dev/null', POSIX::O_WRONLY), 2);
>   exec $pg_ctl @options;

This seems like a whole lot of work to do mostly the wrong thing.
I think the Ubuntu maintainer has failed to think carefully about
what should happen to startup-time messages --- what if pg_ctl itself
fails and would like to say something about that?  Good luck finding
out about that from /dev/null.  What about postmaster messages that are
emitted before the postgresql.conf logging options have taken effect?
If there are any such options, early messages will end up in /dev/null
too because the -l switch isn't supplied.

It's a lot simpler and safer to just unconditionally send stderr to
someplace reliable throughout the startup process.  Now you don't
really want that once the postmaster is up and running, because there's
no provision for log rotation on plain stderr output --- but that's
what the postgresql.conf logging options are for.  But trying to be
fancy about what happens before they've kicked in isn't very productive,
and in this case seems downright counterproductive.

            regards, tom lane