Open Bug 1921742 Opened 4 months ago Updated 13 days ago

Firefox spamming logs in journald about shader cache

Categories

(Core :: Graphics: WebRender, defect)

Product:
Core
Component:
Graphics: WebRender
Version:
Firefox 130
Platform:
x86_64
Linux
Type:
defect

Tracking

()

Status:
UNCONFIRMED

People

(Reporter: liangrui.ch, Unassigned)

Details

Attachments

(6 files)

troubleshooting-info-ncfavier
51.27 KB, text/plain
Details
firefox-info.txt
97.59 KB, text/plain
Details
firefox-info.txt
102.14 KB, application/json
Details
firefox-support.txt
41.26 KB, text/plain
Details
firefox_copy.txt
21.79 KB, text/plain
Details
firefox_raw.txt
88.68 KB, text/plain
Details

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0

Steps to reproduce:

I' m using Arch Linux as my daily drive.

I used journalctl to check systemd yesterday and I found out that Firefox reports a lot of error message like
"firefox[137614]: Failed to create /home/bryan/.cache for shader cache (Permission denied)---disabling."

The first error message is on Sep 6, which is the day I upgrade my system, and Firefox is upgraded to 130 from 129.

As far I notice that once I visit some video platform like youtube, Firefox keep reporting this error. Here is the screen record of this phenomenon: https://vimeo.com/1014038156?share=copy.

Actual results:

Firefox reports a lot of error in journald

Expected results:

There is no error message.

Here is my system information:

Operating System: Arch Linux
KDE Plasma Version: 6.1.5
KDE Frameworks Version: 6.6.0
Qt Version: 6.7.3
Kernel Version: 6.10.10-zen1-1-zen-cjktty (64-bit)
Graphics Platform: Wayland
Processors: 16 × AMD Ryzen 7 5800H with Radeon Graphics
Memory: 13.5 GiB of RAM
Graphics Processor: AMD Radeon Graphics

I have checked the permission of related directory, but I did not find something abnormal.

bryan on Bryan-YOGA14s in ~ took 14s 
❯ LC_ALL=C stat .cache/
  File: .cache/
  Size: 1882            Blocks: 8          IO Block: 4096   directory
Device: 0,50    Inode: 450         Links: 1
Access: (0755/drwxr-xr-x)  Uid: ( 1000/   bryan)   Gid: ( 1000/   bryan)
Access: 2024-09-30 17:35:59.542560487 +0800
Modify: 2024-09-30 17:18:38.967434371 +0800
Change: 2024-09-30 17:18:38.967434371 +0800
 Birth: 2024-08-18 08:55:18.030328424 +0800
bryan on Bryan-YOGA14s in ~ 
❯ LC_ALL=C stat .cache/mesa_shader_cache/ .cache/mesa_shader_cache_db/
  File: .cache/mesa_shader_cache/
  Size: 0               Blocks: 0          IO Block: 4096   directory
Device: 0,50    Inode: 1764403     Links: 1
Access: (0700/drwx------)  Uid: ( 1000/   bryan)   Gid: ( 1000/   bryan)
Access: 2024-09-30 01:19:23.555762340 +0800
Modify: 2024-09-26 22:32:24.124328934 +0800
Change: 2024-09-26 22:32:24.124328934 +0800
 Birth: 2024-09-26 22:32:24.124328934 +0800
  File: .cache/mesa_shader_cache_db/
  Size: 602             Blocks: 0          IO Block: 4096   directory
Device: 0,50    Inode: 1764404     Links: 1
Access: (0700/drwx------)  Uid: ( 1000/   bryan)   Gid: ( 1000/   bryan)
Access: 2024-09-30 01:19:23.555762340 +0800
Modify: 2024-09-26 22:32:24.144328955 +0800
Change: 2024-09-26 22:32:24.144328955 +0800
 Birth: 2024-09-26 22:32:24.124328934 +0800
OS: Unspecified → Linux
Hardware: Unspecified → x86_64

