Laravel 7.x Production Not Logging HTTP 500 Exception

Question

There seems to be a long-standing issue around Laravel not logging correctly on the production environment. I have a small application using Docker-compose to make web, queue, and scheduler, services. Testing the small app on production (which has no users currently, so I can do some breaking debugging without worrying much), I got an HTTP 500 error trying to access a page. Checking My web/laravel.log file, there were no outputs in the past month. I tried deleting the log file, And hit the page's 500 error again. No file created.

Going into the Web Service container and running tinker and executing the following:

Log::debug("HELLO, World?");

Created the Web/Laravel.log file with text a line

[2020-08-19 17:51:36] production.DEBUG: HELLO, World?

So a few things:

1. Every docker rebuild, my Cache, Configuration, etc. are rebuilt from The base project on the host, and the containers only volumes are for the log file, so It's likely not an issue with caching or resetting (As I'll explain below).
2. The fact that Log::debug("message") works as intended indicates that it's not a PATH issue, and not a Permissions issue.
3. I just had to do a bunch of debugging with my Queue service, during which I used the Queue/laravel.log file a lot. The Queue Service logged exceptions without issue, as far as I could tell. Since the Queue Service and Web Services are made from the exact same base project, with the exact same steps, only difference being the Execution Commands.
4. I tried on my development environment changing the APP_DEBUG and APP_ENV to false and production respectively, And still got correct output on my development environment.

And there seems to be a lot of other forms with this same problem, none of which gave a proper solution. Using This Thread I was able to see the error message

"Property [permissioned_users] does not exist on this collection instance."

Which was then very easy to find the issue and solve. However, if I get a 500 Issue in the future, I want it to log so I know what's going on, So I'd like to fully solve this and get to the bottom of it. The following threads on this issue do not give official solutions:

Laravel log errors in production

Laravel 5.8 Log levels are not working

App Debug Not Working in Laravel 5.8

Log info not working

Laravel 5.3 Logging not working

Many of these older solutions give advice to set "APP_LOG_LEVEL", Which seems to have been depreciated in Laravel 5.6. ( Unrelated - Reimplementation of this here? )

For now, My solution seems to be something like adding the following line to the App\Exception\Handler line 37 (Instead of the above dd($e->getMessage() that helped me debug in the first place):

if(config('app.env') == "production" && env('CONTAINER_ROLL') == "web-server"){ Log::error("PRODUCTION WEB EXCEPTION : " . $exception->getMessage()); }

But I'd rather figure out the underlying issue and fully solve this problem.

While writing this message, I discovered the underlying issue (Permission issue). See below for my specific (Docker) issue

Answer 1

It was a Docker And Permissions issue.

In my Web-service Dockerfile , I have the following line:

RUN chown -R www-data:www-data /app/storage/

Upon inspecting my web service's log files, I found the following:

drwxrwxr-x 1 www-data www-data   4096 Jun 17  2019 storage

drwxrwxr-x 1 www-data www-data 4096 Jun 17  2019 app
drwxrwxr-x 1 www-data www-data 4096 Jun 11 08:15 framework
drwxr-xr-x 2 root     root     4096 Aug 19 08:51 logs

-rw-r--r-- 1 root     root     1353 Aug 20 03:13 laravel.log

Running the Command

chown -R www-data:www-data ./storage/logs/

Solved the issue, and re-hitting my 500 HTTP error showed up in the logs !

MISSION ACCOMPLISHED !

Additional Note for anyone who still needs an explanation on this part.

www-data is needed by the Apache Web Server (dockerfile FROM php:7.4-apache) . The Apache server running the PHP (laravel) application is www-data , which needs permission to write to the log file . I you BASH into the container , You're running as root , so if you execute the Log::debug() from Tinker , It will execute by the root user . For Queue and Scheduler (dockerfile FROM php:7.4 , running CRON or Artisan Worker) , These both execute as the root user as well, not apache.

Following up on this,

I did notice some interesting artifacts, As well as was able to recreate this. The issue is the volumes. The HOST VOLUME file will override the Container's file , and therefore the Application's files (That get copied into the Docker Container) will be overwritten and not effected. Also noteworthy, Modifying the volume File within the Container (Including ownership and Permissions) will modify the Volume file on the host, And Vice Versa. The issue was my Host-side Volume File web/laravel.log had root:root ownership originally , Which gets linked to the web-service Container . So despite Dockerfile chown command on this file, It will be overwritten by this Volume's Host file , Which will make it not work. Running the

chown -R www-data:www-data storage/logs/

within the web-service container modified the Host's File to ownership of www-data . Since the Host Volume file was now www-data ownership, Docker-compose rebuilds and refreshes worked from there. However if I exited the container (While the container is still running) and did the opposite command on the host volume log file

chown -R root:root logs/web/

(where web/laravel.log exists) , It would immediately change the web-service container's file (going back in to check) to root:root again , which stops the logging by apache from working properly.

Note the following :

HOST APPLICATION:

drwxrwxr-x  5 root www-data   4096 Jun 17  2019 storage

drwxrwxr-x  3 root www-data 4096 Jun 17  2019 app
drwxrwxr-x  6 root www-data 4096 Jun 11 08:15 framework
drwxrwxr-x  2 root root     4096 Nov 21  2019 logs

-rwxrwxr-x 1 root root     1657039 Jun 28 05:29 laravel.log <<<< Irrelevant due to Volume

HOST WEB CONTAINER :

drwxrwxr-x 1 www-data www-data   4096 Jun 17  2019 storage

drwxrwxr-x 1 www-data www-data 4096 Jun 17  2019 app
drwxrwxr-x 1 www-data www-data 4096 Jun 11 08:15 framework
drwxr-xr-x 2 www-data www-data 4096 Aug 20 05:21 logs

-rw-r--r-- 1 www-data www-data 19840 Aug 20 06:02 laravel.log <<<< Linked to Host by Volume

HOST WEB LOG VOLUME LOCATION:

drwxr-xr-x  2 www-data www-data 4096 Aug 20 05:21 web

-rw-r--r-- 1 www-data www-data 19840 Aug 20 06:02 laravel.log <<<< Linked to Container by Volume

HOST QUEUE CONTAINER :

drwxrwxr-x 3 root root 4096 Jun 17  2019 app
drwxrwxr-x 1 root root 4096 Jun 11 08:15 framework
drwxr-xr-x 2 root root 4096 Jun 11 12:26 logs

-rw-r--r-- 1 root root 322662871 Aug 20 08:01 laravel.log <<<< Linked to Host by Volume

HOST QUEUE LOG VOLUME LOCATION:

drwxr-xr-x  2 root     root     4096 Jun 11 12:26 queue

-rw-r--r-- 1 root root 322662871 Aug 20 08:01 laravel.log <<<< Linked to Container by Volume