Queue messages are logged twice
Open, LowPublic
Actions

Assigned To

None

Authored By

	Cstone
	Jan 23 2025, 5:05 AM

Description

I really thought we had fixed this, at least attempted before. Not sure if there was a previous task, I couldn't find it.

The message is logged, then immediately again with class_name, message

Example message:
2025-01-23 01:10:06,215 ERROR civicrm.wmf.INFO: RecurringQueueConsumer array{"txn_type":"subscr_cancel","rescue_reference":"ZJ2HKCRVMB383Z59","is_
autorescue":true,"cancel_reason":"Payment cannot be rescued: maximum failures reached","source_name":"SmashPig","source_type":"listener","source_hos
t":"frpig1002","source_run_id":1224135,"source_version":"1d060a11706b20479061205a7b6f02a0e4f9b0ed","source_enqueued_time":1737594343} {"class_name":
"RecurringQueueConsumer","message":{"txn_type":"subscr_cancel","rescue_reference":"ZJ2HKCRVMB383Z59","is_autorescue":true,"cancel_reason":"Payment c
annot be rescued: maximum failures reached","source_name":"SmashPig","source_type":"listener","source_host":"frpig1002","source_run_id":1224135,"sou
rce_version":"1d060a11706b20479061205a7b6f02a0e4f9b0ed","source_enqueued_time":1737594343}}

Related Objects

Mentioned In: T412492: Queue consumers duplicating all 'wmf' log lines
Mentioned Here: rWFSP1d060a11706b: Merge branch 'master' into deployment

Event Timeline

Cstone created this task.Jan 23 2025, 5:05 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 23 2025, 5:05 AM

Damilare added a project: Fundraising Tech - Chaos Crew.Jan 28 2025, 8:17 PM

Damilare moved this task from Triage to Chaos Crew Backlog on the Fundraising-Backlog board.

XenoRyet triaged this task as Low priority.Feb 3 2025, 9:14 PM

XenoRyet moved this task from Chaos Crew Backlog to Chaos Holding Pen on the Fundraising-Backlog board.Oct 17 2025, 6:14 PM

XenoRyet edited projects, added Fundraising Tech Chaos Holding Pen; removed Fundraising Tech - Chaos Crew.Oct 17 2025, 6:17 PM

I have an explanation for this ...

We have 2 standard out loggers - in theory the wmf_cli one logs for wmf channel (only) for info and above and cli_std_out_l logs for all channels when the level is warning and above - so info is only logged by the former & only for wmf

id	name	type	channel	minimum_severity	is_final	weight
5	syslog	syslog	*	error	0	-2
7	wmf_cli	std_err	wmf	info	0	1
8	acoustic_info	mail	Silverpop	info	0	1
9	alert_failmail	mail	*	alert	0	1
6	cli_std_out_l...	std_err	*	warning	0	8
1	wmf_syslog	syslog	wmf	debug	1	10
2	default_logger	log_file	*	debug	0	15

However, IF we use --vv on the command line the log level for the latter one is adjusted per

'-v' => 'notice',
'--verbose' => 'notice',
'--debug' => 'debug',
'-d' => 'debug',
'-q' => 'error',
'--quiet' => 'error',
// https://symfony.com/doc/current/logging/monolog_console.html
'-vv' => 'info',
'-vvv' => 'debug',

In practice this means it always runs at info level & we get stuff twice

I am going to disable the wmf_cli on grounds of it being redundant - we could increase the weight & make the other final - but I'm struggling to make a case for that.

Ejegg mentioned this in T412492: Queue consumers duplicating all 'wmf' log lines.Mar 9 2026, 9:42 PM

Queue messages are logged twiceOpen, LowPublicActions

Description

Related Objects

Event Timeline

Queue messages are logged twice
Open, LowPublic
Actions