Zen and the Art of Craft CMS Log File Reading

Like a black box record­ing, log files con­tain pre­cious foren­sic infor­ma­tion for when you have to diag­nose prob­lems. Let’s learn the art of read­ing them

Andrew Welch / nystudio107

The age old prac­tice of log­ging is used in pro­gram­ming to pro­vide a record of not just errors that hap­pen, but also gen­er­al sta­tus infor­ma­tion. It’s this con­text that makes them use­ful when you’re try­ing to fig­ure out what happened.

                            Or more often than not, <span></span>​<span>“</span>What went wrong?”

Log files are your ​“black box” record­ing of what hap­pened, allow­ing you to piece things togeth­er post-fac­to when some­thing goes wrong.

Craft CMS Debugging

Craft CMS is no dif­fer­ent, in that it cre­ates a num­ber of logs to help you. If you’re debug­ging in local dev, I rec­om­mend using the Debug Tool­bar as dis­cussed in the Pro­fil­ing your Web­site with Craft CMS 3’s Debug Tool­bar article:

The Debug Tool­bar pro­vides access to the Craft CMS logs in a nice GUI that allows you to eas­i­ly search, sort, and fil­ter in a vari­ety of ways. For more infor­ma­tion on using the Debug Tool­bar, please see the Pro­fil­ing your Web­site with Craft CMS 3’s Debug Tool­bar article.

In many cas­es you’ll need to debug a prob­lem that you only have log files to go on, because:

• You can’t repro­duce the issue locally
• You don’t have any steps to repro­duce the issue
• The issue hap­pened on some­one else’s website

In these cas­es, we’ll be rely­ing on log files to find out what hap­pened, so let’s have a look what the var­i­ous log files look like in Craft CMS.

Craft CMS Log Files

Craft CMS cre­ates a a num­ber of log files in the storage/logs/ direc­to­ry. The for­mat of the infor­ma­tion logged in each is the same, but the files are seg­re­gat­ed to make it eas­i­er to read through them.

Here are the log files that Craft CMS cre­ates in the storage/logs/ directory:

• web.log — this is the pri­ma­ry web log file where most log­ging from Craft CMS & plu­g­ins will end up
• web404s.log — this is where the details of any 404 not found http requests are logged; they are logged sep­a­rate­ly to keep from clut­ter­ing up the web.log
• console.log — this con­sole or CLI ver­sion of web.log; when you run Craft via the CLI, this is where most log­ging from Craft CMS & plu­g­ins will end up
• queue.log — this is where any log­ging from queue jobs (such as ​“Resav­ing Ele­ments”) ends up, whether run via the web or CLI
• phperrors.log — this is where hard PHP errors that could­n’t be han­dled by Yii2’s excep­tion han­dling are stored

Even if you use a third par­ty log­ging ser­vice such as Paper­Trail or Sen­try to redi­rect or aggre­gate your Craft CMS logs, the infor­ma­tion in this arti­cle will still help you digest the Craft logs.

A typ­i­cal storage/logs/ direc­to­ry might look like this:

vagrant@homestead ~/sites/craft3/storage/logs $ ls -al
total 63632
drwxr-xr-x 12 vagrant vagrant 384 Jul 20 2019 .
drwxr-xr-x 10 vagrant vagrant 320 Feb 16 03:11 ..
-rw-r--r-- 1 vagrant vagrant 180660 Jul 17 03:03 console.log
-rw-r--r-- 1 vagrant vagrant 389886 Jul 17 02:05 queue.log
-rw-r--r-- 1 vagrant vagrant 132927 Jul 20 2019 web-404s.log
-rw-r--r-- 1 vagrant vagrant 8072957 Jul 20 2019 web.log
-rw-r--r-- 1 vagrant vagrant 10497035 Jul 18 20:37 web.log.1
-rw-r--r-- 1 vagrant vagrant 10578305 Jul 18 20:37 web.log.2
-rw-r--r-- 1 vagrant vagrant 10555544 Jul 18 20:37 web.log.3
-rw-r--r-- 1 vagrant vagrant 10555546 Jul 18 20:37 web.log.4
-rw-r--r-- 1 vagrant vagrant 10578305 Jul 18 20:37 web.log.5

Note that all of the logs rotate as soon as they reach the max­i­mum file size of 10,240KB, up to the a max­i­mum of 5 rotat­ed logs (both default max­i­mums can be changed via app.php con­fig). So in the above exam­ple, the web.log.5 file is the old­est log file, and web.log is the cur­rent log file.

Dis­sect­ing a Craft CMS Log File Line

Let’s dis­sect a line from my web.log file:

2019-03-04 00:08:49 [-][1][mivsgmhfgalsu5k7cv1f0q8m13][trace][yii\base\Module::getModule] Loading module: site-module

