Project

General

Profile

Actions

Bug #98159

closed

Logging Levels not working correctly, starts at warning.

Added by Melanie Laschinger over 2 years ago. Updated about 2 years ago.

Status:
Closed
Priority:
Should have
Assignee:
-
Category:
Logging
Target version:
-
Start date:
2022-08-17
Due date:
% Done:

0%

Estimated time:
TYPO3 Version:
11
PHP Version:
7.4
Tags:
Complexity:
Is Regression:
Sprint Focus:

Description

If you enable the logging level debug, info or notice it works fine.
All logging levels above are enabled.

Expample which is not working:
If you enable the logging level warning you get one warning message in the logging file (which is correct)
but all messages for each logging levels above printed twice.

The Excecution of logging level error ( $this->logger->error('ERROR: My class is executed.'); ) in our function
and error enabled in LocalConfiguration results:

Wed, 17 Aug 2022 10:42:47 +0200 [WARNING] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ERROR] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ERROR] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [CRITICAL] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [CRITICAL] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ALERT] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ALERT] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [EMERGENCY] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [EMERGENCY] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

In this case we are not expecting the warning message and no double messages like error, critical, alert and emergency.

The same Bug exists with critical, alert and emergency.

Full Debug on one call:

$this->logger->debug('DEBUG: My class is executed.');
$this->logger->info('INFO: My class is executed.');
$this->logger->notice('NOTICE: My class is executed.');
$this->logger->warning('WARNING: My class is executed.');
$this->logger->error('ERROR: My class is executed.');
$this->logger->critical('CRITICAL: My class is executed.');
$this->logger->alert('ALERT: My class is executed.');
$this->logger->emergency('EMERGENCY: My class is executed.');

DEBUG enabled:

Wed, 17 Aug 2022 10:39:42 +0200 [DEBUG] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": DEBUG: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [INFO] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": INFO: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [NOTICE] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": NOTICE: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [WARNING] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [WARNING] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [ERROR] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [ERROR] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [ERROR] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [CRITICAL] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [CRITICAL] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [CRITICAL] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [ALERT] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [ALERT] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [ALERT] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [EMERGENCY] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [EMERGENCY] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:39:42 +0200 [EMERGENCY] request="a7b3fec7127cc" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

INFO enabled:

Wed, 17 Aug 2022 10:40:37 +0200 [INFO] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": INFO: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [NOTICE] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": NOTICE: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [WARNING] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [WARNING] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [ERROR] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [ERROR] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [ERROR] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [CRITICAL] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [CRITICAL] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [CRITICAL] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [ALERT] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [ALERT] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [ALERT] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [EMERGENCY] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [EMERGENCY] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:40:37 +0200 [EMERGENCY] request="428ce0dfcee00" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

NOTICE enabled:

Wed, 17 Aug 2022 10:41:19 +0200 [NOTICE] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": NOTICE: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [WARNING] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [WARNING] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [ERROR] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [ERROR] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [ERROR] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [CRITICAL] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [CRITICAL] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [CRITICAL] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [ALERT] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [ALERT] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [ALERT] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [EMERGENCY] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [EMERGENCY] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:41:19 +0200 [EMERGENCY] request="60be54ed33939" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

WARNING enabled:

Wed, 17 Aug 2022 10:41:55 +0200 [WARNING] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [ERROR] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [ERROR] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [CRITICAL] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [CRITICAL] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [ALERT] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [ALERT] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [EMERGENCY] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:41:55 +0200 [EMERGENCY] request="427ed4804ef4d" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

ERROR enabled:

Wed, 17 Aug 2022 10:42:47 +0200 [WARNING] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ERROR] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ERROR] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [CRITICAL] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [CRITICAL] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ALERT] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [ALERT] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [EMERGENCY] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:42:47 +0200 [EMERGENCY] request="4a6701ecca766" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

CRITICAL enabled:

Wed, 17 Aug 2022 10:43:29 +0200 [WARNING] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [ERROR] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [ERROR] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [CRITICAL] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [CRITICAL] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [CRITICAL] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [ALERT] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [ALERT] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [ALERT] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [EMERGENCY] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [EMERGENCY] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:43:29 +0200 [EMERGENCY] request="6275da42e20ea" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

ALERT enabled:

Wed, 17 Aug 2022 10:43:57 +0200 [WARNING] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [ERROR] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [ERROR] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [CRITICAL] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [CRITICAL] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [ALERT] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [ALERT] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [ALERT] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [EMERGENCY] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [EMERGENCY] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:43:57 +0200 [EMERGENCY] request="d197b09ec6241" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

EMERGENCY enabled:

Wed, 17 Aug 2022 10:44:40 +0200 [WARNING] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": WARNING: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [ERROR] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [ERROR] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": ERROR: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [CRITICAL] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [CRITICAL] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": CRITICAL: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [ALERT] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [ALERT] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": ALERT: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [EMERGENCY] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [EMERGENCY] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.
Wed, 17 Aug 2022 10:44:40 +0200 [EMERGENCY] request="bc68e79f3194e" component="Vendor.MyExtension.Controller.MyController": EMERGENCY: My class is executed.

Actions #1

Updated by Markus Klein over 2 years ago

Where do you call those logger->*() functions? Backend or Frontend?

Actions #2

Updated by Melanie Laschinger over 2 years ago

We are calling those logger->*() in the frontend in one of our extensions in listAction.

Actions #3

Updated by Markus Klein over 2 years ago

  • Status changed from New to Needs Feedback

I'm failing to reproduce this.

Can you maybe debug the FileWriter or Logger::log calls in your instance and see where those calls and records come from?
I've currently no idea, where such a behaviour should come from.

Please also dump your LOG configuration here. (From the Configuration module)
Maybe you configured two loggers writing to the same file?

Actions #4

Updated by Melanie Laschinger about 2 years ago

You are absolutely right.

I have configured two loggers in two different configuration.

Now I know why the warning was always present because it is default.

Maybe you can document somewhere that the warning logging level is default.

Thank you for your help.

Actions #5

Updated by Markus Klein about 2 years ago

  • Status changed from Needs Feedback to Closed
Actions #6

Updated by Markus Klein about 2 years ago

This information is permanently present. Take a look at the Configuration module for LOG.
Also the default is noted here: https://docs.typo3.org/m/typo3/reference-coreapi/11.5/en-us/ApiOverview/Logging/Quickstart/Index.html#set-logging-output

Actions

Also available in: Atom PDF