Andrew Welch · Insights · #craftcms #craft-3 #logs

Published , updated · 5 min read ·


Please consider 🎗 sponsoring me 🎗 to keep writing articles like this.

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

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, “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.

Link 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:

Debug Tool­bar Log Mes­sages Filtering

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.

Link 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.

Link Dissecting 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.

Link Divining Meaning 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 directions 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 0th 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.

Console.app’s fil­ter­ing & searching

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…

Link Doing the Downward 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 understanding 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!