bug on log generation ?

From: Marcos Pegoraro <marcos(at)f10(dot)com(dot)br>
To: pgsql-hackers <pgsql-hackers(at)postgresql(dot)org>
Subject: bug on log generation ?
Date: 2022-08-07 13:56:10
Message-ID: CAB-JLwbmTieFK00SBSGczcTrXKTWs1s4XMHQjZBreq84c_0NOw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

I have to fix log files because its content is not properly formatted, I´m
using version 14.4 but that happened when I was using version 11 too. It
happens only when that statement is huge, or because it is a long sequence
of updates in a WITH or DO statements, or because i´m updating a bytea
field. This kind of statement occurs on log dozens of times a day, but just
2 or 3 are wrongly formatted.

one example is a WITH statement with dozens of inserts and updates on it
2022-08-06 10:05:10.822
-03,"user_0566","db",1956432,"10.158.0.17:56098",62ee66ee.1dda50,1,"SELECT",2022-08-06
10:04:46 -03,266/383801,229907216,LOG,00000,"duration: 1735.107 ms execute
PRSTMTST155939968154/PORTALST155939968154: /*Cobranca.ImportaCobranca*/
WITH Receber1 AS (UPDATE fin_Re>
NNLiquidado1 AS (UPDATE fin_ReceberNossoNumero SET Status = 7 WHERE
NossoNumero = any($${90062164}$$)),
--statement continues, with some more dozens of update/inserts
NNDesconsiderado48 AS (UPDATE fin_recebernossonumero SET status = 9 WHERE
receber_id = 104201 AND status = 1 AND nossonumero <> 90086321),
NNExcluir48 AS (UPDATE fin_recebernossonumero SET status = 4 WHERE
receber_id = 104201 AND status = any($IN${2,3}$IN$) AND nossonumero <>
90086321 RETURNING recebernossonumero_id),
Baixa48 AS (INSERT INTO fin_ReceberBaixa(Historico, Desconto, Valor,
Lancamento) VALUES ($vs$Paga2022-08-06 10:07:07.505
-03,"user_0566","db",1956432,"10.158.0.17:56098",62ee66ee.1dda50,2,"idle",2022-08-06
10:04:46 -03,266/0,0,FATAL,57P01,"terminating connection due to
administrator command",,,,,,,,,"2022062701adriana.aguiar","client
backend",,0
2022-08-06 10:07:07.507
-03,"user_0328","db",1957035,"10.158.0.17:57194",62ee6730.1ddcab,1,"idle",2022-08-06
10:05:52 -03,410/0,0,FATAL,57P01,"terminating connection due to
administrator command",,,,,,,,,"2022062701tmk06.madureira","client
backend",,0

if you search for "$vs$Paga2022-08-06 10:07:07.505" you´ll see that
"$vs$Paga" is still part of first statement but "2022-08-06 10:07:07.505"
is the starting of next statement, but there are some missing chars of
previous statement.

another example is just one update with a large bytea field on it
2022-08-06 15:57:46.955
-03,"user_0591","db",2103042,"10.158.0.17:43662",62eeb9aa.201702,1,"INSERT",2022-08-06
15:57:46 -03,49/639939,230013197,LOG,00000,"duration: 11.012 ms execute
PRSTMTST1612483842/PORTALST1612483842: WITH upsert AS (
UPDATE sys_var SET varBlob = $1 WHERE name = $2 RETURNING *) INSERT
INTO sys_var (Name, varBlob) SELECT $3 , $4 WHERE NOT EXISTS (SELECT *
FROM upsert)","parameters: $1 =
'\x3c3f786d6 --field content continues
$2 = '/users/39818/XMLConfig', $3 = '/users/39818/XMLConfig', $4 =
'\x3c3f786d6 --field content continues
e4445583e2d313c2f47524f555045445f494e4445583e32022-08-06 15:58:42.436
-03,"user_0591","db",2103042,"10.158.0.17:43662",62eeb9aa.201702,2,"idle",2022-08-06
15:57:46 -03,49/0,0,FATAL,57P01,"terminating connection due to
administrator command",,,,,,,,,"","client backend",,-4199849316459484872
2022-08-06 15:58:42.436
-03,"user_0143","db",2103112,"10.158.0.17:43794",62eeb9bf.201748,1,"idle",2022-08-06
15:58:07 -03,44/0,0,FATAL,57P01,"terminating connection due to
administrator command",,,,,,,,,"2022062701joyceb(dot)l(at)hotmail(dot)com","client
backend",,0

Here "4445583e32022-08-06 15:58:42.436", where bytea content "4445583e" was
being displayed and the next statement started with "32022-08-06
15:58:42.436".

Obviously because that the previous line is not finished correctly and I
cannot import log files properly, so I have to edit those log files to
properly import them.

thanks
Marcos

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Dave Cramer 2022-08-07 14:08:35 Re: default result formats setting
Previous Message Tom Lane 2022-08-07 13:44:07 Re: pgsql: BRIN: mask BRIN_EVACUATE_PAGE for WAL consistency checking