Log Debug \Log::debug('Static cache loaded is out of control.

[ericlbarnes]

Bug Description

When you have full caching enabled the \Log::debug('Static cache loaded ['.$url.'] If you are seeing this, your server rewrite rules have not been set up correctly.'); message is out of control.

How to Reproduce

Setup full caching. CACHE_STRATEGY=full. Then change your nginx to what your docs outline:

location / {
  try_files /static${uri}_${args}.html $uri /index.php?$args;
}

Now start browsing the site. Every time a new page is visited, even without a cache file the log debug message fires.

Extra Detail

Unless I'm reading the code wrong it's because of the way this statement is written:
https://github.com/statamic/cms/blob/3.0/src/StaticCaching/Middleware/Cache.php#L30-L32

if ($this->canBeCached($request) && ($cached = $this->cacher->getCachedPage($request))) {
    return response($cached);
}

If a page canBeCached, then it tries to getCachedPage, so it doesn't matter what getCachedPage returns, it's always going to log the message.

[duncanmcclean]

Can confirm, this error message fills up all of my daily logs on my production server 😂

[jonassiewertsen]

Can confirm as well.

[jasonvarga]

This is fixed for 3.1 because there's a little breaking change for people using custom drivers.

[DrTrills]

I am getting this issue in my production logs, any support would be appreciated

Statamic 3.1.25 Pro
Laravel 8.41.0
PHP 8.0.0
withcandour/aardvark-seo 2.0.13

[2021-06-13 15:27:11] production.DEBUG: Static cache loaded [https://site.com/casestudies/iams-security-administration?li_fat_id=d54dd710-48e5-4129-a1d2-0796b71a85ed&utm_campaign=Citi&utm_content=Picture&utm_medium=CPC&utm_source=linkedin] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-06-13 19:30:39] production.DEBUG: Static cache loaded [https://site.com/casestudies/iams-security-administration?li_fat_id=6b45d16e-3d91-4725-b4b5-058d602b2cbb&utm_campaign=Citi&utm_content=Picture&utm_medium=CPC&utm_source=linkedin] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-06-14 15:53:19] production.DEBUG: Static cache loaded [https://site.com/enterprise-software-solutions?utm_campaign=Citi&utm_medium=Brand%20awareness%20financial%20institutions&utm_source=linkedin] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-06-14 16:33:30] production.DEBUG: Static cache loaded [https://site.com/casestudies/iams-security-administration?utm_campaign=Citi&utm_content=Picture&utm_medium=CPC&utm_source=linkedin] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-06-15 01:41:51] production.ERROR: Connection lost {"exception":"[object] (RedisException(code: 0): Connection lost at /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php:116)
[stacktrace]
#0 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Redis/Connections/Connection.php(116): Redis->eval()
#1 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php(532): Illuminate\\Redis\\Connections\\Connection->command()
#2 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php(449): Illuminate\\Redis\\Connections\\PhpRedisConnection->command()
#3 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(247): Illuminate\\Redis\\Connections\\PhpRedisConnection->eval()
#4 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(230): Illuminate\\Queue\\RedisQueue->migrateExpiredJobs()
#5 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/RedisQueue.php(210): Illuminate\\Queue\\RedisQueue->migrate()
#6 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(327): Illuminate\\Queue\\RedisQueue->pop()
#7 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(336): Illuminate\\Queue\\Worker->Illuminate\\Queue\\{closure}()
#8 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(145): Illuminate\\Queue\\Worker->getNextJob()
#9 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(117): Illuminate\\Queue\\Worker->daemon()
#10 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(101): Illuminate\\Queue\\Console\\WorkCommand->runWorker()
#11 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(36): Illuminate\\Queue\\Console\\WorkCommand->handle()
#12 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Container/Util.php(40): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#13 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(93): Illuminate\\Container\\Util::unwrapIfClosure()
#14 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): Illuminate\\Container\\BoundMethod::callBoundMethod()
#15 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Container/Container.php(611): Illuminate\\Container\\BoundMethod::call()
#16 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Console/Command.php(136): Illuminate\\Container\\Container->call()
#17 /home/forge/site.com/vendor/symfony/console/Command/Command.php(256): Illuminate\\Console\\Command->execute()
#18 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run()
#19 /home/forge/site.com/vendor/symfony/console/Application.php(971): Illuminate\\Console\\Command->run()
#20 /home/forge/site.com/vendor/symfony/console/Application.php(290): Symfony\\Component\\Console\\Application->doRunCommand()
#21 /home/forge/site.com/vendor/symfony/console/Application.php(166): Symfony\\Component\\Console\\Application->doRun()
#22 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Console/Application.php(92): Symfony\\Component\\Console\\Application->run()
#23 /home/forge/site.com/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\\Console\\Application->run()
#24 /home/forge/site.com/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle()
#25 {main}
"} 

nginx.conf

# FORGE CONFIG (DO NOT REMOVE!)
include forge-conf/site.com/before/*;

server {
    listen 443 ssl http2;
    listen [::]:443 ssl http2;
    server_name site.com;
    server_tokens off;
    root /home/forge/site.com/public;

    # FORGE SSL (DO NOT REMOVE!)
    ssl_certificate /etc/nginx/ssl/site.com/977919/server.crt;
    ssl_certificate_key /etc/nginx/ssl/site.com/977919/server.key;

    ssl_protocols TLSv1.2 TLSv1.3;
    ssl_ciphers TLS13-AES-256-GCM-SHA384:TLS13-CHACHA20-POLY1305-SHA256:TLS_AES_256_GCM_SHA384:TLS-AES-256-GCM-SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS-CHACHA20-POLY1305-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA;
    ssl_prefer_server_ciphers on;
    ssl_dhparam /etc/nginx/dhparams.pem;

    add_header X-Frame-Options "SAMEORIGIN";
    add_header X-XSS-Protection "1; mode=block";
    add_header X-Content-Type-Options "nosniff";

    index index.html index.htm index.php;

    charset utf-8;

    # FORGE CONFIG (DO NOT REMOVE!)
    include forge-conf/site.com/server/*;

    # location / {
    #     try_files $uri $uri/ /index.php?$query_string;
    # }
    
    # https://statamic.dev/static-caching#nginx
    location / {
        try_files /static${uri}_${args}.html $uri /index.php?$args;
    }

    location = /favicon.ico { access_log off; log_not_found off; }
    location = /robots.txt  { access_log off; log_not_found off; }

    access_log off;
    error_log  /var/log/nginx/site.com-error.log error;

    error_page 404 /index.php;

    location ~ \.php$ {
        fastcgi_split_path_info ^(.+\.php)(/.+)$;
        fastcgi_pass unix:/var/run/php/php8.0-fpm.sock;
        fastcgi_index index.php;
        include fastcgi_params;
    }

    location ~ /\.(?!well-known).* {
        deny all;
    }
}

# FORGE CONFIG (DO NOT REMOVE!)
include forge-conf/site.com/after/*;

[ericlbarnes]

@DrTrills Based on what you shared, I believe that message is actually accurate for you. By default, Statamic will create a cache file with query strings. So in your first two urls:

https://site.com/casestudies/iams-security-administration?li_fat_id=d54dd710-48e5-4129-a1d2-0796b71a85ed&utm_campaign=Citi&utm_content=Picture&utm_medium=CPC&utm_source=linkedin
https://site.com/casestudies/iams-security-administration?li_fat_id=6b45d16e-3d91-4725-b4b5-058d602b2cbb&utm_campaign=Citi&utm_content=Picture&utm_medium=CPC&utm_source=linkedin

Notice the li_fat_id has different hashes. Which will create two cache files so it would be a cache miss and log that message.

[DrTrills]

Hi @ericlbarnes, appreciate the feedback. So in this case anything that I can do to prevent the error or just leave it as is?

[ericlbarnes]

Yes, I believe in these situations it's safe to just ignore the log entry. The way the message is written its meant more for when you are just setting up static caching and are not sure if it's working.

[jimblue]

Hi there,
I know this issue is closed by I'm also getting this error on my production server.
Do you have any idea why ?

Here is the log

[2021-07-10 22:59:35] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-10 23:41:00] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-10 23:41:00] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 03:18:29] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 03:18:31] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 04:19:45] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 04:19:46] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 06:05:56] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 06:05:57] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 09:50:05] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 13:45:15] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 19:20:29] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 19:54:23] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 19:54:23] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 22:11:57] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 22:11:57] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 22:12:22] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 23:24:13] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-11 23:56:25] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 01:41:14] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 01:46:25] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 04:50:34] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 04:53:13] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 04:53:56] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 04:53:58] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 20:54:26] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-12 20:54:26] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 05:11:25] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 05:11:25] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 05:11:25] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 05:11:26] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 06:28:04] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 13:54:37] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-13 13:54:37] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-14 07:01:56] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-14 12:41:35] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-14 12:41:35] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-14 20:28:41] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-14 20:47:50] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-15 06:15:06] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-15 13:47:49] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-15 15:08:37] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-15 15:08:37] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly.  
[2021-07-15 16:25:53] production.DEBUG: Static cache loaded [https://www.mywebsite.com/contact/] If you are seeing this, your server rewrite rules have not been set up correctly. 

[jasonvarga]

The slash on the end of that URL might be the hint. If the cached version is being served, then the log is doing what it's supposed to. Your rewrite rules might not be handling the slash. Does visiting /contact without the slash cause the log?

[jimblue]

Hey @jasonvarga,
Sorry to only answer now.
You were right, I only get that warning in the logs when I visit a page with a trailing slash in the URL.
The fix was easy to found for Nginx :

# Remove trailing slash by doing a 301 redirect
rewrite ^/(.*)/$ /$1 permanent;

[freshface]

I also get the message wihout the trailing slash

[2023-06-21 14:05:27] production.DEBUG: Static cache loaded [https://figure8.be/contact] If you are seeing this, your server rewrite rules have not been set up correctly.

[stanbridge-wcorrea]

This is still happening and I don't want to open a new issue. Is there anyone that is runnning into this? I looked the source code and it doesn't make sense, if anyone can explain to me how it works, would be awesome.

[ashermiddleton]

I was also a little dumbfounded by these messages, as I was getting them for every page and the web server seemed to be redirecting URLs correctly and without trailing slashes. However I was simply missing the static caching rewrite rules for apache as explained here. After adding the rewrite rules to /public/.htaccess the logs are gone.

So in the end the logging was informing me that Statamic was having to process a URL and fetch a file, even though the web server itself should've been able to parse the URL and serve it directly. Statamic should only be parsing the GET request itself if the request string is longer than what is allowed by max_filename_length (default is 255) because then the file name has to be MD5 hashed and returned manually (which the webserver cannot do). Maybe more clarification on the log message is needed to convey this? It is a little vague.

[jasonvarga]

So in the end the logging was informing me that Statamic was having to process a URL and fetch a file, even though the web server itself should've been able to parse the URL and serve it directly. Statamic should only be parsing the GET request itself if the request string is longer than what is allowed by max_filename_length (default is 255) because then the file name has to be MD5 hashed and returned manually. Maybe more clarification on the log message is needed to convey this? It is a little vague.

@ashermiddleton I'm not sure what you mean about this max length issue. Can you elaborate?

[ashermiddleton]

@ashermiddleton I'm not sure what you mean about this max length issue. Can you elaborate?

@jasonvarga sure, to be clear there is no bug, I was explaining Statamic's file caching behaviour (with full caching strategy) for anyone stumbling on this in future. I was referring to isBasenameTooLong()'s use in getFilePath()