aleszeleny
commented
2 years ago I did a test case:
- delete and create output directory
- copy the postgres log file to
postgresql-test.log - run pgbadger
- create a copy of the
postgresql-test.logfile to have a reference - copy the postgres log (with some new lines) file to
postgresql-test.log - run pgbadger
Several times. From the user's perspective, it looks non-deterministic, since the first round detected new lines and parse them, while the same repeated once more claims there are no new log lines to be parsed. So there must be a difference, but I haven't revealed it yet.
Create a clean output directory:
-bash-4.2$ rm -rf reports/
-bash-4.2$ mkdir reportsCopy Postgres log file:
-bash-4.2$ cp /var/postgresdata/13/data/log/postgresql.log /var/postgresdata/13/data/log/postgresql-test.log
Run pgBadger in incremental mode:
-bash-4.2$ pgbadger/pgbadger -v --start-monday -I -p '%m, %p, %c, %l, %u, %d, %r, %a, %x, %v, %e, %i: ' -f stderr -O /var/postgresdata/reports /var/postgresdata/13/data/log/postgresql-test.log
DEBUG: pgBadger version 11.7.
DEBUG: Output 'html' reports will be written to out.html
DEBUG: pgBadger will use log format stderr to parse /var/postgresdata/13/data/log/postgresql-test.log.
DEBUG: Starting progressbar writer process
DEBUG: timezone not specified, using -7200 seconds
DEBUG: Processing log file: /var/postgresdata/13/data/log/postgresql-test.log
DEBUG: Starting reading file "/var/postgresdata/13/data/log/postgresql-test.log"...
DEBUG: Start parsing postgresql log at offset 0 of file "/var/postgresdata/13/data/log/postgresql-test.log" to 7102089
DEBUG: setting current position in log to 7102089of 7102089 (82.80%), queries: 770, events: 61
DEBUG: Saving last parsed line into /tmp/tmp_LAST_PARSED (2022-03-29 16:18:03s: 7102089)nts: 69
DEBUG: Reading temporary last parsed line from /tmp/tmp_LAST_PARSED
DEBUG: Saving last parsed line into /var/postgresdata/reports/LAST_PARSED
DEBUG: the log statistics gathering took: 4 wallclock secs ( 0.00 usr 0.00 sys + 2.92 cusr 0.01 csys = 2.93 CPU)
DEBUG: Building incremental report for 2022-03-29
LOG: Ok, generating HTML daily report into /var/postgresdata/reports/2022/03/29/...
LOG: Ok, generating HTML weekly report into /var/postgresdata/reports/2022/week-14/...
LOG: Ok, generating global index to access incremental reports...
DEBUG: writing global index into /var/postgresdata/reports/index.html
DEBUG: building reports took: 2 wallclock secs ( 1.85 usr + 0.01 sys = 1.86 CPU)
DEBUG: the total execution time took: 6 wallclock secs ( 1.85 usr 0.01 sys + 2.92 cusr 0.01 csys = 4.79 CPU)It processed the log file smoothly.
Backup a copy of the parsed file and make sure that the new working file is not same as the copy:
-bash-4.2$ cp /var/postgresdata/13/data/log/postgresql-test.log /var/postgresdata/13/data/log/postgresql-test.log.1
-bash-4.2$ cp /var/postgresdata/13/data/log/postgresql.log /var/postgresdata/13/data/log/postgresql-test.log
-bash-4.2$ diff -q /var/postgresdata/13/data/log/postgresql-test.log /var/postgresdata/13/data/log/postgresql-test.log.1
Files /var/postgresdata/13/data/log/postgresql-test.log and /var/postgresdata/13/data/log/postgresql-test.log.1 differRun pgBadger in incremental mode:
-bash-4.2$ pgbadger/pgbadger -v --start-monday -I -p '%m, %p, %c, %l, %u, %d, %r, %a, %x, %v, %e, %i: ' -f stderr -O /var/postgresdata/reports /var/postgresdata/13/data/log/postgresql-test.log
DEBUG: pgBadger version 11.7.
DEBUG: Output 'html' reports will be written to out.html
DEBUG: Found log offset 7102089 in file /var/postgresdata/reports/LAST_PARSED
DEBUG: pgBadger will use log format stderr to parse /var/postgresdata/13/data/log/postgresql-test.log.
DEBUG: timezone not specified, using -7200 seconds
DEBUG: Starting progressbar writer process
DEBUG: Processing log file: /var/postgresdata/13/data/log/postgresql-test.log
DEBUG: This log might not be parsed: /var/postgresdata/13/data/log/postgresql-test.log, there are no new lines in this file
DEBUG: Starting reading file "/var/postgresdata/13/data/log/postgresql-test.log"...
DEBUG: Start parsing postgresql log at offset 7102089 of file "/var/postgresdata/13/data/log/postgresql-test.log" to 7331890
DEBUG: setting current position in log to 7331890of 7331890 (99.53%), queries: 25, events: 2
DEBUG: Saving last parsed line into /tmp/tmp_LAST_PARSED (2022-03-29 16:19:01s: 7331890)ts: 2
DEBUG: Reading temporary last parsed line from /tmp/tmp_LAST_PARSED
DEBUG: Saving last parsed line into /var/postgresdata/reports/LAST_PARSED
DEBUG: the log statistics gathering took: 2 wallclock secs ( 0.02 usr 0.01 sys + 0.15 cusr 0.00 csys = 0.18 CPU)
DEBUG: Building incremental report for 2022-03-29
LOG: Ok, generating HTML daily report into /var/postgresdata/reports/2022/03/29/...
LOG: Ok, generating HTML weekly report into /var/postgresdata/reports/2022/week-14/...
LOG: Ok, generating global index to access incremental reports...
DEBUG: writing global index into /var/postgresdata/reports/index.html
DEBUG: building reports took: 1 wallclock secs ( 1.56 usr + 0.02 sys = 1.58 CPU)
DEBUG: the total execution time took: 3 wallclock secs ( 1.58 usr 0.03 sys + 0.15 cusr 0.00 csys = 1.76 CPU)
``` This time, new lines were detected and parsed.
Repeat the test again (including the last working file backup):-bash-4.2$ cp /var/postgresdata/13/data/log/postgresql-test.log /var/postgresdata/13/data/log/postgresql-test.log.2 -bash-4.2$ cp /var/postgresdata/13/data/log/postgresql.log /var/postgresdata/13/data/log/postgresql-test.log -bash-4.2$ diff -q /var/postgresdata/13/data/log/postgresql-test.log /var/postgresdata/13/data/log/postgresql-test.log.2 Files /var/postgresdata/13/data/log/postgresql-test.log and /var/postgresdata/13/data/log/postgresql-test.log.2 differ
And run pgBadger:
```-bash-4.2$ pgbadger/pgbadger -v --start-monday -I -p '%m, %p, %c, %l, %u, %d, %r, %a, %x, %v, %e, %i: ' -f stderr -O /var/postgresdata/reports /var/postgresdata/13/data/log/postgresql-test.log
DEBUG: pgBadger version 11.7.
DEBUG: Output 'html' reports will be written to out.html
DEBUG: Found log offset 7331890 in file /var/postgresdata/reports/LAST_PARSED
DEBUG: this file has already been parsed: /var/postgresdata/13/data/log/postgresql-test.log, there are no new lines in this file
DEBUG: Reading temporary last parsed line from /tmp/tmp_LAST_PARSED
DEBUG: the log statistics gathering took: 1 wallclock secs ( 0.78 usr + 0.00 sys = 0.78 CPU)
DEBUG: no new entries in your log(s) since last run.
DEBUG: building reports took: 0 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU)
DEBUG: the total execution time took: 1 wallclock secs ( 0.78 usr + 0.00 sys = 0.78 CPU)(!) This time, pgbadger did not detect the new log lines.
The last_parsed file:
-bash-4.2$ cat /var/postgresdata/reports/LAST_PARSED
2022-03-29 16:19:01 7331890 2022-03-29 16:19:01.433 CEST, 50632, 62431555.c5c8, 2, u_app, live, 192.168.12.93(50696), [unknown], 0, 7/2827694, 00000, authentication: LOG: connection authorized: user=u_app database=liveDouble-check, there are new lines:
-bash-4.2$ wc -l /var/postgresdata/13/data/log/postgresql-test.log /var/postgresdata/13/data/log/postgresql-test.log.2
39332 /var/postgresdata/13/data/log/postgresql-test.log
37370 /var/postgresdata/13/data/log/postgresql-test.log.2The postgresql-test.log.2 file (backup before copying the latest log into a test working file) has fewer lines, so there were new lines to be parsed.
and a diff:
-bash-4.2$ diff /var/postgresdata/13/data/log/postgresql-test.log /var/postgresdata/13/data/log/postgresql-test.log.2 | head
37371,39332d37370
< 2022-03-29 16:19:01.475 CEST, 50629, 62431555.c5c5, 3, u_app, cfgdb, 192.168.12.93(50694), [unknown], 0, , 00000, idle: LOG: disconnection: session time: 0:00:00.216 user=u_app database=cfgdb host=192.168.12.93 port=50694
< 2022-03-29 16:19:01.475 CEST, 50632, 62431555.c5c8, 3, u_app, live, 192.168.12.93(50696), [unknown], 0, , 00000, idle: LOG: disconnection: session time: 0:00:00.044 user=u_app database=live host=192.168.12.93 port=50696
< 2022-03-29 16:19:01.540 CEST, 50633, 62431555.c5c9, 1, [unknown], [unknown], 192.168.12.93(50697), [unknown], 0, , 00000, : LOG: connection received: host=192.168.12.93 port=50697
< 2022-03-29 16:19:01.541 CEST, 50633, 62431555.c5c9, 2, u_app, cfgdb, 192.168.12.93(50697), [unknown], 0, 5/9508614, 00000, authentication: LOG: connection authorized: user=u_app database=cfgdb
< 2022-03-29 16:19:01.673 CEST, 50634, 62431555.c5ca, 1, [unknown], [unknown], 192.168.12.93(50698), [unknown], 0, , 00000, : LOG: connection received: host=192.168.12.93 port=50698
< 2022-03-29 16:19:01.674 CEST, 50634, 62431555.c5ca, 2, u_app, live, 192.168.12.93(50698), [unknown], 0, 7/2827717, 00000, authentication: LOG: connection authorized: user=u_app database=live
< 2022-03-29 16:19:01.718 CEST, 50634, 62431555.c5ca, 3, u_app, live, 192.168.12.93(50698), [unknown], 0, , 00000, idle: LOG: disconnection: session time: 0:00:00.046 user=u_app database=live host=192.168.12.93 port=50698
< 2022-03-29 16:19:01.718 CEST, 50633, 62431555.c5c9, 3, u_app, cfgdb, 192.168.12.93(50697), [unknown], 0, , 00000, idle: LOG: disconnection: session time: 0:00:00.179 user=u_app database=cfgdb host=192.168.12.93 port=50697
< 2022-03-29 16:19:01.809 CEST, 50635, 62431555.c5cb, 1, [unknown], [unknown], 192.168.12.93(50699), [unknown], 0, , 00000, : LOG: connection received: host=192.168.12.93 port=50699- without the incremental mode, the log file is parsed, as expected
DEBUG: pgBadger version 11.7. DEBUG: Output 'html' reports will be written to out.html DEBUG: pgBadger will use log format stderr to parse /var/postgresdata/13/data/log/postgresql-test.log. DEBUG: Starting progressbar writer process DEBUG: timezone not specified, using -7200 seconds DEBUG: Processing log file: /var/postgresdata/13/data/log/postgresql-test.log DEBUG: Starting reading file "/var/postgresdata/13/data/log/postgresql-test.log"... DEBUG: Start parsing postgresql log at offset 0 of file "/var/postgresdata/13/data/log/postgresql-test.log" to 7714956 [========================>] Parsed 7714956 bytes of 7714956 (100.00%), queries: 1034, events: 74 DEBUG: the log statistics gathering took: 5 wallclock secs ( 0.03 usr 0.00 sys + 3.11 cusr 0.02 csys = 3.16 CPU) DEBUG: Output 'html' reports will be written to out.html LOG: Ok, generating html report... DEBUG: building reports took: 1 wallclock secs ( 0.90 usr + 0.01 sys = 0.91 CPU) DEBUG: the total execution time took: 6 wallclock secs ( 0.93 usr 0.01 sys + 3.11 cusr 0.02 csys = 4.07 CPU)
PostgreSQL instance is 13, logging configuration:
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.
# These are only used if logging_collector is on:
log_directory = 'log' # directory where log files are written,
log_filename = 'postgresql.log' # log file name pattern,
#log_file_mode = 0600 # creation mode for log files,
log_truncate_on_rotation = on # If on, an existing log file with the
# same name as the new log file will be
#log_rotation_age = 1d # Automatic rotation of logfiles will
log_rotation_size = 0 # Automatic rotation of logfiles will
# happen after that much log output.
log_min_duration_statement = 500 # -1 is disabled, 0 logs all statements
# and their durations, > 0 logs only
log_min_duration_sample = 1 # -1 is disabled, 0 logs a sample of statements
# and their durations, > 0 logs only a sample of
# sample fraction is determined by log_statement_sample_rate
log_statement_sample_rate = 0.01 # fraction of logged statements exceeding
# log_min_duration_sample to be logged;
# 1.0 logs all such statements, 0.0 never logs
log_checkpoints = on
log_connections = on
log_disconnections = on
log_line_prefix = '%m, %p, %c, %l, %u, %d, %r, %a, %x, %v, %e, %i: ' # special values:
log_lock_waits = on # log lock waits >= deadlock_timeout
log_statement = 'ddl' # none, ddl, mod, all
log_temp_files = 0 # log temporary files equal or larger
# -1 disables, 0 logs all temp files
log_timezone = 'Europe/Prague'
log_autovacuum_min_duration = 0 # -1 disables, 0 logs all actions and
gilles-migops
darold
Hello, it looks pgbadger is unable to properly detect new log entries in the active log. Once the log is rotated, the content is parsed.
And a subsequent run a while later - as we can see from the
wcoutput, there are new lines (logon/logoff almost every second), but pgBadger did not realize that:Behaves same way with RPM version 11.7 and with the latest commit available at time of testing:
Sample log file entries: