Zen and the Art of Craft CMS Log File Reading
Tags: craftcms, devops, logs
Published: 2020-03-04 05:43:43

---
title: Zen and the Art of Craft CMS Log File Reading
published: true
date: 2019-07-22 05:00:00 UTC
tags: craftcms,devops,logs
canonical_url: https://nystudio107.com/blog/zen-and-the-art-of-craft-cms-log-file-reading
---

# 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](https://nystudio107.com)

![Zen sand japanese rock garden](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_1200x675_crop_center-center_82_line/zen-sand-japanese-rock-garden.jpg)

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.

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

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](https://craftcms.com/) 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](https://dev.to/gaijinity/profiling-your-website-with-craft-cms-3-8217-s-debug-toolbar-1jig-temp-slug-5108979) article:

![Debug Toolbar Log Filtering](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_1200x669_crop_center-center_100_line/debug-toolbar-log-filtering.png)

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](https://dev.to/gaijinity/profiling-your-website-with-craft-cms-3-8217-s-debug-toolbar-1jig-temp-slug-5108979) 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 <kbd>storage/logs/</kbd> 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.

![Types of loose leaf tea](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_992x558_crop_center-center_82_line/types-of-loose-leaf-tea.jpg)

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

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

Even if you use a third par­ty log­ging ser­vice such as [Paper­Trail](https://papertrailapp.com/) or [Sen­try](https://sentry.io) 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 <kbd>storage/logs/</kbd> 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 <kbd>10,240</kbd>KB, up to the a max­i­mum of 5 rotat­ed logs (both default max­i­mums can be changed via <kbd>app.php</kbd> con­fig). So in the above exam­ple, the <kbd>web.log.5</kbd> file is the old­est log file, and <kbd>web.log</kbd> is the cur­rent log file.

## Dis­sect­ing a Craft CMS Log File Line

Let’s dis­sect a line from my <kbd>web.log</kbd> file:

```

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

```

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

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

- <kbd>debug</kbd> (aka <kbd>trace</kbd>)- a mes­sage to trace how a piece of code runs. This is main­ly for devel­op­ment use.
- <kbd>info</kbd> — a mes­sage that con­veys some use­ful information.
- <kbd>warning</kbd> — a warn­ing mes­sage that indi­cates some­thing unex­pect­ed has happened.
- <kbd>error</kbd> — a fatal error that should be inves­ti­gat­ed as soon as possible.
- <kbd>profile</kbd> — 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](https://craftcms.com/guides/what-dev-mode-does) is on, Craft will only log lev­els <kbd>warning</kbd>, <kbd>error</kbd> & <kbd>profile</kbd>. 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](https://dev.to/gaijinity/profiling-your-website-with-craft-cms-3-8217-s-debug-toolbar-1jig-temp-slug-5108979) article.

Since Craft CMS is based on the Yii2 frame­work, you can read up on the gory details of [Yii2 Log­ging here](https://www.yiiframework.com/doc/guide/2.0/en/runtime-logging).

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 <kbd>devMode</kbd> is on.

![Tea leaf reading](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_1200x675_crop_center-center_82_line/tea-leaf-reading.jpg)

If <kbd>devMode</kbd> is enabled, in addi­tion to <kbd>error</kbd>, <kbd>warning</kbd>, & <kbd>profile</kbd> log lev­els, we’re also log­ging <kbd>trace</kbd> (aka <kbd>debug</kbd>) and <kbd>info</kbd> 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.

![Find needle in a haystack](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_1200x675_crop_center-center_82_line/find-needle-in-a-haystack.jpg)

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 <kbd>rm -f storage/logs/*</kbd> 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 <kbd>error</kbd>.

But if you just search on <kbd>error</kbd> you’ll find tons of match­es. Instead, use the knowl­edge we learned ear­li­er to search on the log lev­el <kbd>[error]</kbd> (with the <kbd>[]</kbd>) 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 <kbd>stack trace</kbd>. He’s a stack trace from an [actu­al issue](https://github.com/craftcms/cms/issues/4589) 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.

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

The bot­tom­most item in the stack trace labeled <kbd>#22 {main}</kbd> is where the exe­cu­tion start­ed, and it ends up at <kbd>#0</kbd> 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:

- <kbd>#0</kbd> — this is the 0<sup>th</sup> line in the stack trace before the error occurred; think ​“ground zero”
- <kbd>/home/vagrant/sites/craft3/vendor/craftcms/cms/src/helpers/Assets.php</kbd> — the path to the file in which the error occurred
- <kbd>(93)</kbd> — the line num­ber in the afore­men­tioned file where the error occurred
- <kbd>craft\elements\Asset-&gt;getFolder()</kbd> — 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 <kbd>queue.log</kbd>, not the nor­mal <kbd>web.log</kbd> file.

Sim­i­lar­ly, if you’re attempt­ing to debug a Con­sole Com­mand, make sure you look in <kbd>console.log</kbd>, not the nor­mal <kbd>web.log</kbd> 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 for reading log files](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_1200x609_crop_center-center_100_line/console-app-for-reading-log-files.png)

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 <kbd>retour</kbd> 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, <kbd>error</kbd> in this case.

Console.app real­ly is designed for pars­ing log files; if you dou­ble click on any file with a <kbd>.log</kbd> 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:

- <kbd>grep -F '[error]' web.log</kbd> — search the <kbd>web.log</kbd> file for the fixed string <kbd>[error]</kbd> and dis­play match­ing lines. [More info…](https://explainshell.com/explain?cmd=grep+-F+%27%5Berror%5D%27+web.log)
- <kbd>grep -C 2 -F '[error]' web.log</kbd> — adding the <kbd>-C 2</kbd> 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…](https://explainshell.com/explain?cmd=grep+-C+2+-F+%27%5Berror%5D%27+web.log)
- <kbd>tail -f web.log | grep -F '[error]'</kbd> — con­tin­u­ous­ly mon­i­tor the <kbd>web.log</kbd> file and out­put any new lines logged to it that match the fixed string <kbd>[error]</kbd>. [More Info…](https://explainshell.com/explain?cmd=tail+-f+web.log+%7C+grep+-F+%27%5Berror%5D%27)

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

<aside>
                                And with under­stand­ing comes confidence
                            </aside>

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

![Downward dog yoga](https://nystudio107-ems2qegf7x6qiqq.netdna-ssl.com/img/blog/_1200x675_crop_center-center_82_line/downward-dog-yoga.jpg)

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](https://dev.to/gaijinity/creating-a-custom-logger-for-craft-cms-4pn0-temp-slug-8139286) article.

Hap­py logging!

## Further Reading

_If you want to be notified about new articles, follow [nystudio107](https://twitter.com/nystudio107) on Twitter._

<small>Copyright ©2020 nystudio107. Designed by nystudio107</small>