Logging tweaks

[timkelty]

Description

• Allow devMode to be set via CRAFT_DEV_MODE in bootstrap
• Remove DbConfig::enableProfiling, DbConfig::enableLogging
  • Configure matching Connection props using devMode
• Default log level when in devMode is now LogLevel::INFO
• SQL queries are now logged as Craft::debug, meaning they won't be logged by default in devMode.
• microsecond precision is disabled by default for the timestamp (enabled via components.log.monologTargetConfig.useMicrosecondTimestamps)
• Request context is now only logged once per request, not in each log.
  • It is logged with a message of Request context, followed by the multiline var output (if allowLineBreaks), otherwise as single-line json.

When hitting actions/app/health-check in devMode, this reduces the logs from 52k to 3k (2 lines).

Related issues

• FIxes [4.x]: Default dev mode logging configuration should at least have a max file size #10903
• Logging via Monolog #10659

Examples:

Request with devMode:

With components.log.monologTargetConfig.allowLineBreaks set to true (the default, when in devMode)

[2022-04-14T17:25:53+00:00] web.INFO: Opening DB connection: pgsql:host=postgres-13-5432.database.nitro;dbname=craft4_dev;port=5432 {"trace":[],"memory":9625984,"category":"yii\\db\\Connection::open"} 
[2022-04-14T17:25:53+00:00] web.INFO: Request context
$_GET = []

$_POST = []

$_FILES = []

$_COOKIE = []

$_SERVER = [
    'PATH' => '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin'
    'HOSTNAME' => '4.craft.test'
    'PHP_DISPLAY_ERRORS' => 'on'
    'PHP_MEMORY_LIMIT' => '512M'
    'PHP_MAX_EXECUTION_TIME' => '5000'
    'PHP_UPLOAD_MAX_FILESIZE' => '512M'
    'PHP_MAX_INPUT_VARS' => '5000'
    'PHP_POST_MAX_SIZE' => '512M'
    'PHP_OPCACHE_ENABLE' => '0'
    'PHP_OPCACHE_REVALIDATE_FREQ' => '0'
    'PHP_OPCACHE_VALIDATE_TIMESTAMPS' => '0'
    'XDEBUG_SESSION' => 'PHPSTORM'
    'PHP_IDE_CONFIG' => 'serverName=4.craft.test'
    'XDEBUG_CONFIG' => 'client_host=host.docker.internal client_port=9003'
    'XDEBUG_MODE' => 'develop,debug'
    'IMAGE_USER' => 'nitro'
    'PHP_VERSION' => '8.0'
    'NVM_VERSION' => '0.38.0'
    'DEBIAN_FRONTEND' => 'noninteractive'
    'HOME' => '/home/nitro'
    'LC_CTYPE' => 'C.UTF-8'
    'SUPERVISOR_ENABLED' => '1'
    'SUPERVISOR_PROCESS_NAME' => 'php-fpm'
    'SUPERVISOR_GROUP_NAME' => 'php-fpm'
    'USER' => 'nitro'
    'HTTP_ACCEPT_ENCODING' => 'gzip'
    'HTTP_X_FORWARDED_PROTO' => 'https'
    'HTTP_X_FORWARDED_FOR' => '172.18.0.1'
    'HTTP_ACCEPT' => '*/*'
    'HTTP_USER_AGENT' => 'curl/7.79.1'
    'HTTP_HOST' => '4.craft.test'
    'SCRIPT_FILENAME' => '/app/web/index.php'
    'REDIRECT_STATUS' => '200'
    'SERVER_NAME' => ''
    'SERVER_PORT' => '80'
    'SERVER_ADDR' => '172.18.0.12'
    'REMOTE_USER' => ''
    'REMOTE_PORT' => '44484'
    'REMOTE_ADDR' => '172.18.0.19'
    'SERVER_SOFTWARE' => 'nginx/1.18.0'
    'GATEWAY_INTERFACE' => 'CGI/1.1'
    'REQUEST_SCHEME' => 'http'
    'SERVER_PROTOCOL' => 'HTTP/1.1'
    'DOCUMENT_ROOT' => '/app/web'
    'DOCUMENT_URI' => '/index.php'
    'REQUEST_URI' => '/'
    'SCRIPT_NAME' => '/index.php'
    'CONTENT_LENGTH' => ''
    'CONTENT_TYPE' => ''
    'REQUEST_METHOD' => 'GET'
    'QUERY_STRING' => ''
    'FCGI_ROLE' => 'RESPONDER'
    'PHP_SELF' => '/index.php'
    'REQUEST_TIME_FLOAT' => 1649957152.8935
    'REQUEST_TIME' => 1649957152
    'DEFAULT_SITE_URL' => 'https://4.craft.test/'
    'CRAFT_ENVIRONMENT' => 'dev'
    'CRAFT_SECURITY_KEY' => 'tmp'
    'CRAFT_DEV_MODE' => '1'
    'CRAFT_DB_DATABASE' => 'craft4_dev'
    'CRAFT_DB_USER' => 'nitro'
    'CRAFT_DB_PASSWORD' => 'nitro'
    'CRAFT_DB_DRIVER' => 'pgsql'
    'CRAFT_DB_SCHEMA' => 'public'
    'CRAFT_DB_SERVER' => 'postgres-13-5432.database.nitro'
]  {"ip":"172.18.0.1"}

