1

I am trying to track down a row delete that is happening somewhere in a huge and sprawling application. I know that something deleted a row in an important DB table, and I have narrowed down when the delete happened to a 78 second time window. The app is spread over about 150 servers, but a simple grep for "delete" in the logs of those servers for that time window and a few minutes either side is not finding anything helpful, so I think the delete must have been a side effect of something else, or have happened inside the object relational mapper that the app uses.

Anyway, I decided to take a different approach and look at the postgres logs for the offending delete. It should already be configured to log everything log_statement = 'all', but that is not working as expected. If I tail the logs, I would expect a far higher volume of log messages going past that I actually see, and if I use the web interface to view the current status of the app (generating queries to the DB), then I don't see any queries go past. I see some queries, just not very many, and they all appear to be from one IP address.

What have I miss-configured? How do I get posgres to log everything?

Here is the contents of the log section in /var/lib/pgsql/11/data/postgresql.conf

#------------------------------------------------------------------------------
# REPORTING AND LOGGING
#------------------------------------------------------------------------------

# - Where to Log -

log_destination = 'stderr'              # Valid values are combinations of
                                        # stderr, csvlog, syslog, and eventlog,
                                        # depending on platform.  csvlog
                                        # requires logging_collector to be on.

# This is used when logging to stderr:
logging_collector = on                  # Enable capturing of stderr and csvlog
                                        # into log files. Required to be on for
                                        # csvlogs.
                                        # (change requires restart)

# These are only used if logging_collector is on:
log_directory = 'log'                   # directory where log files are written,
                                        # can be absolute or relative to PGDATA
log_filename = 'postgresql-%Y-%m-%d.log'        # log file name pattern,
                                        # can include strftime() escapes
#log_file_mode = 0600                   # creation mode for log files,
                                        # begin with 0 to use octal notation
log_truncate_on_rotation = on           # If on, an existing log file with the
                                        # same name as the new log file will be
                                        # truncated rather than appended to.
                                        # But such truncation only occurs on
                                        # time-driven rotation, not on restarts
                                        # or size-driven rotation.  Default is
                                        # off, meaning append to existing files
                                        # in all cases.
log_rotation_age = 1d                   # Automatic rotation of logfiles will
                                        # happen after that time.  0 disables.
log_rotation_size = 0                   # Automatic rotation of logfiles will
                                        # happen after that much log output.
                                        # 0 disables.

# These are relevant when logging to syslog:
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'
#syslog_sequence_numbers = on
#syslog_split_messages = on

# This is only relevant when logging to eventlog (win32):
# (change requires restart)
#event_source = 'PostgreSQL'

# - When to Log -

#log_min_messages = warning             # values in order of decreasing detail:
                                        #   debug5
                                        #   debug4
                                        #   debug3
                                        #   debug2
                                        #   debug1
                                        #   info
                                        #   notice
                                        #   warning
                                        #   error
                                        #   log
                                        #   fatal
                                        #   panic

#log_min_error_statement = error        # values in order of decreasing detail:
                                        #   debug5
                                        #   debug4
                                        #   debug3
                                        #   debug2
                                        #   debug1
                                        #   info
                                        #   notice
                                        #   warning
                                        #   error
                                        #   log
                                        #   fatal
                                        #   panic (effectively off)

#log_min_duration_statement = -1        # -1 is disabled, 0 logs all statements
                                        # and their durations, > 0 logs only
                                        # statements running at least this number
                                        # of milliseconds


# - What to Log -

#debug_print_parse = off
#debug_print_rewritten = off
#debug_print_plan = off
#debug_pretty_print = on
#log_checkpoints = off
#log_connections = off
#log_disconnections = off
#log_duration = off
#log_error_verbosity = default          # terse, default, or verbose messages
#log_hostname = off
log_line_prefix = '%m %h [%p] '         # special values:
                                        #   %a = application name
                                        #   %u = user name
                                        #   %d = database name
                                        #   %r = remote host and port
                                        #   %h = remote host
                                        #   %p = process ID
                                        #   %t = timestamp without milliseconds
                                        #   %m = timestamp with milliseconds
                                        #   %n = timestamp with milliseconds (as a Unix epoch)
                                        #   %i = command tag
                                        #   %e = SQL state
                                        #   %c = session ID
                                        #   %l = session line number
                                        #   %s = session start timestamp
                                        #   %v = virtual transaction ID
                                        #   %x = transaction ID (0 if none)
                                        #   %q = stop here in non-session
                                        #        processes
                                        #   %% = '%'
                                        # e.g. '<%u%%%d> '
#log_lock_waits = off                   # log lock waits >= deadlock_timeout
log_statement = 'all'                   # none, ddl, mod, all
#log_replication_commands = off
#log_temp_files = -1                    # log temporary files equal or larger
                                        # than the specified size in kilobytes;
                                        # -1 disables, 0 logs all temp files
log_timezone = 'UCT'


2
  • Perhaps you want to look at the effective settings, not those in some configuration file.
    – mustaccio
    Commented Aug 14, 2023 at 12:23
  • @mustaccio - What do you mean by effective settings? - I queried the pg_settings table to get the internal settings and there where no parameters that had a source field other than that config file or the default. SELECT * FROM pg_settings WHERE category LIKE 'Reporting and Logging %' Commented Aug 14, 2023 at 12:42

1 Answer 1

1

It is possible to countermand the log_statement=all setting. A superuser can just run SET log_statement=none in their session (although the SET statement itself would be logged before the new behavior takes effect, so it does leave evidence). It can also be countermanded "permanently" by ALTER user someone set log_statement=none, or the analogous thing with ALTER database. This would leave evidence behind when the ALTER statement was run, but not when the individual user establishes each new connection. It could also be countermanded within the config file itself, just be having a new setting further down in the file, or in the postgresql.auto.conf file.

There are other possibilities. If the delete is executed from within a user-defined-function, the function call would be logged but the nested delete would not be. If it is executed as part of a cascaded delete from a foreign key, that too would evade logging.

or have happened inside the object relational mapper that the app uses

I don't see how that would evade logging, unless it also fell under one of the possibilities I already raised.

1
  • Thanks @jjanes - The log_statement property had been modified for some users at some point in the past. I have no idea when, and as I only have a month of logs, I doubt I will find that event, it could have been years ago. By a delete within an ORM, I meant that if I grep the source code for "delete" then I might not find the offending line of SQL code because the delete got triggered via a method in the ORM with an unrelated name. It would still show up in the database logs. Commented Aug 15, 2023 at 8:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.