• 2019-03-04 00:08:49 — Date and time of the logged mes­sage (for­mat­ted as Y-m-d H:i:s in serv­er time)
• [-] — The IP address of the client, by default redact­ed to - for GDPR com­pli­ance
• [1] — The user ID of the cur­rent­ly logged in user (or - if no user is logged in)
• [mivsgmhfgalsu5k7cv1f0q8m13] — The ses­sion ID (or - if no ses­sion exists)
• [trace] — The lev­el of the log mes­sage (n.b. trace is aka debug, see below)
• [yii\base\Module::getModule] — The cat­e­go­ry of the log mes­sage, usu­al­ly set to the class::method that called the log­ging, via METHOD
• Loading module: site-module — The log mes­sage itself

Let’s have a look at the log lev­els you’ll encounter:

• debug (aka trace)- a mes­sage to trace how a piece of code runs. This is main­ly for devel­op­ment use.
• info — a mes­sage that con­veys some use­ful information.
• warning — a warn­ing mes­sage that indi­cates some­thing unex­pect­ed has happened.
• error — a fatal error that should be inves­ti­gat­ed as soon as possible.
• profile — a spe­cial type of mes­sage log­ging that is used to mea­sure the time tak­en by cer­tain code blocks

It’s impor­tant to note that unless dev­Mode is on, Craft will only log lev­els warning, error & profile. We don’t cov­er the pro­file lev­el here, for more infor­ma­tion on that, check out the Pro­fil­ing your Web­site with Craft CMS 3’s Debug Tool­bar article.

Since Craft CMS is based on the Yii2 frame­work, you can read up on the gory details of Yii2 Log­ging here.

Now that we have a ground­ing on what is in the Craft CMS logs, let’s dive into how to read the tea leaves.

Divin­ing Mean­ing from the Craft CMS log files

So great, we’re armed with the knowl­edge of what the var­i­ous log files are in Craft CMS, and also what each log line looks like. But there’s a ton of infor­ma­tion logged by Craft, espe­cial­ly if devMode is on.

If devMode is enabled, in addi­tion to error, warning, & profile log lev­els, we’re also log­ging trace (aka debug) and info log lev­els too.

While in the­o­ry this may not seem like it’s not such a big deal adding 2 more log lev­els, in prac­tice it’s actu­al­ly adding heaps of infor­ma­tion to the logs files. Part of the rea­son is that every data­base query is now logged:

2019-03-04 00:08:49 [-][-][mivsgmhfgalsu5k7cv1f0q8m13][profile begin][yii\db\Command::query] SELECT
    d.nspname AS table_schema,
    c.relname AS table_name,
    a.attname AS column_name,
    COALESCE(td.typname, tb.typname, t.typname) AS data_type,
    COALESCE(td.typtype, tb.typtype, t.typtype) AS type_type,
    a.attlen AS character_maximum_length,
    pg_catalog.col_description(c.oid, a.attnum) AS column_comment,
    a.atttypmod AS modifier,
    a.attnotnull = false AS is_nullable,
    CAST(pg_get_expr(ad.adbin, ad.adrelid) AS varchar) AS column_default,
    coalesce(pg_get_expr(ad.adbin, ad.adrelid) ~ 'nextval',false) AS is_autoinc,
    CASE WHEN COALESCE(td.typtype, tb.typtype, t.typtype) = 'e'::char
        THEN array_to_string((SELECT array_agg(enumlabel) FROM pg_enum WHERE enumtypid = COALESCE(td.oid, tb.oid, a.atttypid))::varchar[], ',')
        ELSE NULL
    END AS enum_values,
    CASE atttypid
         WHEN 21 /*int2*/ THEN 16
         WHEN 23 /*int4*/ THEN 32
         WHEN 20 /*int8*/ THEN 64
         WHEN 1700 /*numeric*/ THEN
              CASE WHEN atttypmod = -1
               THEN null
               ELSE ((atttypmod - 4) >> 16) & 65535
               END
         WHEN 700 /*float4*/ THEN 24 /*FLT_MANT_DIG*/
         WHEN 701 /*float8*/ THEN 53 /*DBL_MANT_DIG*/
         ELSE null
      END AS numeric_precision,
      CASE
        WHEN atttypid IN (21, 23, 20) THEN 0
        WHEN atttypid IN (1700) THEN
        CASE
            WHEN atttypmod = -1 THEN null
            ELSE (atttypmod - 4) & 65535
        END
           ELSE null
      END AS numeric_scale,
    CAST(
             information_schema._pg_char_max_length(information_schema._pg_truetypid(a, t), information_schema._pg_truetypmod(a, t))
             AS numeric
    ) AS size,
    a.attnum = any (ct.conkey) as is_pkey,
    COALESCE(NULLIF(a.attndims, 0), NULLIF(t.typndims, 0), (t.typcategory='A')::int) AS dimension