The Bugbug bot thinks this bug should belong to the 'Core::Graphics: WebRender' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: Untriaged → Graphics: WebRender
Product: Firefox → Core

Can you go to about:support in Firefox and click either one of the two copy to clipboard buttons at the top of that page and paste into an attachment on this bug? It has information about your OpenGL drivers and decisions the browser made on how to play media such as video streams which may be relevant.

Severity: -- → S3
Flags: needinfo?(liangrui.ch)

I'm having the same issue, here's my info.

Attached file firefox-info.txt —

Here is my firefox information.

Flags: needinfo?(liangrui.ch)

(In reply to Ashley Hale [:ahale] from comment #4)

Can you go to about:support in Firefox and click either one of the two copy to clipboard buttons at the top of that page and paste into an attachment on this bug? It has information about your OpenGL drivers and decisions the browser made on how to play media such as video streams which may be relevant.

Sorry for replying late, I uploaded my firefox information just now.

The same thing is happening for me with the Flatpak for the location ~/.var/app/org.mozilla.firefox/cache, and I attached my about:support information as well in case it helps to narrow the problem down.

Attached file firefox-info.txt —

I started looking into this issues as well. My system:

Distro: EndeavourOS (ARCH)
Kernel: 6.11.9-zen1-1-zen arch: x86_64 bits: 64
Desktop: GNOME v: 47.2
Firefox 133 (native package).

I notice when I start Firefox and it needs to use mesa shaders it creates the two following directories:

~/.cache/mesa_shader_cache_db
~/.cache/mesa_shader_cache

I did try deleting these directories and let them re-create to make sure they had the expected permissions:

drwx------    2 user user     4096 Dec  9 17:31  mesa_shader_cache
drwx------   52 user user     4096 Dec  9 17:31  mesa_shader_cache_db

When I run firefox from terminal I will get the follow messages when a video starts playing:

❯ firefox
Failed to create /home for shader cache (Permission denied)---disabling.
Failed to create /home for shader cache (Permission denied)---disabling.
Unsupported modifier, resource creation failed.

I will attach my firefox support details to help with the issue.

Attached file firefox-support.txt —

(In reply to liangrui.ch from comment #7)

(In reply to Ashley Hale [:ahale] from comment #4)

Can you go to about:support in Firefox and click either one of the two copy to clipboard buttons at the top of that page and paste into an attachment on this bug? It has information about your OpenGL drivers and decisions the browser made on how to play media such as video streams which may be relevant.

Sorry for replying late, I uploaded my firefox information just now.

Hi Liang,

I was wondering if you tried downgrading Firefox to a previous release to see if the error went away?

Thanks

Failed to create /home for shader cache (Permission denied)---disabling.

Exact same message here, also using Arch w/ kernel 6.12.4 and firefox 133.0.

(In reply to rsramkis from comment #12)

(In reply to liangrui.ch from comment #7)

(In reply to Ashley Hale [:ahale] from comment #4)

Can you go to about:support in Firefox and click either one of the two copy to clipboard buttons at the top of that page and paste into an attachment on this bug? It has information about your OpenGL drivers and decisions the browser made on how to play media such as video streams which may be relevant.

Sorry for replying late, I uploaded my firefox information just now.

Hi Liang,

I was wondering if you tried downgrading Firefox to a previous release to see if the error went away?

Thanks

No, but I'm sure that the error message came after Firefox 130.

Can also confirm this bug is happening for me as well. Also on Firefox 133.0.3.

(In reply to Ashley Hale [:ahale] from comment #4)

Can you go to about:support in Firefox and click either one of the two copy to clipboard buttons at the top of that page and paste into an attachment on this bug? It has information about your OpenGL drivers and decisions the browser made on how to play media such as video streams which may be relevant.

Hi Ashley,

Is there an update on where we are with this bug? There are multiple people reporting the issue as re-producible. Can we get anything else to help you complete the root cause analysis?

Just to confirm the same issue: Failed to create /var for shader cache (Permission denied)---disabling:

dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: libva info: VA-API version 1.19.0
dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: libva info: Trying to open /usr/lib/x86_64-linux-gnu/dri/radeonsi_drv_video.so
dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: libva info: Trying to open /usr/lib/x86_64-linux-gnu/dri/intel-vaapi-driver/radeonsi_drv_video.so
dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: libva info: Trying to open /usr/lib/x86_64-linux-gnu/GL/lib/dri/radeonsi_drv_video.so
dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: libva info: Found init function __vaDriverInit_1_19
dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:02:58 fedora org.mozilla.firefox.desktop[75880]: libva info: va_openDriver() returns 0
dec 29 22:03:01 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:06 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:07 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora bluetoothd[1418]: Player registered: sender=:1.35 path=/_1_984
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.
dec 29 22:03:08 fedora org.mozilla.firefox.desktop[75880]: Failed to create /var for shader cache (Permission denied)---disabling.

Attached file firefox_copy.txt —
Attached file firefox_raw.txt —

I'm using a hybrid stack, and on Fedora Silverblue.

It seems very unstable, and I do get a low performance.

Getting the same message on system's installed Firefox on OpenSUSE Tumbleweed.

On a first glance it looks like some sandboxed Firefox process does not have rights to stat() in arbitrary directories.

Seems to be caused by the code at https://searchfox.org/mozilla-central/source/third_party/rust/glslopt/glsl-optimizer/src/util/disk_cache.c#149

   if (stat(path, &sb) == 0) {
      if (S_ISDIR(sb.st_mode)) {
         return 0;
      } else {
         fprintf(stderr, "Cannot use %s for shader cache (not a directory)"
                         "---disabling.\n", path);
         return -1;
      }
   }

Correction on the above message. The error message is very similar but different to the one I mentioned. Seems to be coming from a few lines under in the same file https://searchfox.org/mozilla-central/source/third_party/rust/glslopt/glsl-optimizer/src/util/disk_cache.c#159

   int ret = mkdir(path, 0755);
   if (ret == 0 || (ret == -1 && errno == EEXIST))
     return 0;

   fprintf(stderr, "Failed to create %s for shader cache (%s)---disabling.\n",
           path, strerror(errno));

   return -1;

So it's an error on mkdir(), not on stat that I erroneously mentioned. My assumption then is wrong, it's not a sandbox error, as no user process should mkdir() on these system directories.

Could you please try setting MESA_SHADER_CACHE_DIR? (see https://github.com/flathub/io.gitlab.librewolf-community/pull/145/files)

For some reason I did get this at first on the Firefox flatpak, but after forcing VA-API/HWAccel, the issue went away.
I don't know why.

I analyzed the problem, and indeed the issue is triggered by a sub-process with limited privilege/sandboxed.
It looks like this message log does not have any impact

Here the functions called by disk_cache_create() in mesa source code:

  • disk_cache_delete_old_cache() is only called if MESA_SHADER_CACHE_DIR is not defined
    • disk_cache_generate_cache_dir()
    • mkdir_if_needed("/home") failed to stat()
  • disk_cache_type_create()
    • disk_cache_enabled() is called, if cache is disabled (disabled if not a __normal_user()), do nothing and return.
    • disk_cache_generate_cache_dir() (is not called if cache is disabled). So this call never trigger the warning

So defining MESA_SHADER_CACHE_DIR prevent the delete of the cache, and so no warning is displayed.

To fix this the following patch is needed in mesa (I will try to submit it):
Add the following lines at the beginning of disk_cache_delete_old_cache():

   if (!disk_cache_enabled())
      return;

(In reply to benjarobin from comment #26)

Fix the issue in this MR: https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/32886

If you have a local install (from Arch repository) and not a Flatpak, there a work around to stop the spamming?

On my own I did the following:

  1. Deleted the two directories:
~/.cache/mesa_shader_cache_db
~/.cache/mesa_shader_cache
  1. Added the following to the " ~/.config/environment.d/envvars.conf " file:
MESA_SHADER_CACHE_DIR=/home/testuser/.cache/mesa_shader_cache
  1. After reboot and launching Firefox and playing a video I did see the directories get recreated:
/home/testuser/.cache/mesa_shader_cache
/home/testuser/.cache/mesa_shader_cache/mesa_shader_cache_db

But I am still seeing the journal filling up with the same error messages.

(In reply to rsramkis from comment #27)

(In reply to benjarobin from comment #26)

Fix the issue in this MR: https://gitlab.freedesktop.org/mesa/mesa/-/merge_requests/32886

If you have a local install (from Arch repository) and not a Flatpak, there a work around to stop the spamming?

On my own I did the following:

  1. Deleted the two directories:
~/.cache/mesa_shader_cache_db
~/.cache/mesa_shader_cache
  1. Added the following to the " ~/.config/environment.d/envvars.conf " file:
MESA_SHADER_CACHE_DIR=/home/testuser/.cache/mesa_shader_cache
  1. After reboot and launching Firefox and playing a video I did see the directories get recreated:
/home/testuser/.cache/mesa_shader_cache
/home/testuser/.cache/mesa_shader_cache/mesa_shader_cache_db

But I am still seeing the journal filling up with the same error messages.

Did you try setting using this as a local env var, e.g. prefix this with the Firefox command?

I also enabled video HWAccel, but I don't know if this prevents the shader cache from being used, thus preventing the error.

(In reply to rsramkis from comment #27)

But I am still seeing the journal filling up with the same error messages.

From a terminal, is the environment variable MESA_SHADER_CACHE_DIR set? What is the output of: echo $MESA_SHADER_CACHE_DIR
If the environment variable MESA_SHADER_CACHE_DIR is indeed set, close all Firefox window / process, then launch Firefox from that terminal. Do you have still these errors messages, and if this is the case, what is the error exactly?

(In reply to benjarobin from comment #29)

(In reply to rsramkis from comment #27)

But I am still seeing the journal filling up with the same error messages.

From a terminal, is the environment variable MESA_SHADER_CACHE_DIR set? What is the output of: echo $MESA_SHADER_CACHE_DIR
If the environment variable MESA_SHADER_CACHE_DIR is indeed set, close all Firefox window / process, then launch Firefox from that terminal. Do you have still these errors messages, and if this is the case, what is the error exactly?

This is what I am seeing after I reset my test:

❯ echo $MESA_SHADER_CACHE_DIR
/home/rsruser/.cache/mesa_shader_cache

~
❯ firefox
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.

As long as the video is playing the screen will fill up with the out put of "Unsupported modifier, resource creation failed.".

(In reply to rsramkis from comment #30)

Unsupported modifier, resource creation failed.

This is another issue, complete unrelated to this ticket/bug report. You should create another bug report for that

(In reply to benjarobin from comment #31)

(In reply to rsramkis from comment #30)

Unsupported modifier, resource creation failed.

This is another issue, complete unrelated to this ticket/bug report. You should create another bug report for that

I can create another bug (but then this one has been sitting around for 4 months). The "Unsupported modifier, resource creation failed." only shows up when playing a video (e.g. https://www.youtube.com/live/6nCNlI_0-KU?si=rW9M_Z9F1h0JSIxx).

This is the output without an environment variable:

❯ firefox
Failed to create /home for shader cache (Permission denied)---disabling.
Failed to create /home for shader cache (Permission denied)---disabling.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.
Unsupported modifier, resource creation failed.

My guess is the suggested fix is part of the issue. I get this feeling I open another bug and there is a dependency with this issue. Should we not try to debug here instead of just addressing the shader log messages?

If not, then what should I capture (debugging and all) to make sure we get everything for the investigator in one shot?

Trust me, this is a complete unrelated issue (that I do not have). Please do not SPAM this issue with unrelated topic.

I've continued the separate issue with this bug filed 23 days ago:

https://bugzilla.mozilla.org/show_bug.cgi?id=1933040

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: