Log and continue when failing to update encryption keys during for individual files

[juliusknorr]

In cases where a single file update of encryption keys fails e.g. when creating a share, the share is created as the update is handled in the postShared/postUnshared hook though the actual request to create the share fails and will be in some inconsistent state.

In the specific case there was a single file that had somehow corrupted keys so the original owner also wasn't able to open it anymore. Now when the folder containing the file was shared to a group only the files that were updated before the failing file became accessible, but since the Sharing API request fails the UI didn't get a proper response that the folder was shared and all files after the corrupt one were inaccessible.

Logging helps to get a clue about the actual affected file here and makes share operations work again.

Example trace to the original exception thrown that blocks the unshare request:

{
  "reqId": "YEniiKnnCEzjeqCBhknDOgAAAAQ",
  "level": 3,
  "time": "March 11, 2021 09:28:08",
  "remoteAddr": "REMOVED",
  "user": "REMOVED",
  "app": "no app in context",
  "method": "DELETE",
  "url": "/ocs/v2.php/apps/files_sharing/api/v1/shares/134782",
  "message": {
    "Exception": "OCA\\Encryption\\Exceptions\\MultiKeyDecryptException",
    "Message": "multikeydecrypt with share key failed:error:0906D06C:PEM routines:PEM_read_bio:no start line",
    "Code": 0,
    "Trace": [
      {
        "file": "/var/www/html/nextcloud/apps/encryption/lib/KeyManager.php",
        "line": 480,
        "function": "multiKeyDecrypt",
        "class": "OCA\\Encryption\\Crypto\\Crypt",
        "type": "->",
        "args": [
          null,
          "REMOVED",
          "-----BEGIN PRIVATE KEY-----\nREMOVED"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/apps/encryption/lib/Crypto/Encryption.php",
        "line": 396,
        "function": "getFileKey",
        "class": "OCA\\Encryption\\KeyManager",
        "type": "->",
        "args": [
          "*** sensitive parameter replaced ***",
          "*** sensitive parameter replaced ***"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/Encryption/Update.php",
        "line": 190,
        "function": "update",
        "class": "OCA\\Encryption\\Crypto\\Encryption",
        "type": "->",
        "args": [
          "*** sensitive parameters replaced ***"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/Encryption/Update.php",
        "line": 108,
        "function": "update",
        "class": "OC\\Encryption\\Update",
        "type": "->",
        "args": [
          "*** sensitive parameters replaced ***"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/Encryption/HookManager.php",
        "line": 39,
        "function": "postUnshared",
        "class": "OC\\Encryption\\Update",
        "type": "->",
        "args": [
          {
            "id": "134782",
            "itemType": "folder",
            "itemSource": 19095,
            "shareType": 1,
            "shareWith": "1001874",
            "0": "And 5 more entries, set log level to debug to see all entries"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/legacy/OC_Hook.php",
        "line": 110,
        "function": "postUnshared",
        "class": "OC\\Encryption\\HookManager",
        "type": "::",
        "args": [
          {
            "id": "134782",
            "itemType": "folder",
            "itemSource": 19095,
            "shareType": 1,
            "shareWith": "1001874",
            "0": "And 5 more entries, set log level to debug to see all entries"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/Share20/LegacyHooks.php",
        "line": 85,
        "function": "emit",
        "class": "OC_Hook",
        "type": "::",
        "args": [
          "OCP\\Share",
          "post_unshare",
          {
            "id": "134782",
            "itemType": "folder",
            "itemSource": 19095,
            "shareType": 1,
            "shareWith": "1001874",
            "0": "And 5 more entries, set log level to debug to see all entries"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
        "line": 264,
        "function": "postUnshare",
        "class": "OC\\Share20\\LegacyHooks",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\EventDispatcher\\GenericEventWrapper"
          },
          "OCP\\Share::postUnshare",
          {
            "__class__": "Symfony\\Component\\EventDispatcher\\EventDispatcher"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
        "line": 239,
        "function": "doDispatch",
        "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          [
            {
              "__class__": "Closure"
            },
            {
              "__class__": "Closure"
            }
          ],
          "OCP\\Share::postUnshare",
          {
            "__class__": "OC\\EventDispatcher\\GenericEventWrapper"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php",
        "line": 73,
        "function": "callListeners",
        "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          [
            {
              "__class__": "Closure"
            },
            {
              "__class__": "Closure"
            }
          ],
          "OCP\\Share::postUnshare",
          {
            "__class__": "OC\\EventDispatcher\\GenericEventWrapper"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/EventDispatcher/SymfonyAdapter.php",
        "line": 85,
        "function": "dispatch",
        "class": "Symfony\\Component\\EventDispatcher\\EventDispatcher",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\EventDispatcher\\GenericEventWrapper"
          },
          {
            "__class__": "OC\\EventDispatcher\\GenericEventWrapper"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/Share20/Manager.php",
        "line": 1175,
        "function": "dispatch",
        "class": "OC\\EventDispatcher\\SymfonyAdapter",
        "type": "->",
        "args": [
          "OCP\\Share::postUnshare",
          {
            "__class__": "Symfony\\Component\\EventDispatcher\\GenericEvent"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/apps/files_sharing/lib/Controller/ShareAPIController.php",
        "line": 405,
        "function": "deleteShare",
        "class": "OC\\Share20\\Manager",
        "type": "->",
        "args": [
          {
            "__class__": "OC\\Share20\\Share"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/AppFramework/Http/Dispatcher.php",
        "line": 169,
        "function": "deleteShare",
        "class": "OCA\\Files_Sharing\\Controller\\ShareAPIController",
        "type": "->",
        "args": [
          "134782"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/AppFramework/Http/Dispatcher.php",
        "line": 100,
        "function": "executeController",
        "class": "OC\\AppFramework\\Http\\Dispatcher",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Files_Sharing\\Controller\\ShareAPIController"
          },
          "deleteShare"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/AppFramework/App.php",
        "line": 152,
        "function": "dispatch",
        "class": "OC\\AppFramework\\Http\\Dispatcher",
        "type": "->",
        "args": [
          {
            "__class__": "OCA\\Files_Sharing\\Controller\\ShareAPIController"
          },
          "deleteShare"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/lib/private/Route/Router.php",
        "line": 309,
        "function": "main",
        "class": "OC\\AppFramework\\App",
        "type": "::",
        "args": [
          "OCA\\Files_Sharing\\Controller\\ShareAPIController",
          "deleteShare",
          {
            "__class__": "OC\\AppFramework\\DependencyInjection\\DIContainer"
          },
          {
            "id": "134782",
            "_route": "ocs.files_sharing.ShareAPI.deleteShare"
          }
        ]
      },
      {
        "file": "/var/www/html/nextcloud/ocs/v1.php",
        "line": 88,
        "function": "match",
        "class": "OC\\Route\\Router",
        "type": "->",
        "args": [
          "/ocsapp/apps/files_sharing/api/v1/shares/134782"
        ]
      },
      {
        "file": "/var/www/html/nextcloud/ocs/v2.php",
        "line": 24,
        "args": [
          "/var/www/html/nextcloud/ocs/v1.php"
        ],
        "function": "require_once"
      }
    ],
    "File": "/var/www/html/nextcloud/apps/encryption/lib/Crypto/Crypt.php",
    "Line": 682,
    "Hint": "multikeydecrypt with share key failed:error:0906D06C:PEM routines:PEM_read_bio:no start line",
    "CustomMessage": "--"
  },
  "userAgent": "Mozilla/5.0 (X11; Linux x86_64; rv:86.0) Gecko/20100101 Firefox/86.0",
  "version": "20.0.7.1"
}

[rullzer]

Fine by me

[PVince81]

Makes sense 👍

[PVince81]

php:cs is not happy:

Warning: Found violation(s) of type: list_syntax
Warning: Found violation(s) of type: class_definition
Warning: Found violation(s) of type: braces

[PVince81]

rebased, let's see if the problem disappears...

[juliusknorr]

/backport to stable21

[juliusknorr]

/backport to stable20