1

I am trying to log executed queries into a csv file.

My main objective is to log the command tag and query. For that I enabled logging in the postgresql.conf, my configs are the following:

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

# - Where to Log -

log_destination = 'stderr,csvlog'               # 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 = 'pg_log'                # directory where log files are written,
                                        # can be absolute or relative to PGDATA
log_filename = 'postgresql-%a-%H-%M.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 = 10                   # Automatic rotation of logfiles will
                                        # happen after that time.  0 disables.
log_rotation_size = 10240                       # 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'

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

# - When to Log -

#client_min_messages = log              # values in order of decreasing detail:
                                        #   debug5
                                        #   debug4
                                        #   debug3
                                        #   debug2
                                        #   debug1
                                        #   log
                                        #   notice
                                        #   warning
                                        #   error

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

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

log_min_duration_statement = 0          # -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 = on
log_disconnections = on
#log_duration = off
log_error_verbosity = verbose          # terse, default, or verbose messages
#log_hostname = off
log_line_prefix = 'ts="%t"/>'                       # 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
                                        #   %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_temp_files = -1                    # log temporary files equal or larger
                                        # than the specified size in kilobytes;
                                        # -1 disables, 0 logs all temp files
log_timezone = 'UTC'

So, the main things I did:

  • add csvlog to log_destination;
  • enable logging_collector;
  • set log_min_duration_statement to 0 (to log all executed queries);
  • enable log_connections and log_disconnections;
  • set log_error_verbosity to verbose (to get the max fields in the csv logs)
  • set log_statement to all

Yet, when I run a simple query, like:

 SELECT * FROM tests WHERE id='70';

I get:

2017-07-19 16:42:09.369 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,37,"idle",2017-07-19 16:33:37 UTC,2/20,0,LOG,00000,"statement: SELECT * FROM tests WHERE id='70';",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:914","pgAdmin III - Query Tool"
2017-07-19 16:42:09.369 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,38,"SELECT",2017-07-19 16:33:37 UTC,2/0,0,LOG,00000,"duration: 0.000 ms",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:1142","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,39,"idle",2017-07-19 16:33:37 UTC,2/21,0,LOG,00000,"statement: SELECT format_type(oid,-1) as typname FROM pg_type WHERE oid = 23",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:914","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,40,"SELECT",2017-07-19 16:33:37 UTC,2/0,0,LOG,00000,"duration: 0.000 ms",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:1142","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,41,"idle",2017-07-19 16:33:37 UTC,2/22,0,LOG,00000,"statement: SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS basetype
  FROM pg_type WHERE oid=23",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:914","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,42,"SELECT",2017-07-19 16:33:37 UTC,2/0,0,LOG,00000,"duration: 0.000 ms",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:1142","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,43,"idle",2017-07-19 16:33:37 UTC,2/23,0,LOG,00000,"statement: SELECT format_type(oid,44) as typname FROM pg_type WHERE oid = 1043",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:914","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,44,"SELECT",2017-07-19 16:33:37 UTC,2/0,0,LOG,00000,"duration: 0.000 ms",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:1142","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,45,"idle",2017-07-19 16:33:37 UTC,2/24,0,LOG,00000,"statement: SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS basetype
  FROM pg_type WHERE oid=1043",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:914","pgAdmin III - Query Tool"
2017-07-19 16:42:09.416 UTC,"postgres","postgres",11956,"::1:22927",596f89e1.2eb4,46,"SELECT",2017-07-19 16:33:37 UTC,2/0,0,LOG,00000,"duration: 0.000 ms",,,,,,,,"exec_simple_query, src\backend\tcop\postgres.c:1142","pgAdmin III - Query Tool"

Why is the first line, that has the query executed, saying that the command tag is "idle", shouldn't it say "SELECT"? Is there any way to have a logged line indicating the correct command tag and query in the proper columns? I set the log_error_verbosity to verbose in order to get that information. Is there any way to achieve what I want?

My postgres version is 9.4.

Thank you.

1
  • Are you sure that the Configuration settings have been applied, as i cannot see the log_line_prefix ts="%t"/> in your logs. Jul 20, 2017 at 10:08

2 Answers 2

1

The log_line_prefix is only present in the text file log, not in the csv log, thats why its not present in my question.

Either way, I managed to "solve" my problem, I started playing with the logging configurations and managed to get it working. I still have no clue why a thing so basic isn't correctly implemented.

In a simple way, what I wanted to do was to configure postgres so it would log all the queries and respective types in a file, like this

"SELECT * FROM test","SELECT"
"INSERT INTO test (id, time) VALUES ('123','1-1-2010')","INSERT"
...

Now, when checking the official documentation regarding postgres logging, I noticed that the csv format had all the information I needed (https://www.postgresql.org/docs/9.4/static/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-CSVLOG)

In theory, logging to a csv file would give a lot of information that would be usefull to me, return code, query, command tag, etc... In practice, most of the columns are missing... Not very usefull at all. I started playing with the logging configuration and managed to have an output that I can use.

By setting the next variables:

log_min_duration_statement = 0
log_statement = 'none'

I managed to create an output with the actual command tag of the query instead of the word "idle". Funny part, if I change the setting log_statement to anything else than none, all the command tags are set to "idle"... As I already said, fields are missing, for instance, I have no query... I had to use some regex to get it from the message field, but it should be present in the respective column, but it isn't.

BTW I am the OP, I didn't have my credential at the time.

1
0

The query is specifically suppressed on log_min_duration_statement and log_statement log entries because it's already included in the message. Maybe this may not be ideal but keep in mind that the message itself has to be sensible for the text logging case as well.

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.