FROM
    pg_class c
    LEFT JOIN pg_attribute a ON a.attrelid = c.oid
    LEFT JOIN pg_attrdef ad ON a.attrelid = ad.adrelid AND a.attnum = ad.adnum
    LEFT JOIN pg_type t ON a.atttypid = t.oid
    LEFT JOIN pg_type tb ON (a.attndims > 0 OR t.typcategory='A') AND t.typelem > 0 AND t.typelem = tb.oid OR t.typbasetype > 0 AND t.typbasetype = tb.oid
    LEFT JOIN pg_type td ON t.typndims > 0 AND t.typbasetype > 0 AND tb.typelem = td.oid
    LEFT JOIN pg_namespace d ON d.oid = c.relnamespace
    LEFT JOIN pg_constraint ct ON ct.conrelid = c.oid AND ct.contype = 'p'
WHERE
    a.attnum > 0 AND t.typname != ''
    AND c.relname = 'retour_redirects'
    AND d.nspname = 'public'
ORDER BY
    a.attnum;

And there are lots of them, so the pile you have to search through gets large quick. This ​“log every­thing” strat­e­gy is actu­al­ly very use­ful when you’re doing foren­sics to fig­ure out what hap­pened. The more con­text the better.

But it’s also a bit like look­ing for a nee­dle in a haystack to find what’s real­ly rel­e­vant to you.

So let’s have a look at a few strate­gies that can help find what we’re look­ing for.

1. DELETE THE LOGS

If you’re attempt­ing to repro­duce an issue (espe­cial­ly in local dev), one way to make sift­ing through piles of infor­ma­tion eas­i­er is to have less infor­ma­tion to sift through!

