Zen and the Art of Craft CMS Log File Reading

N.B.: This arti­cle was updat­ed to con­tain infor­ma­tion rel­e­vant to changes in the log­ging for­mat used in Craft 4 or later.

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:

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:

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.

On Craft 4 or lat­er, the log files will be suf­fixed with a time­stamp date rather than a num­ber, e.g.: web-2024-08-15.log

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

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] / [web.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 matches.

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.

On Craft 4 or lat­er, search on [web.ERROR], since the log­ging for­mat was changed to log in that format.

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:

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:

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.

Craft 3:

• 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…

Craft 4 or later:

• grep -F '[web.ERROR]' web.log — search the web.log file for the fixed string [web.ERROR] and dis­play match­ing lines. More info…
• grep -C 2 -F '[web.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 '[web.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 [web.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!