search

darold / pgbadger

A fast PostgreSQL Log Analyzer
http://pgbadger.darold.net/
PostgreSQL License
3.54k stars 353 forks source link

pgbadger not parsing log #468

Closed MichalPP closed 5 years ago

MichalPP commented 5 years ago

pgbadger v10.2 fails to find any queries in the following log (by postgresql 10):

2019-01-19 20:32:59 CET ERROR:  parse error - invalid geometry at character 130
2019-01-19 20:32:59 CET STATEMENT:  select osm_id, uri, st_x(geometry(way)) as lon, st_y(geometry(way)) as lat,  name, 'wikipedia' as typ_elementu, st_distance(way, '') as vzdialenost , (st_azimuth(ST_ClosestPoint(geometry(''), geometry(way)), geometry(way))*180/pi()) as azimut  from wikipedia where (true) and way && st_buffer(''::geography, 100) and osm_id != 2906297401 order by st_distance(way, '') limit 29
2019-01-19 20:33:01 CET LOG:  duration: 21.701 ms  statement: select * from trasy where (osm_id::text = '-6477564' or ref ilike '-6477564') and typ = 'turistika' order by st_length(way) desc limit 1
2019-01-19 01:58:02 CET LOG:  duration: 1090.729 ms  statement: select * from fotos where st_dwithin('0101000020E610000010FCB9B2553535402F7A5D75D36C4840', way, 100, false) order by st_distance('0101000020E610000010FCB9B2553535402F7A5D75D36C4840', way) limit 12
2019-01-19 20:33:01 CET LOG:  duration: 42.598 ms  statement: select osm_id, t, name, tags->'lon' as lon, tags->'lat' as lat, way, popis, popis_maly, way, case when way_full is null then way else way_full end as way_full, (select concat('<div class="box">', string_agg(concat('<a href="https://', name_asci, '.oma.sk">', name, '</a>'), ' &raquo; ' order by st_area(oblasti.waym) desc ), '</div>') from oblasti where oblasti.osm_id = any(oblasti_ids) and st_covers(oblasti.way,poi.way) and typ in ('obec', 'okres','kraj', 'sr','nuts2', 'region','mikroregion') ) as cesta, (select string_agg(concat(name, ', ', name_asci), ', ') from oblasti where osm_id = any(oblasti_ids)) || ', ' || (select string_agg(concat(nazov, ', ', name, ', ', keywords), ', ') from oma_poi where name = any(typy) ) as keywords, case when typy && '{restaruacia,pohostinstvo,kaviaren,fastfood,pizzeria,bar,cajovna,palacinkaren}' then 'restarant.restarant' else 'place' end as og_type, (select name from oblasti where oblasti.osm_id = any(oblasti_ids) order by st_area(oblasti.waym) asc limit 1) as og_locality from poi where osm_id='5094533532' and t = 'n'
2019-01-19 20:33:01 CET LOG:  duration: 28.078 ms  statement: select trasy.*, 'trasy' as typ_elementu, st_x(st_closestpoint(geometry(way), '0101000020E6100000D423B2B4F80533404AEB14504D9F4840')) as lon, st_y(st_closestpoint(geometry(way), '0101000020E6100000D423B2B4F80533404AEB14504D9F4840')) as lat from trasy, zastavky where abs(trasy.osm_id) = zastavky.id and typ='mhd' and array['n5094533532'] && members
2019-01-19 20:33:01 CET LOG:  duration: 50.070 ms  statement: select osm_id, t, name, tags->'lon' as lon, tags->'lat' as lat, way, popis, popis_maly, way, case when way_full is null then way else way_full end as way_full, (select concat('<div class="box">', string_agg(concat('<a href="https://', name_asci, '.oma.sk">', name, '</a>'), ' &raquo; ' order by st_area(oblasti.waym) desc ), '</div>') from oblasti where oblasti.osm_id = any(oblasti_ids) and st_covers(oblasti.way,poi.way) and typ in ('obec', 'okres','kraj', 'sr','nuts2', 'region','mikroregion') ) as cesta, (select string_agg(concat(name, ', ', name_asci), ', ') from oblasti where osm_id = any(oblasti_ids)) || ', ' || (select string_agg(concat(nazov, ', ', name, ', ', keywords), ', ') from oma_poi where name = any(typy) ) as keywords, case when typy && '{restaruacia,pohostinstvo,kaviaren,fastfood,pizzeria,bar,cajovna,palacinkaren}' then 'restarant.restarant' else 'place' end as og_type, (select name from oblasti where oblasti.osm_id = any(oblasti_ids) order by st_area(oblasti.waym) asc limit 1) as og_locality from poi where osm_id='451717336' and t = 'n'
2019-01-19 20:33:01 CET LOG:  duration: 32.117 ms  statement: select trasy.*, 'trasy' as typ_elementu, st_x(st_closestpoint(geometry(way), '0101000020E610000062D7F6764B1A3240F40BC050D1E04740')) as lon, st_y(st_closestpoint(geometry(way), '0101000020E610000062D7F6764B1A3240F40BC050D1E04740')) as lat from trasy, zastavky where abs(trasy.osm_id) = zastavky.id and typ='mhd' and array['n451717336'] && members
2019-01-19 20:33:02 CET LOG:  duration: 100.097 ms  statement: select osm_id, name, ref, typ, 'trasy' as typ_elementu, st_x(way) as lon, st_y(way) as lat, vzdialenost, trasauri(osm_id, typ, ref, popis_maly) as uri , st_azimuth(ST_ClosestPoint(geometry('0101000020E6100000D423B2B4F80533404AEB14504D9F4840'), geometry(way)), way)*180/pi() as azimut  from (select osm_id, typ, name, ref, popis_maly, ST_ClosestPoint(geometry(way), geometry('0101000020E6100000D423B2B4F80533404AEB14504D9F4840')) as way, st_distance(way, '0101000020E6100000D423B2B4F80533404AEB14504D9F4840') as vzdialenost from trasy where st_dwithin(way, '0101000020E6100000D423B2B4F80533404AEB14504D9F4840', 300, false) and typ ='turistika' and osm_id != 5094533532 ) as trasa order by vzdialenost asc limit 15
2019-01-19 20:33:02 CET LOG:  duration: 29.809 ms  statement: select osm_id, name, ref, typ, 'trasy' as typ_elementu, st_x(way) as lon, st_y(way) as lat, vzdialenost, trasauri(osm_id, typ, ref, popis_maly) as uri , st_azimuth(ST_ClosestPoint(geometry('0101000020E610000062D7F6764B1A3240F40BC050D1E04740'), geometry(way)), way)*180/pi() as azimut  from (select osm_id, typ, name, ref, popis_maly, ST_ClosestPoint(geometry(way), geometry('0101000020E610000062D7F6764B1A3240F40BC050D1E04740')) as way, st_distance(way, '0101000020E610000062D7F6764B1A3240F40BC050D1E04740') as vzdialenost from trasy where st_dwithin(way, '0101000020E610000062D7F6764B1A3240F40BC050D1E04740', 300, false) and typ ='cyklotrasa' and osm_id != 451717336 ) as trasa order by vzdialenost asc limit 15

command that should work, is pgbadger -f stderr --prefix '%t ' /tmp/pg/t.log -o out.html

pgbadger produces histogram of queries, but it does not display any individual slow queries entry.

however, if I remove the first query from the above log (first two lines), pgbadger finds just one query (the second one), the other queries are ignored.

any hints on how to solve?

darold commented 5 years ago

Hi, This is a normal behavior, the documentation says:

pgBadger supports any custom format set into the log_line_prefix directive of
your postgresql.conf file as long as it at least specify the %t and %p patterns.

that mean that a log_line_prefix: %t [%p]: should be enough.

MichalPP commented 5 years ago

thanks

for those searching:

you have to change postgresql.conf settings so that variable log_line_prefix includes %t and %p. for example %t [%p]:. then postgresql will produce log parsable by pgbadger. posgresql variable log_line_prefix must match pgbadger --prefix

%t and %p are described in postgresql documentation:

#   %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