Thumbnailer seems broken

[t3chguy]

Description

Since #17239 Element Web's end-to-end test suite has started failing. Digging in this seems to be due to the /thumbnail API returning zero data for a 200 OK.

Steps to reproduce

• Upload image
• Download it successfuly
• Try request a thumbnail and be given

Homeserver

localhost

Synapse Version

develop

Installation Method

Docker (matrixdotorg/synapse)

Database

SQLite

Workers

Single process

Platform

Docker

Configuration

https://github.com/matrix-org/matrix-react-sdk/blob/develop/playwright/plugins/homeserver/synapse/templates/default/homeserver.yaml

Relevant log output

2024-05-30 08:03:06,769 - synapse.access.http.8008 - 428 - DEBUG - GET-69 - ::ffff:172.17.0.1 - 8008 - Received request: GET /_matrix/media/v3/thumbnail/localhost/FUWUhOIoKJihHQRBdtBJPHIF?width=14&height=14&method=crop&allow_redirect=true
2024-05-30 08:03:06,770 - synapse.access.http.8008 - 428 - DEBUG - GET-70 - ::ffff:172.17.0.1 - 8008 - Received request: GET /_matrix/media/v3/thumbnail/localhost/FUWUhOIoKJihHQRBdtBJPHIF?width=30&height=30&method=crop&allow_redirect=true
2024-05-30 08:03:06,770 - synapse.storage.txn - 758 - DEBUG - GET-69 - [TXN START] {get_local_media-209}
2024-05-30 08:03:06,770 - synapse.storage.SQL - 466 - DEBUG - GET-69 - [SQL] {get_local_media-209} SELECT media_type, media_length, upload_name, created_ts, quarantined_by, url_cache, last_access_ts, safe_from_quarantine, user_id FROM local_media_repository WHERE media_id = ?
2024-05-30 08:03:06,770 - synapse.storage.SQL - 471 - DEBUG - GET-69 - [SQL values] {get_local_media-209} ['FUWUhOIoKJihHQRBdtBJPHIF']
2024-05-30 08:03:06,770 - synapse.storage.SQL - 492 - DEBUG - GET-69 - [SQL time] {get_local_media-209} 0.000043 sec
2024-05-30 08:03:06,770 - synapse.storage.txn - 862 - DEBUG - GET-69 - [TXN END] {get_local_media-209} 0.000311 sec
2024-05-30 08:03:06,770 - synapse.storage.txn - 758 - DEBUG - GET-70 - [TXN START] {get_local_media-20a}
2024-05-30 08:03:06,770 - synapse.storage.SQL - 466 - DEBUG - GET-70 - [SQL] {get_local_media-20a} SELECT media_type, media_length, upload_name, created_ts, quarantined_by, url_cache, last_access_ts, safe_from_quarantine, user_id FROM local_media_repository WHERE media_id = ?
2024-05-30 08:03:06,771 - synapse.storage.SQL - 471 - DEBUG - GET-70 - [SQL values] {get_local_media-20a} ['FUWUhOIoKJihHQRBdtBJPHIF']
2024-05-30 08:03:06,771 - synapse.storage.SQL - 492 - DEBUG - GET-70 - [SQL time] {get_local_media-20a} 0.000015 sec
2024-05-30 08:03:06,771 - synapse.storage.txn - 862 - DEBUG - GET-70 - [TXN END] {get_local_media-20a} 0.000223 sec
2024-05-30 08:03:06,771 - synapse.storage.txn - 758 - DEBUG - GET-69 - [TXN START] {get_local_media_thumbnails-20b}
2024-05-30 08:03:06,771 - synapse.storage.SQL - 466 - DEBUG - GET-69 - [SQL] {get_local_media_thumbnails-20b} SELECT thumbnail_width, thumbnail_height, thumbnail_method, thumbnail_type, thumbnail_length FROM local_media_repository_thumbnails WHERE media_id = ?
2024-05-30 08:03:06,771 - synapse.storage.SQL - 471 - DEBUG - GET-69 - [SQL values] {get_local_media_thumbnails-20b} ['FUWUhOIoKJihHQRBdtBJPHIF']
2024-05-30 08:03:06,771 - synapse.storage.SQL - 492 - DEBUG - GET-69 - [SQL time] {get_local_media_thumbnails-20b} 0.000019 sec
2024-05-30 08:03:06,771 - synapse.storage.txn - 862 - DEBUG - GET-69 - [TXN END] {get_local_media_thumbnails-20b} 0.000254 sec
2024-05-30 08:03:06,771 - synapse.storage.txn - 758 - DEBUG - GET-70 - [TXN START] {get_local_media_thumbnails-20c}
2024-05-30 08:03:06,772 - synapse.storage.SQL - 466 - DEBUG - GET-70 - [SQL] {get_local_media_thumbnails-20c} SELECT thumbnail_width, thumbnail_height, thumbnail_method, thumbnail_type, thumbnail_length FROM local_media_repository_thumbnails WHERE media_id = ?
2024-05-30 08:03:06,772 - synapse.storage.SQL - 471 - DEBUG - GET-70 - [SQL values] {get_local_media_thumbnails-20c} ['FUWUhOIoKJihHQRBdtBJPHIF']
2024-05-30 08:03:06,772 - synapse.storage.SQL - 492 - DEBUG - GET-70 - [SQL time] {get_local_media_thumbnails-20c} 0.000016 sec
2024-05-30 08:03:06,772 - synapse.storage.txn - 862 - DEBUG - GET-70 - [TXN END] {get_local_media_thumbnails-20c} 0.000253 sec
2024-05-30 08:03:06,772 - synapse.media.thumbnailer - 478 - DEBUG - GET-69 - _select_and_respond_with_thumbnail: media_id=FUWUhOIoKJihHQRBdtBJPHIF desired=14x14 (crop) thumbnail_infos=[ThumbnailInfo(width=32, height=32, method='crop', type='image/png', length=0), ThumbnailInfo(width=96, height=96, method='crop', type='image/png', length=6494), ThumbnailInfo(width=240, height=240, method='scale', type='image/png', length=19245), ThumbnailInfo(width=480, height=480, method='scale', type='image/png', length=15584)]
2024-05-30 08:03:06,772 - synapse.media.media_storage - 204 - DEBUG - GET-69 - responding with local file /data/media_store/local_thumbnails/FU/WU/hOIoKJihHQRBdtBJPHIF/32-32-image-png-crop
2024-05-30 08:03:06,772 - synapse.media._base - 292 - DEBUG - GET-69 - Responding to media request with responder <synapse.media.media_storage.FileResponder object at 0x7fe4f35d9250>
2024-05-30 08:03:06,772 - synapse.media.thumbnailer - 478 - DEBUG - GET-70 - _select_and_respond_with_thumbnail: media_id=FUWUhOIoKJihHQRBdtBJPHIF desired=30x30 (crop) thumbnail_infos=[ThumbnailInfo(width=32, height=32, method='crop', type='image/png', length=0), ThumbnailInfo(width=96, height=96, method='crop', type='image/png', length=6494), ThumbnailInfo(width=240, height=240, method='scale', type='image/png', length=19245), ThumbnailInfo(width=480, height=480, method='scale', type='image/png', length=15584)]
2024-05-30 08:03:06,773 - synapse.media.media_storage - 204 - DEBUG - GET-70 - responding with local file /data/media_store/local_thumbnails/FU/WU/hOIoKJihHQRBdtBJPHIF/32-32-image-png-crop
2024-05-30 08:03:06,773 - synapse.media._base - 292 - DEBUG - GET-70 - Responding to media request with responder <synapse.media.media_storage.FileResponder object at 0x7fe4f35da3d0>
2024-05-30 08:03:06,773 - synapse.access.http.8008 - 473 - INFO - GET-69 - ::ffff:172.17.0.1 - 8008 - {None} Processed request: 0.004sec/-0.000sec (0.001sec, 0.000sec) (0.001sec/0.001sec/2) 1655B 200 "GET /_matrix/media/v3/thumbnail/localhost/FUWUhOIoKJihHQRBdtBJPHIF?width=14&height=14&method=crop&allow_redirect=true HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/125.0.6422.26 Safari/537.36" [0 dbevts]
2024-05-30 08:03:06,773 - synapse.access.http.8008 - 473 - INFO - GET-70 - ::ffff:172.17.0.1 - 8008 - {None} Processed request: 0.004sec/-0.000sec (0.000sec, 0.000sec) (0.001sec/0.000sec/2) 1655B 200 "GET /_matrix/media/v3/thumbnail/localhost/FUWUhOIoKJihHQRBdtBJPHIF?width=30&height=30&method=crop&allow_redirect=true HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/125.0.6422.26 Safari/537.36" [0 dbevts]
2024-05-30 08:03:06,774 - synapse.access.http.8008 - 428 - DEBUG - GET-71 - ::ffff:172.17.0.1 - 8008 - Received request: GET /_matrix/media/v3/thumbnail/localhost/ChsaUEGRoyuziRBcrLyKtitA?width=14&height=14&method=crop&allow_redirect=true
2024-05-30 08:03:06,775 - synapse.storage.txn - 758 - DEBUG - GET-71 - [TXN START] {get_local_media-20d}
2024-05-30 08:03:06,775 - synapse.storage.SQL - 466 - DEBUG - GET-71 - [SQL] {get_local_media-20d} SELECT media_type, media_length, upload_name, created_ts, quarantined_by, url_cache, last_access_ts, safe_from_quarantine, user_id FROM local_media_repository WHERE media_id = ?
2024-05-30 08:03:06,775 - synapse.storage.SQL - 471 - DEBUG - GET-71 - [SQL values] {get_local_media-20d} ['ChsaUEGRoyuziRBcrLyKtitA']
2024-05-30 08:03:06,775 - synapse.storage.SQL - 492 - DEBUG - GET-71 - [SQL time] {get_local_media-20d} 0.000017 sec
2024-05-30 08:03:06,775 - synapse.storage.txn - 862 - DEBUG - GET-71 - [TXN END] {get_local_media-20d} 0.000250 sec
2024-05-30 08:03:06,775 - synapse.storage.txn - 758 - DEBUG - GET-71 - [TXN START] {get_local_media_thumbnails-20e}
2024-05-30 08:03:06,775 - synapse.storage.SQL - 466 - DEBUG - GET-71 - [SQL] {get_local_media_thumbnails-20e} SELECT thumbnail_width, thumbnail_height, thumbnail_method, thumbnail_type, thumbnail_length FROM local_media_repository_thumbnails WHERE media_id = ?
2024-05-30 08:03:06,775 - synapse.storage.SQL - 471 - DEBUG - GET-71 - [SQL values] {get_local_media_thumbnails-20e} ['ChsaUEGRoyuziRBcrLyKtitA']
2024-05-30 08:03:06,775 - synapse.storage.SQL - 492 - DEBUG - GET-71 - [SQL time] {get_local_media_thumbnails-20e} 0.000016 sec
2024-05-30 08:03:06,775 - synapse.storage.txn - 862 - DEBUG - GET-71 - [TXN END] {get_local_media_thumbnails-20e} 0.000269 sec
2024-05-30 08:03:06,776 - synapse.media.thumbnailer - 478 - DEBUG - GET-71 - _select_and_respond_with_thumbnail: media_id=ChsaUEGRoyuziRBcrLyKtitA desired=14x14 (crop) thumbnail_infos=[ThumbnailInfo(width=32, height=32, method='crop', type='image/png', length=0), ThumbnailInfo(width=96, height=96, method='crop', type='image/png', length=7937), ThumbnailInfo(width=240, height=240, method='scale', type='image/png', length=21249), ThumbnailInfo(width=480, height=480, method='scale', type='image/png', length=45062), ThumbnailInfo(width=512, height=512, method='scale', type='image/png', length=18431)]
2024-05-30 08:03:06,776 - synapse.media.media_storage - 204 - DEBUG - GET-71 - responding with local file /data/media_store/local_thumbnails/Ch/sa/UEGRoyuziRBcrLyKtitA/32-32-image-png-crop
2024-05-30 08:03:06,776 - synapse.media._base - 292 - DEBUG - GET-71 - Responding to media request with responder <synapse.media.media_storage.FileResponder object at 0x7fe4f35ac650>
2024-05-30 08:03:06,776 - synapse.access.http.8008 - 473 - INFO - GET-71 - ::ffff:172.17.0.1 - 8008 - {None} Processed request: 0.002sec/-0.000sec (0.003sec, 0.000sec) (0.000sec/0.001sec/2) 2101B 200 "GET /_matrix/media/v3/thumbnail/localhost/ChsaUEGRoyuziRBcrLyKtitA?width=14&height=14&method=crop&allow_redirect=true HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/125.0.6422.26 Safari/537.36" [0 dbevts]
2024-05-30 08:03:06,780 - synapse.access.http.8008 - 428 - DEBUG - GET-72 - ::ffff:172.17.0.1 - 8008 - Received request: GET /_matrix/media/v3/thumbnail/localhost/ChsaUEGRoyuziRBcrLyKtitA?width=30&height=30&method=crop&allow_redirect=true
2024-05-30 08:03:06,780 - synapse.storage.txn - 758 - DEBUG - GET-72 - [TXN START] {get_local_media-20f}
2024-05-30 08:03:06,781 - synapse.storage.SQL - 466 - DEBUG - GET-72 - [SQL] {get_local_media-20f} SELECT media_type, media_length, upload_name, created_ts, quarantined_by, url_cache, last_access_ts, safe_from_quarantine, user_id FROM local_media_repository WHERE media_id = ?
2024-05-30 08:03:06,781 - synapse.storage.SQL - 471 - DEBUG - GET-72 - [SQL values] {get_local_media-20f} ['ChsaUEGRoyuziRBcrLyKtitA']
2024-05-30 08:03:06,781 - synapse.storage.SQL - 492 - DEBUG - GET-72 - [SQL time] {get_local_media-20f} 0.000025 sec
2024-05-30 08:03:06,781 - synapse.storage.txn - 862 - DEBUG - GET-72 - [TXN END] {get_local_media-20f} 0.000291 sec
2024-05-30 08:03:06,781 - synapse.storage.txn - 758 - DEBUG - GET-72 - [TXN START] {get_local_media_thumbnails-210}
2024-05-30 08:03:06,781 - synapse.storage.SQL - 466 - DEBUG - GET-72 - [SQL] {get_local_media_thumbnails-210} SELECT thumbnail_width, thumbnail_height, thumbnail_method, thumbnail_type, thumbnail_length FROM local_media_repository_thumbnails WHERE media_id = ?
2024-05-30 08:03:06,781 - synapse.storage.SQL - 471 - DEBUG - GET-72 - [SQL values] {get_local_media_thumbnails-210} ['ChsaUEGRoyuziRBcrLyKtitA']
2024-05-30 08:03:06,781 - synapse.storage.SQL - 492 - DEBUG - GET-72 - [SQL time] {get_local_media_thumbnails-210} 0.000017 sec
2024-05-30 08:03:06,781 - synapse.storage.txn - 862 - DEBUG - GET-72 - [TXN END] {get_local_media_thumbnails-210} 0.000267 sec
2024-05-30 08:03:06,782 - synapse.media.thumbnailer - 478 - DEBUG - GET-72 - _select_and_respond_with_thumbnail: media_id=ChsaUEGRoyuziRBcrLyKtitA desired=30x30 (crop) thumbnail_infos=[ThumbnailInfo(width=32, height=32, method='crop', type='image/png', length=0), ThumbnailInfo(width=96, height=96, method='crop', type='image/png', length=7937), ThumbnailInfo(width=240, height=240, method='scale', type='image/png', length=21249), ThumbnailInfo(width=480, height=480, method='scale', type='image/png', length=45062), ThumbnailInfo(width=512, height=512, method='scale', type='image/png', length=18431)]
2024-05-30 08:03:06,782 - synapse.media.media_storage - 204 - DEBUG - GET-72 - responding with local file /data/media_store/local_thumbnails/Ch/sa/UEGRoyuziRBcrLyKtitA/32-32-image-png-crop
2024-05-30 08:03:06,782 - synapse.media._base - 292 - DEBUG - GET-72 - Responding to media request with responder <synapse.media.media_storage.FileResponder object at 0x7fe4f35dd250>
2024-05-30 08:03:06,782 - synapse.access.http.8008 - 473 - INFO - GET-72 - ::ffff:172.17.0.1 - 8008 - {None} Processed request: 0.002sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.001sec/2) 2101B 200 "GET /_matrix/media/v3/thumbnail/localhost/ChsaUEGRoyuziRBcrLyKtitA?width=30&height=30&method=crop&allow_redirect=true HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/125.0.6422.26 Safari/537.36" [0 dbevts]

### Anything else that would be useful to know?

_No response_

[t3chguy]

Fixed by #17246