1. Nav­i­gate to the fron­tend page or CP page where you can repro­duce the issue
2. Delete all of the log files either via GUI or via rm -f storage/logs/* via shell
3. Repro­duce the issue

Now your log files will be pared down to most­ly rel­e­vant infor­ma­tion, and it should make your job eas­i­er to do. If you need to then pass the issue along to Pix­el & Ton­ic or a plu­g­in devel­op­er, this also gives you con­cise and rel­e­vant logs for them.

2. SEARCH ON [ERROR]

If you’re try­ing to find an error that’s report­ed by Craft or a plu­g­in, usu­al­ly it’ll be logged with log lev­el error.

But if you just search on error you’ll find tons of match­es. Instead, use the knowl­edge we learned ear­li­er to search on the log lev­el [error] (with the []) This should help you find just the lines where an actu­al error is thrown.

3. CRAWL THE STACK

If an actu­al error is thrown, usu­al­ly there will be what’s called a ​“stack trace” right after the error line in your log file. Worst case, you can always just search the log file for stack trace. He’s a stack trace from an actu­al issue I was try­ing to track down:

Stack trace:
#0 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/helpers/Assets.php(93): craft\elements\Asset->getFolder()
#1 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/services/Assets.php(579): craft\helpers\Assets::generateUrl(Object(craft\volumes\Local), Object(craft\elements\Asset))
#2 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/elements/Asset.php(773): craft\services\Assets->getAssetUrl(Object(craft\elements\Asset), NULL)
#3 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/Component.php(139): craft\elements\Asset->getUrl()
#4 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/base/Element.php(879): yii\base\Component->__get('url')
#5 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/elements/Asset.php(582): craft\base\Element->__get('url')
#6 /home/vagrant/webdev/craft/craft-retour/src/Retour.php(306): craft\elements\Asset->__get('url')
#7 [internal function]: nystudio107\retour\Retour->nystudio107\retour\{closure}(Object(craft\events\ElementEvent))
#8 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/Event.php(312): call_user_func(Object(Closure), Object(craft\events\ElementEvent))
#9 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/Component.php(636): yii\base\Event::trigger('craft\\services\\...', 'beforeSaveEleme...', Object(craft\events\ElementEvent))
#10 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/services/Elements.php(502): yii\base\Component->trigger('beforeSaveEleme...', Object(craft\events\ElementEvent))
#11 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/controllers/AssetsController.php(118): craft\services\Elements->saveElement(Object(craft\elements\Asset))
#12 [internal function]: craft\controllers\AssetsController->actionSaveAsset()
#13 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array(Array, Array)
#14 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/Controller.php(157): yii\base\InlineAction->runWithParams(Array)
#15 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/web/Controller.php(187): yii\base\Controller->runAction('save-asset', Array)
#16 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/Module.php(528): craft\web\Controller->runAction('save-asset', Array)
#17 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/web/Application.php(298): yii\base\Module->runAction('assets/save-ass...', Array)
#18 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/web/Application.php(565): craft\web\Application->runAction('assets/save-ass...', Array)
#19 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/web/Application.php(277): craft\web\Application->_processActionRequest(Object(craft\web\Request))
#20 /home/vagrant/sites/craft3/vendor/yiisoft/yii2/base/Application.php(386): craft\web\Application->handleRequest(Object(craft\web\Request))
#21 /home/vagrant/sites/craft3/web/index.php(24): yii\base\Application->run()
#22 {main}

This may look a lit­tle scary, but we can break it down into some­thing eas­i­ly understandable.

First of all, stack traces are a list of the func­tions or meth­ods that are called, in reverse order, until the error or excep­tion happened.

                            A Stack Trace is turn by turn direc­tions to your code’s car crash

The bot­tom­most item in the stack trace labeled #22 {main} is where the exe­cu­tion start­ed, and it ends up at #0 where the error was caught:

#0 /home/vagrant/sites/craft3/vendor/craftcms/cms/src/helpers/Assets.php(93): craft\elements\Asset->getFolder()

Let’s break down what this line is telling us:

• #0 — this is the 0^th line in the stack trace before the error occurred; think ​“ground zero”
• /home/vagrant/sites/craft3/vendor/craftcms/cms/src/helpers/Assets.php — the path to the file in which the error occurred
• (93) — the line num­ber in the afore­men­tioned file where the error occurred
• craft\elements\Asset->getFolder() — the line of code where the error or excep­tion occurred

So great! This gives us a pret­ty good idea of what hap­pened, and we can look back through the stack trace to see all of the functions/​methods that were called lead­ing up to the error.

4. LOOK IN THE RIGHT PLACE

If you’re attempt­ing to diag­nose a prob­lem, make sure you’re look­ing at the right log file. While this may seem basic, it’s an impor­tant thing to keep in mind.

For instance, if you’re attempt­ing to diag­nose an issue with a queue job like ​“Resav­ing Ele­ments”, any errors would be logged in queue.log, not the nor­mal web.log file.

Sim­i­lar­ly, if you’re attempt­ing to debug a Con­sole Com­mand, make sure you look in console.log, not the nor­mal web.log file.

5. USE CONSOLE.APP

If you’re using a Mac, you might con­sid­er using Console.app (in Applications/​Utilities) when you’re doing some seri­ous log file spelunk­ing. It’s a lean, mean, log-eat­ing machine.

Your text edi­tor of choice is prob­a­bly fan­tas­tic for edit­ing code, but it’s usu­al­ly only pass­able for pars­ing through mass­es of data in a log file.

A real­ly handy fea­ture is that you can use Console.app’s fil­ter at the top of the win­dow to show only lines that con­tain retour in the exam­ple screenshot.

Then you can use its search fea­ture to search only the result­ing fil­ter lines of the log file for spe­cif­ic text, error in this case.

Console.app real­ly is designed for pars­ing log files; if you dou­ble click on any file with a .log suf­fix, Console.app opens by default.

6. USE THE COM­MAND LINE

If you feel com­fort­able using the CLI, here are a few com­mands that you may file useful:

• grep -F '[error]' web.log — search the web.log file for the fixed string [error] and dis­play match­ing lines. More info…
• grep -C 2 -F '[error]' web.log — adding the -C 2 option to the above com­mand caus­es it to also print out the 2 lines before and 2 lines after the match. More info…
• tail -f web.log | grep -F '[error]' — con­tin­u­ous­ly mon­i­tor the web.log file and out­put any new lines logged to it that match the fixed string [error]. More Info…

Doing the Down­ward Log

Hope­ful­ly the infor­ma­tion pre­sent­ed here will give you some under­stand­ing of how the log­ging mech­a­nism works, and what the data in the log files means.

                            And with under­stand­ing comes confidence

It’ll give you the flex­i­bil­i­ty and empow­er­ment to do some error diag­no­sis on your own.

With this foren­sic infor­ma­tion, we can have a pret­ty good idea what’s going on, and attempt to fix it, or at the very least have a real­ly good bug report for Pix­el & Ton­ic or a plu­g­in author.

Even if you’re not ulti­mate­ly the one who will fix the error, the bet­ter the bug report is that you pass along, the more like­ly it is that the issue will be resolved with alacrity.

If you want to flex your mus­cles even more, check out the Cre­at­ing a Cus­tom Log­ger for Craft CMS article.

Hap­py logging!

Further Reading

If you want to be notified about new articles, follow nystudio107 on Twitter.

Copyright ©2020 nystudio107. Designed by nystudio107