[Bug]: FilesMetadataNotFoundException when trying to generate a blurhash

[SystemKeeper]

⚠️ This issue respects the following points: ⚠️

• This is a bug, not a question or a configuration/webserver/proxy issue.
• This issue is not already reported on Github OR Nextcloud Community Forum (I've searched it).
• Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
• I agree to follow Nextcloud's Code of Conduct.

Bug description

{
    "level": 2,
    "user": "--",
    "app": "no app in context",
    "method": "",
    "url": "--",
    "message": "Error while generating metadata for fileid 886",
    "version": "29.0.0.10",
    "exception": {
        "Exception": "OCP\\FilesMetadata\\Exceptions\\FilesMetadataNotFoundException",
        "Message": "",
        "Code": 0,
        "Trace": [
            {
                "file": "/var/www/html/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php",
                "line": 77,
                "function": "getEtag",
                "class": "OC\\FilesMetadata\\Model\\FilesMetadata",
                "type": "->",
                "args": [
                    "blurhash"
                ]
            },
            {
                "file": "/var/www/html/lib/private/EventDispatcher/ServiceEventListener.php",
                "line": 86,
                "function": "handle",
                "class": "OC\\Blurhash\\Listener\\GenerateBlurhashMetadata",
                "type": "->",
                "args": [
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ]
                ]
            },
[...]
        "File": "/var/www/html/lib/private/FilesMetadata/Model/FilesMetadata.php",
        "Line": 162,
        "message": "Error while generating metadata for fileid 886",
        "CustomMessage": "Error while generating metadata for fileid 886"
    }
}

Full exception:

{
    "reqId": "kUs0n5NXAfL8vpCKYtQI",
    "level": 2,
    "time": "2024-03-15T17:40:02+00:00",
    "remoteAddr": "",
    "user": "--",
    "app": "no app in context",
    "method": "",
    "url": "--",
    "message": "Error while generating metadata for fileid 886",
    "userAgent": "--",
    "version": "29.0.0.10",
    "exception": {
        "Exception": "OCP\\FilesMetadata\\Exceptions\\FilesMetadataNotFoundException",
        "Message": "",
        "Code": 0,
        "Trace": [
            {
                "file": "/var/www/html/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php",
                "line": 77,
                "function": "getEtag",
                "class": "OC\\FilesMetadata\\Model\\FilesMetadata",
                "type": "->",
                "args": [
                    "blurhash"
                ]
            },
            {
                "file": "/var/www/html/lib/private/EventDispatcher/ServiceEventListener.php",
                "line": 86,
                "function": "handle",
                "class": "OC\\Blurhash\\Listener\\GenerateBlurhashMetadata",
                "type": "->",
                "args": [
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ]
                ]
            },
            {
                "file": "/var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
                "line": 230,
                "function": "__invoke",
                "class": "OC\\EventDispatcher\\ServiceEventListener",
                "type": "->",
                "args": [
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ],
                    "OCP\\FilesMetadata\\Event\\MetadataLiveEvent",
                    [
                        "Symfony\\Component\\EventDispatcher\\EventDispatcher"
                    ]
                ]
            },
            {
                "file": "/var/www/html/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
                "line": 59,
                "function": "callListeners",
                "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
                "type": "->",
                "args": [
                    [
                        [
                            "Closure"
                        ],
                        [
                            "Closure"
                        ],
                        [
                            "Closure"
                        ],
                        [
                            "Closure"
                        ],
                        [
                            "Closure"
                        ]
                    ],
                    "OCP\\FilesMetadata\\Event\\MetadataLiveEvent",
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ]
                ]
            },
            {
                "file": "/var/www/html/lib/private/EventDispatcher/EventDispatcher.php",
                "line": 86,
                "function": "dispatch",
                "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
                "type": "->",
                "args": [
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ],
                    "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                ]
            },
            {
                "file": "/var/www/html/lib/private/EventDispatcher/EventDispatcher.php",
                "line": 98,
                "function": "dispatch",
                "class": "OC\\EventDispatcher\\EventDispatcher",
                "type": "->",
                "args": [
                    "OCP\\FilesMetadata\\Event\\MetadataLiveEvent",
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ]
                ]
            },
            {
                "file": "/var/www/html/lib/private/FilesMetadata/FilesMetadataManager.php",
                "line": 115,
                "function": "dispatchTyped",
                "class": "OC\\EventDispatcher\\EventDispatcher",
                "type": "->",
                "args": [
                    [
                        "OCP\\FilesMetadata\\Event\\MetadataLiveEvent"
                    ]
                ]
            },
            {
                "file": "/var/www/html/core/BackgroundJobs/GenerateMetadataJob.php",
                "line": 109,
                "function": "refreshMetadata",
                "class": "OC\\FilesMetadata\\FilesMetadataManager",
                "type": "->",
                "args": [
                    [
                        "OC\\Files\\Node\\File"
                    ],
                    3
                ]
            },
            {
                "file": "/var/www/html/core/BackgroundJobs/GenerateMetadataJob.php",
                "line": 88,
                "function": "scanFolder",
                "class": "OC\\Core\\BackgroundJobs\\GenerateMetadataJob",
                "type": "->",
                "args": [
                    [
                        "OC\\Files\\Node\\LazyUserFolder"
                    ]
                ]
            },
            {
                "file": "/var/www/html/core/BackgroundJobs/GenerateMetadataJob.php",
                "line": 74,
                "function": "scanFilesForUser",
                "class": "OC\\Core\\BackgroundJobs\\GenerateMetadataJob",
                "type": "->",
                "args": [
                    "admin"
                ]
            },
            {
                "file": "/var/www/html/lib/public/BackgroundJob/Job.php",
                "line": 80,
                "function": "run",
                "class": "OC\\Core\\BackgroundJobs\\GenerateMetadataJob",
                "type": "->",
                "args": [
                    null
                ]
            },
            {
                "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
                "line": 102,
                "function": "start",
                "class": "OCP\\BackgroundJob\\Job",
                "type": "->",
                "args": [
                    [
                        "OC\\BackgroundJob\\JobList"
                    ]
                ]
            },
            {
                "file": "/var/www/html/lib/public/BackgroundJob/TimedJob.php",
                "line": 92,
                "function": "start",
                "class": "OCP\\BackgroundJob\\TimedJob",
                "type": "->",
                "args": [
                    [
                        "OC\\BackgroundJob\\JobList"
                    ]
                ]
            },
            {
                "file": "/var/www/html/cron.php",
                "line": 176,
                "function": "execute",
                "class": "OCP\\BackgroundJob\\TimedJob",
                "type": "->",
                "args": [
                    [
                        "OC\\BackgroundJob\\JobList"
                    ]
                ]
            }
        ],
        "File": "/var/www/html/lib/private/FilesMetadata/Model/FilesMetadata.php",
        "Line": 162,
        "message": "Error while generating metadata for fileid 886",
        "CustomMessage": "Error while generating metadata for fileid 886"
    }
}

