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.
Best Answer
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
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:
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.