HTTP Error 500: http+unix://%2Frun%2Fsnapd.socket/v2/systems/enhanced-secureboot-desktop

[Olivier Gayot]

In multiple private reports, we are seeing snapd return a HTTP 500 error when Subiquity queries http+unix://%2Frun%2Fsnapd.socket/v2/systems/enhanced-secureboot-desktop. Some reports are on 23.10 and some others on 24.04 so it isn't specific to a given Ubuntu release.

2024-02-28 19:32:48,720 ERROR subiquity.server.server:415 top level error
Traceback (most recent call last):
  File "/snap/ubuntu-desktop-bootstrap/6/usr/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquitycore/async_helpers.py", line 25, in _done
    fut.result()
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/server/controllers/filesystem.py", line 413, in _examine_systems
    system = await self._get_system(name, label)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/server/controllers/filesystem.py", line 341, in _get_system
    system = await self.app.snapdapi.v2.systems[label].GET()
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/common/api/client.py", line 47, in impl
    async with make_request(
  File "/snap/ubuntu-desktop-bootstrap/6/usr/lib/python3.10/contextlib.py", line 199, in __aenter__
    return await anext(self.gen)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/server/snapdapi.py", line 298, in make_request
    content = await async_snapd.get(path[1:], **params)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquitycore/snapd.py", line 209, in get
    response.raise_for_status()
  File "/snap/ubuntu-desktop-bootstrap/6/usr/lib/python3/dist-packages/requests/models.py", line 943, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: http+unix://%2Frun%2Fsnapd.socket/v2/systems/enhanced-secureboot-desktop
2024-02-28 19:32:48,803 DEBUG subiquity.common.errorreport:398 generating crash report
2024-02-28 19:32:48,804 INFO subiquity.common.errorreport:424 saving crash report 'unknown error crashed with HTTPError' to /var/crash/1709148768.803752899.unknown.crash
2024-02-28 19:32:48,806 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 500 Traceback (most recent call last):
  File "/snap/ubuntu-desktop-bootstrap/6/b...
2024-02-28 19:32:48,806 DEBUG subiquity.server.server:448 request to /storage/v2?wait=true crashed
Traceback (most recent call last):
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/common/api/server.py", line 164, in handler
    result = await implementation(**args)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/server/controllers/filesystem.py", line 1024, in v2_GET
    return await self.get_v2_storage_response(self.model, wait, include_raid)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/server/controllers/filesystem.py", line 1000, in get_v2_storage_response
    probe_resp = await self._probe_response(wait, StorageResponseV2)
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquity/server/controllers/filesystem.py", line 754, in _probe_response
    await self._examine_systems_task.wait()
  File "/snap/ubuntu-desktop-bootstrap/6/bin/subiquity/subiquitycore/async_helpers.py", line 113, in wait
    return await self.task
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: http+unix://%2Frun%2Fsnapd.socket/v2/systems/enhanced-secureboot-desktop
2024-02-28 19:32:48,806 DEBUG subiquity.common.errorreport:398 generating crash report
2024-02-28 19:32:48,811 INFO subiquity.common.errorreport:424 saving crash report 'request to /storage/v2?wait=true crashed with HTTPError' to /var/crash/1709148768.806477547.server_request_fail.crash

[Olivier Gayot (ogayot)]

I spent time trying to reproduce this issue by sending a combination of:
 * POST requests to /source (to force the storage model to query /v2/systems/enhanced-secureboot-desktop again
 * GET requests to /filesystem/v2

And sadly I wasn't able to reproduce the issue. I must be missing something.

OTOH I created https://github.com/canonical/subiquity/pull/1975 to log the response in case of failure. This should help us understand what's going on on the long run.

[Olivier Gayot (ogayot)]

First report came up with the logs enabled:

2024-04-25 20:05:20,508 WARNING subiquity.server.controllers.filesystem:347 v2/systems/enhanced-secureboot-desktop returned {"type":"error","status-code":500,"status":"Internal Server Error","result":{"message":"cannot load essential snaps metadata: cannot validate \"/var/lib/snapd/seed/snaps/pc-kernel_1803.snap\" for snap \"pc-kernel\" (snap-id \"pYVQrBcKmBa0mZ4CCN7ExT6jH8rY1hza\"), hash mismatch with snap-revision"}}