bug on log generation ? - Mailing list pgsql-hackers

From Marcos Pegoraro
Subject bug on log generation ?
Date
Msg-id CAB-JLwbmTieFK00SBSGczcTrXKTWs1s4XMHQjZBreq84c_0NOw@mail.gmail.com
Whole thread Raw
Responses Re: bug on log generation ?
List 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.l@hotmail.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

pgsql-hackers by date:

Previous
From: Tomas Vondra
Date:
Subject: Re: logical decoding and replication of sequences
Next
From: Dave Cramer
Date:
Subject: Re: default result formats setting