With components.log.monologTargetConfig.allowLineBreaks set to false

[2022-04-14T17:22:09+00:00] web.INFO: Opening DB connection: pgsql:host=postgres-13-5432.database.nitro;dbname=craft4_dev;port=5432 {"trace":[],"memory":9626400,"category":"yii\\db\\Connection::open"} 
[2022-04-14T17:22:09+00:00] web.INFO: Request context  {"ip":"172.18.0.1","vars":{"_GET":[],"_POST":[],"_COOKIE":[],"_FILES":[],"_SERVER":{"PATH":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin","HOSTNAME":"4.craft.test","PHP_DISPLAY_ERRORS":"on","PHP_MEMORY_LIMIT":"512M","PHP_MAX_EXECUTION_TIME":"5000","PHP_UPLOAD_MAX_FILESIZE":"512M","PHP_MAX_INPUT_VARS":"5000","PHP_POST_MAX_SIZE":"512M","PHP_OPCACHE_ENABLE":"0","PHP_OPCACHE_REVALIDATE_FREQ":"0","PHP_OPCACHE_VALIDATE_TIMESTAMPS":"0","XDEBUG_SESSION":"PHPSTORM","PHP_IDE_CONFIG":"serverName=4.craft.test","XDEBUG_CONFIG":"client_host=host.docker.internal client_port=9003","XDEBUG_MODE":"develop,debug","IMAGE_USER":"nitro","PHP_VERSION":"8.0","NVM_VERSION":"0.38.0","DEBIAN_FRONTEND":"noninteractive","HOME":"/home/nitro","LC_CTYPE":"C.UTF-8","SUPERVISOR_ENABLED":"1","SUPERVISOR_PROCESS_NAME":"php-fpm","SUPERVISOR_GROUP_NAME":"php-fpm","USER":"nitro","HTTP_ACCEPT_ENCODING":"gzip","HTTP_X_FORWARDED_PROTO":"https","HTTP_X_FORWARDED_FOR":"172.18.0.1","HTTP_ACCEPT":"*/*","HTTP_USER_AGENT":"curl/7.79.1","HTTP_HOST":"4.craft.test","SCRIPT_FILENAME":"/app/web/index.php","REDIRECT_STATUS":"200","SERVER_NAME":"","SERVER_PORT":"80","SERVER_ADDR":"172.18.0.12","REMOTE_USER":"","REMOTE_PORT":"44474","REMOTE_ADDR":"172.18.0.19","SERVER_SOFTWARE":"nginx/1.18.0","GATEWAY_INTERFACE":"CGI/1.1","REQUEST_SCHEME":"http","SERVER_PROTOCOL":"HTTP/1.1","DOCUMENT_ROOT":"/app/web","DOCUMENT_URI":"/index.php","REQUEST_URI":"/","SCRIPT_NAME":"/index.php","CONTENT_LENGTH":"","CONTENT_TYPE":"","REQUEST_METHOD":"GET","QUERY_STRING":"","FCGI_ROLE":"RESPONDER","PHP_SELF":"/index.php","REQUEST_TIME_FLOAT":1649956928.400415,"REQUEST_TIME":1649956928,"DEFAULT_SITE_URL":"https://4.craft.test/","CRAFT_ENVIRONMENT":"dev","CRAFT_SECURITY_KEY":"•••","CRAFT_DEV_MODE":"1","CRAFT_DB_DATABASE":"craft4_dev","CRAFT_DB_USER":"nitro","CRAFT_DB_PASSWORD":"•••••","CRAFT_DB_DRIVER":"pgsql","CRAFT_DB_SCHEMA":"public","CRAFT_DB_SERVER":"postgres-13-5432.database.nitro"}}}

[khalwat]

Remove DbConfig::enableProfiling, DbConfig::enableLogging

Man. I just added these... 😄

[timkelty]

@khalwat You can still configure them. I'll include examples. You also wont really need to, because they'll only take effect if you manually override the default level to be more verbose.

[khalwat]

Are you planning to add back in the rather useful method context that was in Craft 3 logs?

Craft 3:

2022-04-13 12:15:22 [-][1][-][info][yii\db\Connection::open] Opening DB connection:

Craft 4:

[2022-04-08T19:05:09.197562+00:00] web.INFO: Opening DB connection:

That lack of method context ([yii\db\Connection::open]) is pretty important to me when looking at log files. Also would love it if changes to the log file format (e.g.: web.ERROR instead of [error]) weren't done arbitrarily.

Not sure why listing the log file in the log file is useful, except maybe for streamed logs where everything is combined? If that's the reasoning, could I suggest instead: [web][error]? I think the old Yii2 formatting method of separating categories in []s was. more readable.

I also find the new date/time format to be less readable too (yes, I know, ISO, etc.)

[timkelty]

Are you planning to add back in the rather useful method context that was in Craft 3 logs?

What you're referring to is the category (which is often logged as __METHOD__). That is there in the Craft 4, at the end of the message:

[2022-04-14T17:22:09.232670+00:00] web.INFO: Opening DB connection: pgsql:host=postgres-13-5432.database.nitro;dbname=craft4_dev;port=5432 {"trace":[],"memory":9626400,"category":"yii\\db\\Connection::open"} 

You were likely missing it before because I was erroneously adding all the global vars there too.

Also would love it if changes to the log file format (e.g.: web.ERROR instead of [error]) weren't done arbitrarily.

Not arbitrary. What you're seeing is Monolog's default formatter: LineFormatter::SIMPLE_FORMAT

While you can easily change this by setting components.log.monologTargetConfig.formatter to whatever you want in config/app.php, I'd probably recommend just "getting used to it", if your changes are superficial-ish. While they may feel different from a Craft perspective, they'll probably feel familiar to other non-Craft PHP users.

I also find the new date/time format to be less readable too (yes, I know, ISO, etc.)

Again, we're using stock Monolog settings here: NormalizerFormatter::SIMPLE_DATE. I also much prefer the TZ being in there so there's no guessing. I do agree that the microseconds are annoying. I've updated the PR do disable those by default.

---

We will be working on docs with examples of how to customize all of this.

[timkelty]

@brandonkelly when you review, can you look at the TODO line here:

cms/src/log/Dispatcher.php

Lines 83 to 85 in fdb540b

	// TODO: Ask about except/levels
	$queueTarget->except = ['yii\*'];
	$queueTarget->setLevels(['info', 'warning', 'error']);

It was taken verbatim from https://github.com/craftcms/cms/blob/develop/src/queue/QueueLogBehavior.php#L99-L102, but wasn't 💯 sure what the purpose was.

[brandonkelly]

@timkelty The Craft 3 comment says Prevent verbose system logs so guessing it’s something to do with that? Maybe try comparing what the queue logs look like with/without it.