If I understand the issue correctly, the issue is that getEtag throws a FilesMetadataNotFoundException here, when the key does not exist:

server/lib/private/FilesMetadata/Model/FilesMetadata.php

Lines 160 to 163 in 3fa5e59

	public function getEtag(string $key): string {
	if (!array_key_exists($key, $this->metadata)) {
	throw new FilesMetadataNotFoundException();
	}

But trying to generate a blurhash, this exception is not caught, therefore the blurhash metadata is never generated:

server/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php

Lines 75 to 78 in 79e9cdc

	$currentEtag = $file->getEtag();
	$metadata = $event->getMetadata();
	if ($metadata->getEtag('blurhash') === $currentEtag) {
	return;

Regression from #42707 ?
This obviously works when there's already metadata available for that file, but it fails, when blurhash is the first one to generate metadata.

@ArtificialOwl

I assume something like this is needed?

diff --git a/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php b/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php
index b57dfa317e4..15b830c0a88 100644
--- a/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php
+++ b/lib/private/Blurhash/Listener/GenerateBlurhashMetadata.php
@@ -74,8 +74,12 @@ class GenerateBlurhashMetadata implements IEventListener {
 
                $currentEtag = $file->getEtag();
                $metadata = $event->getMetadata();
-               if ($metadata->getEtag('blurhash') === $currentEtag) {
-                       return;
+
+               try {
+                       if ($metadata->getEtag('blurhash') === $currentEtag) {
+                               return;
+                       }
+               } catch (FilesMetadataNotFoundException) {
                }
 
                // too heavy to run on the live thread, request a rerun as a background job

Steps to reproduce

1. Upload a picture and wait for the exception

Expected behavior

Handle FilesMetadataNotFoundException exception correctly and generate blurhash.

Installation method

None

Nextcloud Server version

master

Operating system

None

PHP engine version

None

Web server

None

Database engine version

None

Is this bug present after an update or on a fresh install?

None

Are you using the Nextcloud Server Encryption module?

None

What user-backends are you using?

• Default user-backend (database)
• LDAP/ Active Directory
• SSO - SAML
• Other

Configuration report

No response

List of activated Apps

No response

Nextcloud Signing status

No response

Nextcloud Logs

No response

Additional info

No response

[SystemKeeper]

Fixed in #44189