Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Caching Issue #6268

Closed
madesimplemedia opened this issue Jan 4, 2018 · 49 comments
Closed

Caching Issue #6268

madesimplemedia opened this issue Jan 4, 2018 · 49 comments

Comments

@madesimplemedia
Copy link

The issue is rather critical, visitors will attempt to browse to a page and it'll fail and show the error, here is an example from the logs:

Exception Occurred: /var/www/vhosts/[sitedomainame]/httpdocs/application/files/cache/0fea6a13c52b4d47/25368f24b045ca84/38a865804f8fdcb6/57cd99682e939275/18e23c785c6a72cf/ca47fbe20fed45aa.php:14 syntax error, unexpected end of file, expecting variable (T_VARIABLE) or ${ (T_DOLLAR_OPEN_CURLY_BRACES) or {$ (T_CURLY_OPEN) (0) 

This is on a site running community store but appears to be a C5 issue. The Stash library seems to build quite large files and then it seems to struggle reading the whole thing, so I guess that is why we get a syntax error when infact there are none in the cache file.

Example cache file attached.
ca47fbe20fed45aa.txt

A suggestion from the Stash page on github:
"Try switching to the SQLite backend. The filesystem one works great in testing but runs into various race conditions when put under load."

Link to Stash issue/conversation: tedious/Stash#374

So it looks like to use PDO/Sqlite we need to write a new class under:
\concrete\src\Cache\Driver\FileSystemStashDriver.php

But call it something else like SqliteStashDriver.php and in /concrete/config/ have a choice of drivers maybe:

'core_filesystem' => [
                        'class' => \Concrete\Core\Cache\Driver\FileSystemStashDriver::class,
                        //'class' => \Concrete\Core\Cache\Driver\SqliteStashDriver::class,
@mnakalay
Copy link
Contributor

mnakalay commented Jan 4, 2018

This bug was, at first, thought to be a Community Store issue but it wasn't.
Here's the conversation about it with more information: concretecms-community-store/community_store#321

At that time, the site had about 2600 images. rescanning them all to regenerate the thumbnails was out of the question. Even trying to do it in batch didn't work and it would always fail mid-ways with a problem reading a malformed string from a Stash-generated cache file.

That file would contain a huge array of objects saved as a string. It contained all the details about each image and from what I could see some info was redundant.

As an example, here's a formatted sample for a single image and its thumbnails. Notice that it's really just the core file manager thumbnail type. Although there is another thumbnail type, the thumbnails were not there yet so they are not listed

{
    "8715/0149/2739/steven-seagal.jpg":{
        "dirname":"8715/0149/2739",
        "basename":"steven-seagal.jpg",
        "extension":"jpg",
        "filename":"steven-seagal",
        "path":"8715/0149/2739/steven-seagal.jpg",
        "type":"file",
        "timestamp":1501492739,
        "size":22179,
        "mimetype":"image/jpeg"
    },
    "8715/0149/2739":{
        "dirname":"8715/0149",
        "basename":"2739",
        "filename":"2739",
        "path":"8715/0149/2739",
        "type":"dir"
    },
    "8715/0149":{
        "dirname":"8715",
        "basename":"0149",
        "filename":"0149",
        "path":"8715/0149",
        "type":"dir"
    },
    "8715":{
        "dirname":"",
        "basename":"8715",
        "filename":"8715",
        "path":"8715",
        "type":"dir"
    },
    "thumbnails/file_manager_listing/8715/0149/2739/steven-seagal.jpg":{
        "dirname":"thumbnails/file_manager_listing/8715/0149/2739",
        "basename":"steven-seagal.jpg",
        "extension":"jpg",
        "filename":"steven-seagal",
        "path":"thumbnails/file_manager_listing/8715/0149/2739/steven-seagal.jpg",
        "type":"file",
        "size":2086,
        "visibility":"public"
    },
    "thumbnails/file_manager_listing/8715/0149/2739":{
        "dirname":"thumbnails/file_manager_listing/8715/0149",
        "basename":"2739",
        "filename":"2739",
        "path":"thumbnails/file_manager_listing/8715/0149/2739",
        "type":"dir"
    },
    "thumbnails/file_manager_listing/8715/0149":{
        "dirname":"thumbnails/file_manager_listing/8715",
        "basename":"0149",
        "filename":"0149",
        "path":"thumbnails/file_manager_listing/8715/0149",
        "type":"dir"
    },
    "thumbnails/file_manager_listing/8715":{
        "dirname":"thumbnails/file_manager_listing",
        "basename":"8715",
        "filename":"8715",
        "path":"thumbnails/file_manager_listing/8715",
        "type":"dir"
    },
    "thumbnails/file_manager_listing":{
        "dirname":"thumbnails",
        "basename":"file_manager_listing",
        "filename":"file_manager_listing",
        "path":"thumbnails/file_manager_listing",
        "type":"dir"
    },
    "thumbnails":{
        "dirname":"",
        "basename":"thumbnails",
        "filename":"thumbnails",
        "path":"thumbnails",
        "type":"dir"
    },
    "thumbnails/file_manager_listing_2x/8715/0149/2739/steven-seagal.jpg":{
        "dirname":"thumbnails/file_manager_listing_2x/8715/0149/2739",
        "basename":"steven-seagal.jpg",
        "extension":"jpg",
        "filename":"steven-seagal",
        "path":"thumbnails/file_manager_listing_2x/8715/0149/2739/steven-seagal.jpg",
        "type":"file",
        "size":4965,
        "visibility":"public"
    },
    "thumbnails/file_manager_listing_2x/8715/0149/2739":{
        "dirname":"thumbnails/file_manager_listing_2x/8715/0149",
        "basename":"2739",
        "filename":"2739",
        "path":"thumbnails/file_manager_listing_2x/8715/0149/2739",
        "type":"dir"
    },
    "thumbnails/file_manager_listing_2x/8715/0149":{
        "dirname":"thumbnails/file_manager_listing_2x/8715",
        "basename":"0149",
        "filename":"0149",
        "path":"thumbnails/file_manager_listing_2x/8715/0149",
        "type":"dir"
    },
    "thumbnails/file_manager_listing_2x/8715":{
        "dirname":"thumbnails/file_manager_listing_2x",
        "basename":"8715",
        "filename":"8715",
        "path":"thumbnails/file_manager_listing_2x/8715",
        "type":"dir"
    },
    "thumbnails/file_manager_listing_2x":{
        "dirname":"thumbnails",
        "basename":"file_manager_listing_2x",
        "filename":"file_manager_listing_2x",
        "path":"thumbnails/file_manager_listing_2x",
        "type":"dir"
    },
    "thumbnails/product_list_thumb/8715/0149/2739/steven-seagal.jpg":{
        "dirname":"thumbnails/product_list_thumb/8715/0149/2739",
        "basename":"steven-seagal.jpg",
        "extension":"jpg",
        "filename":"steven-seagal",
        "path":"thumbnails/product_list_thumb/8715/0149/2739/steven-seagal.jpg",
        "type":"file",
        "size":6478,
        "visibility":"public"
    },
    "thumbnails/product_list_thumb_2x/8715/0149/2739/steven-seagal.jpg":false,
    "thumbnails/file_manager_detail/8715/0149/2739/steven-seagal.jpg":false,
    "thumbnails/file_manager_detail_2x/8715/0149/2739/steven-seagal.jpg":false
}

Looks to me as if a lot of that is redundant. And if you imagine a single file with that kind of data for every single image and all thumbnails, saving using filesystem might not be the best strategy as pointed at by the Stash developer.

Anyway, it seems everything is saved without real consideration for performance and in the end the system breaks.

@mnakalay
Copy link
Contributor

mnakalay commented Jan 4, 2018

Another thing: the file attached as an example in the first message stops abruptly in the middle. That's where it bugged and couldn't write anymore.

I am not 100% sure but if memory serves, the system doesn't append to that file. It reads it all in memory, then adds to the string in memory, then saves it all again.

The function doing it is getApprovedVersion()

And this is no shared hosting, by the way, it's a server with plenty of resources.

@madesimplemedia
Copy link
Author

Server specs are decent, VPS running PHP 7 with opcache, 3GHz Xeon with 8GB RAM.
Other than this issue, it runs nice and fast when the caching is working, but I'm running it on a very short cache lifetime to minimise the issue, so it would be much better if I could run a reasonable cache lifetime.

@herent
Copy link
Contributor

herent commented Jan 4, 2018

Seems like if this is happening on beefed up servers and can be fixed just by switching to sqlite, then maybe we should look into that. We really need to make sure that c5 isn't failing under heavy loads, if that can be avoided.

@aembler
Copy link
Member

aembler commented Jan 4, 2018

I think the issue here specifically is the way that Stash works with file manager caching, which is a feature of the Flysystem file system library that we use. This is a relatively new addition. I've only ever seen this in relation to using the file manager. That doesn't make it any less of a problem, but rather than switching out all caching layers in all situations to use a completely new driver we could also simply turn that back off until it works better again.

Thoughts? I believe the offending caching is here: Concrete\Core\Entity\File\StorageLocation::getFileSystemObject

@Mnkras and @KorvinSzanto should probably be roped into this too.

@aembler
Copy link
Member

aembler commented Jan 4, 2018

Additionally, we had this on a site of ours and solved it by using memcache as a backend

@madesimplemedia
Copy link
Author

Thanks Andrew, I'd like to test that asap as I really need to fix this quickly now, how do I turn off this new driver?

@mnakalay
Copy link
Contributor

mnakalay commented Jan 5, 2018

@aembler there is something that seems off to me but I might be misunderstanding how it's supposed to work.

For some reason, Stash doesn't seem to be using the key provided for caching. Normally the key is 'file/version/approved/' followed by the file ID. But stash uses a generic key instead: flysystem-id-1

Am I wrong in assuming that normally Stash should use the key provided which would make it save data for each image and thumbnails separately? So instead of having everything in one big file, we would have only 1 image and all its thumbnails per file?

Or is the behavior of saving everything in only 1 file the intended behavior?

@ramonleenders
Copy link
Contributor

But this can actually happen to any site using cache and not using memcache? That would be quite a disaster for some then... So only option for now is to switch to memcache or completely disable caching? Just checking!

@madesimplemedia
Copy link
Author

It is indeed a nasty issue - in dev it doesn't really show up, the issue shows when you set it live and you have reasonable traffic hitting the site. Not an issue in 5.7 it seems but I can see some of the caching stuff has changed.

@Ruud-Zuiderlicht
Copy link
Contributor

Ruud-Zuiderlicht commented Jan 5, 2018

Just an observation, the example file is exactly 32KiB long

@madesimplemedia
Copy link
Author

Just checked another file on a different site with the same issue and that one is 101KiB

@Ruud-Zuiderlicht
Copy link
Contributor

Could you post that file as well?

@madesimplemedia
Copy link
Author

Here you go.
ca47fbe20fed45aa.txt

@madesimplemedia
Copy link
Author

I'm also seeing this error in the logs:
Exception Occurred: /var/www/vhosts/[domain].com/httpdocs/concrete/vendor/tedivm/stash/src/Stash/Pool.php:120 Maximum execution time of 60 seconds exceeded

@Ruud-Zuiderlicht
Copy link
Contributor

That file is not chopped off at the end. So I would expect a different error message. Can you post the message here as well?

@madesimplemedia
Copy link
Author

Ah yes you're right. This is the error:

Exception Occurred: /home/sitename/public_html/application/files/cache/0fea6a13c52b4d47/25368f24b045ca84/38a865804f8fdcb6/57cd99682e939275/18e23c785c6a72cf/ca47fbe20fed45aa.php:14 syntax error, unexpected end of file, expecting variable (T_VARIABLE) or ${ (T_DOLLAR_OPEN_CURLY_BRACES) or {$ (T_CURLY_OPEN) (0)

@mnakalay
Copy link
Contributor

mnakalay commented Jan 5, 2018

it seems the error happens in writing mostly but also in reading.

As the Stash developer said, it "runs into various race conditions when put under load" so it's probably not due to the file size only but to all the concurrent operations taking place in memory with the file being open and read in memory thousands of times and written back to the same amout of time.

@Ruud-Zuiderlicht
Copy link
Contributor

I can open the file just fine. When I chop off the end I get that exact same message. @mnakalay just beat me to pointing out I might have overlooked reading of the file.

@madesimplemedia
Copy link
Author

Here is a stack trace that may help.
stack-trace

@madesimplemedia
Copy link
Author

I made a change that Ruud suggested and I am testing. Came across another error now related to Flysystem:
stack-file-exists

@Ruud-Zuiderlicht
Copy link
Contributor

I basically tried this suggestion tedious/Stash#374 (comment) in concrete\vendor\tedivm\stash\src\Stash\Driver\FileSystem\NativeEncoder.php. No real solution was created at this point. But it seems to be working for as far as I understood.

@JamesAntropy
Copy link

Hi @Ruud-Zuiderlicht , could you elaborate? I'm having the same issue but I'm not sure where I should add that snippet

@Ruud-Zuiderlicht
Copy link
Contributor

I've changed the part just before the cached file is read, It locks the file, so that it cannot be altered or removed until reading is finished. After reading finishes the lock is released. These changes were made just to test if this resolves the error, so please report back here and also at tedious/Stash#374

/concrete/vendor/tedivm/stash/src/Stash/Driver/FileSystem/NativeEncoder.php

    public function deserialize($path)
    {
        if (!file_exists($path)) {
            return false;
        }

        $expiration = null;
+       $resFile = fopen($path, 'rb');
+       if (!flock($resFile, LOCK_SH)) {
+           return false;
+       }
        include($path);
+       flock($resFile, LOCK_UN);

        if (!isset($loaded)) {
            return false;
        }

        if (!isset($data)) {
            $data = null;
        }

        return array('data' => $data, 'expiration' => $expiration);
    }

@madesimplemedia
Copy link
Author

I tried Ruud's code above on dev and I didn't get the syntax error anymore so it seemed to work. However, on dev it is hard to replicate the errors anyway, they mostly occur on live I guess due to load from traffic.
On live, I reduced the cache expiry time to help limit the errors, of course the issue is still there.
So do we think the issue is with reading cache rather than writing cache?

@JamesAntropy
Copy link

Many thanks @Ruud-Zuiderlicht, I've applied that fix and I'll keep an eye on it

@madesimplemedia
Copy link
Author

@JamesAntropy Please let us know how you get on, can't believe more people aren't reporting this issue.

@JamesAntropy
Copy link

Unfortunately, it's just happened again, is there an easy way to disable stash altogether? Luckily this site isn't live yet but it has quite a few images

@Ruud-Zuiderlicht
Copy link
Contributor

It might not be the exact same error even though the message is similar. Can you show a stacktrace of that error?

@JamesAntropy
Copy link

Sorry, I don't have a trace, only the error message:

PHP Parse error:  syntax error, unexpected end of file, expecting variable (T_VARIABLE) or ${ (T_DOLLAR_OPEN_CURLY_BRACES) or {$ (T_CURLY_OPEN) in .../application/files/cache/0fea6a13c52b4d47/25368f24b045ca84/38a865804f8fdcb6/57cd99682e939275/18e23c785c6a72cf/ca47fbe20fed45aa.php on line 14

@JamesAntropy
Copy link

The file it references is missing the end of the $data['return'] string

@madesimplemedia
Copy link
Author

This is what I found, makes sense given the error.

@Ruud-Zuiderlicht
Copy link
Contributor

Ruud-Zuiderlicht commented Jan 12, 2018

I think there where write and read errors. I've attempted to fix the read error. Not saying these aren't related, but this probably is a write error.

The read error showed no apparent problem with the files when checked after the error occurred. But I don't think it has been verified that the file wasn't altered between error-message and manual file check though.

@mnakalay
Copy link
Contributor

mnakalay commented Jan 12, 2018

I can confirm that there are both read and write errors the read errors probably being caused by the write errors.

In the cache files, I saw on @madesimplemedia website, some were fully saved but we were getting a parse error. That made no sense because the file was big but PHP allows for 2GB files and we were nowhere near that.

On the other hand, we had parse errors on files that were not fully saved and were stopping mid-string.

Like Stash's developer said, it "runs into various race conditions when put under load" so I guess that means the system tries to read the cache file while another is writing in it and if the read operation throws an error everything stops and the write operation doesn't finish.

So the idea of locking the file while it's being read is good but apparently on Unix systems, the server is free to ignore the lock (on Windows systems the file is locked even if you don't ask for it)

In that situation, when saving the file using file_put_contents() as Stash does, the lock might be ignored and when @Ruud-Zuiderlicht code checks it doesn't find a lock and reads the file anyway.

So I'm wondering if that wouldn't explain why @JamesAntropy can still see the error.

@madesimplemedia
Copy link
Author

I seem to be getting more errors off-peak when traffic is low, rather than on-peak times, so I wonder if it happens more when reading cache than writing.
The stash developer recommended switching to Sqlite rather than Filesystem to avoid race conditions, would be good to test that.

aembler added a commit that referenced this issue Jan 18, 2018
@aembler
Copy link
Member

aembler commented Jan 18, 2018

I believe this is firmly related to flysystem caching. I am currently disabling flysystem caching for 8.3.2.

Eventually, we could/should bring this back as a configurable setting: #6312

@aembler aembler closed this as completed Jan 18, 2018
@aembler
Copy link
Member

aembler commented Jan 18, 2018

I have disabled the cache in b95a610

@madesimplemedia
Copy link
Author

Thanks Andrew I am going to give this a go.

@Remo
Copy link
Contributor

Remo commented Jan 19, 2018

We are using APCu for most of our high load projects, no issues at all

@madesimplemedia
Copy link
Author

Oh interesting! How can I implement that?

@Remo
Copy link
Contributor

Remo commented Jan 19, 2018

well, do you have APCu installed? If you have, you just have to override this https://github.com/concrete5/concrete5/blob/develop/concrete/config/concrete.php#L237

@madesimplemedia
Copy link
Author

Thanks for the info. I'll check if its installed on the server, do you have to add it to "overrides" as well as "expensive"?
Under here /concrete/src/Cache/Driver I only have FileSystemStashDriver.php

@Ruud-Zuiderlicht
Copy link
Contributor

I think he means you should set it to

                    'core_filesystem' => [
                        'class' => '\Stash\Driver\Apc',
                        'options' => [
                            'apcu' => true,
                        ],
                    ],

untested

@Remo
Copy link
Contributor

Remo commented Jan 19, 2018

We are using a custom driver, but yes, somewhere along the lines from @Ruud-Zuiderlicht
Whether you want to change the override cache is up to you. We are using the expensive in a lot of custom packages to avoid the overhead of processing pages/attributes, override cache wasn't much of a concern.

@MrKarlDilkington
Copy link
Contributor

It would be very useful to have documentation or tutorials on using APCu and Memcached with concrete5. We want people to know that concrete5 scales to enterprise and high traffic sites.

@madesimplemedia
Copy link
Author

I'm testing this on a dev site and APCu caching seems to be working rather nicely. Do you use the Cache Warmer addon, does it work with the Stash/APCu cache driver?

@a3020
Copy link
Contributor

a3020 commented Jan 22, 2018

The Cache Warmer plugin performs normal cURL requests on the website. Which cache driver is being used, shouldn't make a difference.

@madesimplemedia
Copy link
Author

Makes sense thanks! :)

@khrelian
Copy link

@madesimplemedia, how fo you test if APCu caching is working?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests