Intermittent failure in offline compression

[jtremesay-sereema]

Hi,

We use django-compressor (v3.1) in our Django (v4.0.2) application. Our CI randomly fails (something like 1 run in 20) on the compress step with errors like this one:

#18 [16/17] RUN python manage.py compress --extension .html,.xsl
#18 3.681 CommandError: An error occurred during rendering registration/password_change_form.html: [Errno 2] No such file or directory: '/code/sereema/staticfiles/CACHE/js/output.5840362cca8f.js'

If I read correctly, this is a known issue (#1082) that was fixed in v3.0. But it seems like the fix was not enough.

[carltongibson]

Hi @jtremesay-sereema — Can you take a look at #1086 and see if you can work out a reproduce? If we can see it ourselves we've got a chance of fixing it.

[jtremesay-sereema]

I can try

[jtremesay-sereema]

I have created a dummy django project that trigger the bug most of the time

https://github.com/jtremesay-sereema/django-compressor-issue-1099

$ pip install -r requirements.txt
$ ./manage.py collectstatic --no-input
$ ./manage.py compress
CommandError: An error occurred during rendering foo/gen/foo_669.html: [Errno 2] No such file or directory: '/Users/jtremesay/projects/compressor_issue/staticfiles/CACHE/js/output.6169dc6ebd1b.js'
Compressing...
$ ./manage.py compress
CommandError: An error occurred during rendering foo/gen/foo_931.html: [Errno 2] No such file or directory: '/Users/jtremesay/projects/compressor_issue/staticfiles/CACHE/js/output.6169dc6ebd1b.js'
Compressing...
$ ./manage.py compress
CommandError: An error occurred during rendering foo/gen/foo_164.html: [Errno 2] No such file or directory: '/Users/jtremesay/projects/compressor_issue/staticfiles/CACHE/js/output.6169dc6ebd1b.js'
Compressing...
$ ./manage.py compress
CommandError: An error occurred during rendering foo/gen/foo_3.html: [Errno 2] No such file or directory: '/Users/jtremesay/projects/compressor_issue/staticfiles/CACHE/js/output.6169dc6ebd1b.js'
Compressing...
$ ./manage.py compress
CommandError: An error occurred during rendering foo/gen/foo_433.html: [Errno 2] No such file or directory: '/Users/jtremesay/projects/compressor_issue/staticfiles/CACHE/js/output.6169dc6ebd1b.js'
Compressing...
$ ./manage.py compress
CommandError: An error occurred during rendering foo/gen/foo_934.html: [Errno 2] No such file or directory: '/Users/jtremesay/projects/compressor_issue/staticfiles/CACHE/js/output.6169dc6ebd1b.js'
Compressing... ⏎

[carltongibson]

Super. Thanks @jtremesay-sereema. //cc @cuu508

[cuu508]

The dummy project is awesome, it reliably reproduces the issue for me. I played around with it for a good bit, some findings:

Looking at the project's templates, the contents of the {% compress %} tag is unique for every template. Therefore, each {% compress %} tag gets its own unique key in the offline manifest.

But, each {% compress %} renders the same output (each template includes a different JS file, but the JS files are all empty, so the end result ends up being the same).

In the offline manifest we get a mapping:

2355b4e143e1afd74db9e033f54732280da6ee00a40ac01603067741881e417b -> output.6169dc6ebd1b.js
f14af6e084bd1a9f6dcec2a008375486b9765d1638b002c3d316bdbab7d2280a -> output.6169dc6ebd1b.js
b4f9d16e23ac06d3fe69f9a51543ad66804cf18825fa07a39111a9ca74d68b7e -> output.6169dc6ebd1b.js
f94920008dd794ad23a04d76de2e2abb47b5bab52c04dc9b4fb8c1bf53141f9a -> output.6169dc6ebd1b.js
[... and lots more...]

Many different offline manifest keys, all pointing to the same file.

If we look at Compressor.output_file(), it:

• generates the filename based on file contents (explains why we get output.6169dc6ebd1b.js over and over again)
• saves the file even if it already exists (because forced=True)

The compress management command runs multiple threads concurrently, if several threads try to save the same file at the same time, we get the error.

One idea for the fix is to remove the "or forced" condition in output_file():

        if not self.storage.exists(new_filepath) or forced:
            self.storage.save(new_filepath, ContentFile(content.encode(self.charset)))

This way, if the file already exists in the filesystem, it would not get overwritten. This fixes the exception and speeds up offline compression :-) But I guess the extra condition was added for a reason. I don't know the reason. Here's the commit where it was added: 1908747

[diox]

Great investigation, thanks!

From memory (I haven't looked closely at this code in years), I think the problem is that forced has too many responsibilities:

• It enables compress command to run even when COMPRESS_ENABLED or COMPRESS_OFFLINE are False, through the --force command line parameter.
• It enables compress to bypass checks about caching, ensuring we are generating a fresh manifest (regardless of the --force parameter: we want this every time).
• It tries to overwrite existing files (our problem here - as mentioned in the previous comment, that's 1908747#diff-13ffcf581741774d4a5f90778458e8b4e884581b455f1f42a12de93fce0d2976R183), which can be useful to clear files from a previously broken run but also from a previous run with different settings. The filename depends on the hash of the contents, but settings governing what we do with the contents might have changed (regardless of the --force parameter: we want this every time).

Without refactoring how forced is used:

• If we keep the condition, we cause that bug with threading.
• If we remove this condition, it settings have changed we are not regenerating files as we should
• If we don't pass the forced in the first place, we likely break regenerating a fresh manifest/fresh files when cache exists.

Bottom line, I think a deeper fix is needed - but I'd be happy to be proven wrong!

[cuu508]

It tries to overwrite existing files [...], which can be useful to clear files from a previously broken run but also from a previous run with different settings.

Perhaps we can find a way to overwrite existing files, but only once within a single manage.py compress run? Suppose we kept track of what cache keys have been saved this run. We could then grab content from cache for known-fresh keys, instead of regenerating them.

In compressor.templatetags.compress.CompressorMixin.render_compressed there's this bit:

        # Check cache
        cache_key = None
        if settings.COMPRESS_ENABLED and not forced:
            cache_key, cache_content = self.render_cached(compressor, kind, mode)
            if cache_content is not None:
                return cache_content

Currently, when running manage.py compress, it does not run because forced=True. But let's say we change the condition to the effect of "if compress enabled and we have written this cache key on this run, then do use cache". Might that work?

[diox]

Yeah. The thing that surprised me is that this is not very different in essence from ef45175 : since what you added in this commit was based on the key being in the manifest, I would have expected it be enough to work around this issue ?

[cuu508]

Thought so too! The catch here is that we have many different offline manifest keys that map to the same generated file:

2355b4e143e1afd74db9e033f54732280da6ee00a40ac01603067741881e417b -> output.6169dc6ebd1b.js
f14af6e084bd1a9f6dcec2a008375486b9765d1638b002c3d316bdbab7d2280a -> output.6169dc6ebd1b.js
b4f9d16e23ac06d3fe69f9a51543ad66804cf18825fa07a39111a9ca74d68b7e -> output.6169dc6ebd1b.js
f94920008dd794ad23a04d76de2e2abb47b5bab52c04dc9b4fb8c1bf53141f9a -> output.6169dc6ebd1b.js
[... and lots more...]

compressor does not regenerate the same offline manifest key multiple times any more. But, if several different {% compress %} ... {% endcompress %} tags render identical content, it still saves the same cache key multiple times.

[diox]

Oh right, I wasn't paying enough attention. So yeah, your idea makes sense, I'm not sure how much refactoring is going to be needed to get to that point though.

[cuu508]

Here's an idea for discussion.

Here's how compressor.base.Compressor.output_file() method looks currently:

def output_file(self, mode, content, forced=False, basename=None):
    """
    The output method that saves the content to a file and renders
    the appropriate template with the file's URL.
    """
    new_filepath = self.get_filepath(content, basename=basename)
    if not self.storage.exists(new_filepath) or forced:
        self.storage.save(new_filepath, ContentFile(content.encode(self.charset)))
    url = mark_safe(self.storage.url(new_filepath))
    return self.render_output(mode, {"url": url})

It:

• generates the filepath based on the contents of the file that's about to be written to the storage
• if the filepath doesn't exist in the storage, or it's an offline compression run, save it to the storage

The proposal: if forced=True, then track what filepaths we've already handled, and only save to storage the filepaths that we see for the first time. I added seen_filepaths and seen_filepaths_lock class variables to compressor.base.Compressor:

class Compressor:
    """
    Base compressor object to be subclassed for content type
    depending implementations details.
    """

    output_mimetypes = {}
    seen_filepaths = set()
    seen_filepaths_lock = Lock()

And changed the output_file method like so:

def output_file(self, mode, content, forced=False, basename=None):
    """
    The output method that saves the content to a file and renders
    the appropriate template with the file's URL.
    """
    new_filepath = self.get_filepath(content, basename=basename)
    if forced:
        # forced=True means this is offline generation (manage.py compress).
        # We should overwrite all existing files.
        # But, to avoid overwriting a file more than once in a single run,
        # keep track of already handled filepaths in `seen_filepaths` class
        # variable. If a filepath is already there, *don't* call
        # self.storage.save() for it.
        with self.seen_filepaths_lock:
            skip_save = new_filepath in self.seen_filepaths
            self.seen_filepaths.add(new_filepath)
    else:
        skip_save = self.storage.exists(new_filepath)

    if not skip_save:
        self.storage.save(new_filepath, ContentFile(content.encode(self.charset)))

    url = mark_safe(self.storage.url(new_filepath))
    return self.render_output(mode, {"url": url})

Class variables feel iffy to me, as they are basically globals. But the alternative would be to pass seen_filepaths down the call chain from the management command. And the call chain is ~7 levels deep.

[cuu508]

I created a PR with the above, plus a test case – #1100.

I'm not 100% sure this is the right way to fix the issue, but it is more concrete and easier to play around with in a PR form.

[cuu508]

I created another PR with an alternate (and I think a better) fix – #1105

[diox]

@jtremesay-sereema thanks to @cuu508 we have a fix for this in the develop branch. Please try it with your application - using git+https://github.com/django-compressor/django-compressor.git@00910e0bd5295044befacdad7b88249ec7bbf142 in your https://github.com/jtremesay-sereema/django-compressor-issue-1099 test project compress finishes successfully for me.

[jtremesay-sereema]

Thx !

[adamkalis]

@diox @cuu508 Thanks for the fix, I've tested it to two of the django projects I maintain that had similar errors and it works perfectly without any issue. Let me know if I can help in any other way for releasing this fix.

[diox]

Excellent, thanks for the feedback, several people have now reported that it fixed the issue for them, I'll try to make a new release this week-end.

[diox]

I just released 4.0 with that fix.