Picard "SSL handshake failed"

alex_s7 · November 14, 2019, 5:24pm

Hello,

I am using Picard for several years now, since some days I can’t load any albums in it. The error log show SSL-related messages:

E: 18:17:17,792 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/oauth2/token: SSL handshake failed (QT code 6, HTTP code 0)

E: 18:17:17,792 /usr/lib64/python3.7/site-packages/picard/oauth.on_refresh_access_token_finished:181: OAuth: access_token refresh failed: b''

E: 18:17:17,832 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://picard.musicbrainz.org:443/api/v2/releases: SSL handshake failed (QT code 6, HTTP code 0)

E: 18:17:17,832 /usr/lib64/python3.7/site-packages/picard/util/checkupdate._releases_json_loaded:98: Error loading Picard releases list: SSL handshake failed

E: 18:17:17,870 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/ws/2/collection: SSL handshake failed (QT code 6, HTTP code 0)

E: 18:17:17,870 /usr/lib64/python3.7/site-packages/picard/ui/mainwindow.set_statusbar_message:340: Error loading collections: SSL handshake failed

E: 18:17:27,231 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/oauth2/token: SSL handshake failed (QT code 6, HTTP code 0)

E: 18:17:27,231 /usr/lib64/python3.7/site-packages/picard/oauth.on_refresh_access_token_finished:181: OAuth: access_token refresh failed: b''

E: 18:17:27,321 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/ws/2/release/f9f83ecb-842f-4120-ad57-e858396a62aa?inc=release-groups+media+discids+recordings+artist-credits+artists+aliases+labels+isrcs+collections+user-collections+artist-rels+release-rels+url-rels+recording-rels+work-rels+recording-level-rels+work-level-rels: SSL handshake failed (QT code 6, HTTP code 0)

E: 18:17:27,321 /usr/lib64/python3.7/site-packages/picard/album.error_append:259: SSL handshake failed

Tried to remove and re-install Picard - no changes.

Running on Fedora Linux 30, picard-2.2.2-1, openssl 1.1.1d.

Tried on Ubuntu in VirtualBox - it works, so the connection is OK.

What should I check?

outsidecontext · November 14, 2019, 9:43pm

It definitely works here, too. Certificates on the servers look good. Has anything changed on your system? Any updates, especially to openssl or Qt? How have you installed Picard, from a package or manually?

For some details please run:

picard --long-version

If SSL support is enabled it should show up here. Also check whether your local openssl in general can verify the MB server certificates:

openssl s_client -connect musicbrainz.org:443

The above command will output a lot of details, but should contain something like:

SSL handshake has read 5114 bytes and written 450 bytes
Verification: OK

Also note that this command will not exit, that’s normal. Terminate it with Ctrl+C.

Finally please provide a full debug log by starting Picard with:

picard --debug

This probably gives some more details.

alex_s7 · November 15, 2019, 6:57pm

Has anything changed on your system? Any updates, especially to openssl or Qt?

I have used Picard last time 3-4 weeks ago. Fedora Linux is a very active distribution, every week there are hundreds of changes. Openssl was not changed since I have used Picard the last time, but Qt and Python were changed several times.

How have you installed Picard, from a package or manually?

RPM package from standard Fedora repository.

picard --long-version

Picard 2.2.2, Python 3.7.5, PyQt 5.13.1, Qt 5.12.5, Mutagen 1.42.0, Discid discid 1.1.0 (compat layer from python-libdiscid 0.4.1), libdiscid 0.6.2, astrcmp C, SSL OpenSSL 1.1.1d FIPS 10 Sep 201977

openssl s_client -connect musicbrainz.org:443

Works perfectly well:

SSL handshake has read 5114 bytes and written 453 bytes
Verification: OK

picard --debug

I have removed OAuth client ID and secret from the output below, otherwise it is unchanged:

D: 19:39:17,924 /usr/lib64/python3.7/site-packages/picard/tagger.__init__:209: Starting Picard from '/usr/lib64/python3.7/site-packages/picard/tagger.py'
D: 19:39:17,924 /usr/lib64/python3.7/site-packages/picard/tagger.__init__:211: Platform: Linux-5.3.8-200.fc30.x86_64-x86_64-with-fedora-30-Thirty CPython 3.7.5
D: 19:39:17,924 /usr/lib64/python3.7/site-packages/picard/tagger.__init__:212: Versions: Picard 2.2.2, Python 3.7.5, PyQt 5.13.1, Qt 5.12.5, Mutagen 1.42.0, Discid discid 1.1.0 (compat layer from python-libdiscid 0.4.1), libdiscid 0.6.2, astrcmp C, SSL OpenSSL 1.1.1d FIPS  10 Sep 2019
D: 19:39:17,924 /usr/lib64/python3.7/site-packages/picard/tagger.__init__:213: Configuration file path: '/home/username/.config/MusicBrainz/Picard.ini'
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/tagger.__init__:215: User directory: '/home/username/.config/MusicBrainz/Picard'
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:76: Using locale 'LC_CTYPE=en_GB.UTF-8;LC_NUMERIC=en_GB.UTF-8;LC_TIME=de_DE.UTF-8;LC_COLLATE=en_GB.UTF-8;LC_MONETARY=de_DE.UTF-8;LC_MESSAGES=en_GB.UTF-8;LC_PAPER=en_GB.UTF-8;LC_NAME=en_GB.UTF-8;LC_ADDRESS=en_GB.UTF-8;LC_TELEPHONE=en_GB.UTF-8;LC_MEASUREMENT=de_DE.UTF-8;LC_IDENTIFICATION=en_GB.UTF-8'
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:78: Loading gettext translation, localedir='/usr/share/locale'
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:89: [Errno 2] No translation file found for domain: 'picard'
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:108: _ = <function setup_gettext.<locals>.<lambda> at 0x7f8d54d9d560>
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:109: N_ = <function <lambda> at 0x7f8d5569d050>
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:110: ngettext = <function setup_gettext.<locals>._ngettext at 0x7f8d54d9d5f0>
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:111: gettext_countries = <function setup_gettext.<locals>._gettext_countries at 0x7f8d54d9d710>
D: 19:39:17,925 /usr/lib64/python3.7/site-packages/picard/i18n.setup_gettext:112: gettext_attributes = <function setup_gettext.<locals>._gettext_attributes at 0x7f8d54d9d7a0>
D: 19:39:17,936 /usr/lib64/python3.7/site-packages/picard/webservice/__init__.set_cache:297: NetworkDiskCache dir: '/home/username/.cache/MusicBrainz/Picard/picard/' size: 16909302 / 104857600
D: 19:39:17,937 /usr/lib64/python3.7/site-packages/picard/pluginmanager.load_plugins_from_directory:212: Looking for plugins in directory '/usr/lib64/python3.7/site-packages/picard/plugins', 0 names found
D: 19:39:17,937 /usr/lib64/python3.7/site-packages/picard/pluginmanager.load_plugins_from_directory:212: Looking for plugins in directory '/home/username/.config/MusicBrainz/Picard/plugins', 0 names found
D: 19:39:17,937 /usr/lib64/python3.7/site-packages/picard/ui/playertoolbar.__init__:83: Internal player: QtMultimedia available, initializing QMediaPlayer
D: 19:39:17,952 /usr/lib64/python3.7/site-packages/picard/ui/playertoolbar.__init__:90: Internal player: available, QMediaPlayer set up
Fontconfig warning: ignoring LC_CTYPE=en_GB.UTF-8;LC_NUMERIC=en_GB.UTF-8;LC_TIME=de_DE.UTF-8;LC_COLLATE=en_GB.UTF-8;LC_MONETARY=de_DE.UTF-8;LC_MESSAGES=en_GB.UTF-8;LC_PAPER=en_GB.UTF-8;LC_NAME=en_GB.UTF-8;LC_ADDRESS=en_GB.UTF-8;LC_TELEPHONE=en_GB.UTF-8;LC_MEASUREMENT=de_DE.UTF-8;LC_IDENTIFICATION=en_GB.UTF-8: not a valid region tag
D: 19:39:18,000 /usr/lib64/python3.7/site-packages/picard/tagger.main:913: Looking for Qt locale C in /usr/share/qt5/translations
D: 19:39:18,000 /usr/lib64/python3.7/site-packages/picard/tagger.main:917: Qt locale C not available
D: 19:39:18,000 /usr/lib64/python3.7/site-packages/picard/browser/browser.start:69: Starting the browser integration (127.0.0.1:8000)
D: 19:39:18,020 /usr/lib64/python3.7/site-packages/picard/ui/mainwindow.auto_update_check:1195: Initiating start-up check for program updates.  Today: 2019-11-15, Last check: 2019-11-05 (Check interval: 7 days), Update level: 0 (stable)
D: 19:39:18,021 /usr/lib64/python3.7/site-packages/picard/util/checkupdate._query_available_updates:85: Getting Picard release information from picard.musicbrainz.org
D: 19:39:18,046 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.get_delay_to_next_request:110: ('musicbrainz.org', 80): First request
D: 19:39:18,046 /usr/lib64/python3.7/site-packages/picard/oauth.refresh_access_token:162: OAuth: refreshing access_token with a refresh_token H-tsIyTnx02VIml1W9pe-Q
D: 19:39:18,046 /usr/lib64/python3.7/site-packages/picard/webservice/__init__.post:461: POST-DATA 'grant_type=refresh_token&refresh_token=H-tsIyTnx02VIml1W9pe-Q&client_id=**hidden**&client_secret=**hidden**'
D: 19:39:18,046 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.get_delay_to_next_request:110: ('picard.musicbrainz.org', 443): First request
D: 19:39:18,046 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.increment_requests:135: ('picard.musicbrainz.org', 443): Incrementing requests to: 1
D: 19:39:18,166 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.decrement_requests:143: ('picard.musicbrainz.org', 443): Decrementing requests to: 0
E: 19:39:18,166 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://picard.musicbrainz.org:443/api/v2/releases: SSL handshake failed (QT code 6, HTTP code 0)
E: 19:39:18,166 /usr/lib64/python3.7/site-packages/picard/util/checkupdate._releases_json_loaded:98: Error loading Picard releases list: SSL handshake failed
D: 19:39:18,167 /usr/lib64/python3.7/site-packages/picard/ui/mainwindow.update_last_check_date:1212: The update check was unsuccessful. The last update date will not be changed.
D: 19:39:18,167 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol._out_of_backoff:226: ('picard.musicbrainz.org', 443): oobackoff; delay: 1000ms -> 1000ms; slow start; window size 1.000 -> 2.000
D: 19:39:18,167 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.get_delay_to_next_request:119: ('musicbrainz.org', 80): Last request was 120 ms ago, waiting 880 ms before starting another one
D: 19:39:19,048 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.get_delay_to_next_request:115: ('musicbrainz.org', 80): Last request was 1002 ms ago, starting another one
D: 19:39:19,049 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.increment_requests:135: ('musicbrainz.org', 80): Incrementing requests to: 1
D: 19:39:19,133 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.decrement_requests:143: ('musicbrainz.org', 80): Decrementing requests to: 0
E: 19:39:19,134 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/oauth2/token: SSL handshake failed (QT code 6, HTTP code 0)
E: 19:39:19,134 /usr/lib64/python3.7/site-packages/picard/oauth.on_refresh_access_token_finished:181: OAuth: access_token refresh failed: b''
D: 19:39:19,135 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.increment_requests:135: ('musicbrainz.org', 80): Incrementing requests to: 1
D: 19:39:19,136 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol._out_of_backoff:226: ('musicbrainz.org', 80): oobackoff; delay: 1000ms -> 1000ms; slow start; window size 1.000 -> 2.000
D: 19:39:19,222 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.decrement_requests:143: ('musicbrainz.org', 80): Decrementing requests to: 0
E: 19:39:19,222 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/ws/2/collection: SSL handshake failed (QT code 6, HTTP code 0)
E: 19:39:19,223 /usr/lib64/python3.7/site-packages/picard/ui/mainwindow.set_statusbar_message:340: Error loading collections: SSL handshake failed
D: 19:39:19,223 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol._out_of_backoff:226: ('musicbrainz.org', 80): oobackoff; delay: 1000ms -> 1000ms; slow start; window size 2.000 -> 3.000
D: 19:39:21,601 /usr/lib64/python3.7/site-packages/picard/ui/itemviews.dropMimeData:568: Drop target = <Cluster 'Unclustered Files'>
D: 19:39:21,602 /usr/lib64/python3.7/site-packages/picard/ui/itemviews.drop_urls:529: Dropped the URL: 'file:///mount/audio/Boccherini, Luigi/Boccherini Edition/CD 01 - Symphonies G. 515, 517 & 518/01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'
D: 19:39:21,605 /usr/lib64/python3.7/site-packages/picard/tagger.add_files:476: Adding files [<FLACFile '01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'>]
D: 19:39:21,606 /usr/lib64/python3.7/site-packages/picard/file._move:524: Moving <FLACFile '01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'> from None to <Cluster 'Unclustered Files'>
D: 19:39:21,608 /usr/lib64/python3.7/site-packages/picard/formats/vorbis._load:87: Loading file '/mount/audio/Boccherini, Luigi/Boccherini Edition/CD 01 - Symphonies G. 515, 517 & 518/01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'
D: 19:39:21,615 /usr/lib64/python3.7/site-packages/picard/coverart/image.__init__:68: Saving image data 670c0532902d750ba58480c16e072b4b to '/tmp/picard_tdjlr2o.jpg'
D: 19:39:21,617 /usr/lib64/python3.7/site-packages/picard/file.update:572: Updating file <FLACFile '01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'>
D: 19:39:21,618 /usr/lib64/python3.7/site-packages/picard/tagger._file_loaded:414: <FLACFile '01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'> has release (f9f83ecb-842f-4120-ad57-e858396a62aa) and recording (4ff01003-1456-4b83-9401-c0cd8a819e5c) MBIDs, moving to track...
D: 19:39:21,619 /usr/lib64/python3.7/site-packages/picard/ui/mainwindow.set_statusbar_message:340: Loading album f9f83ecb-842f-4120-ad57-e858396a62aa ...
D: 19:39:21,621 /usr/lib64/python3.7/site-packages/picard/file.move:512: Moving <FLACFile '01 - Symphony no. 13 in C major, op. 37 no. 1, G. 515 - I. Allegro con moto.flac'> from <Cluster 'Unclustered Files'> to <Cluster f9f83ecb-842f-4120-ad57-e858396a62aa '/Unmatched Files'>
D: 19:39:21,626 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.get_delay_to_next_request:115: ('musicbrainz.org', 80): Last request was 2490 ms ago, starting another one
D: 19:39:21,627 /usr/lib64/python3.7/site-packages/picard/oauth.refresh_access_token:162: OAuth: refreshing access_token with a refresh_token H-tsIyTnx02VIml1W9pe-Q
D: 19:39:21,627 /usr/lib64/python3.7/site-packages/picard/webservice/__init__.post:461: POST-DATA 'grant_type=refresh_token&refresh_token=H-tsIyTnx02VIml1W9pe-Q&client_id=**hidden**&client_secret=**hidden**'
D: 19:39:22,649 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.get_delay_to_next_request:115: ('musicbrainz.org', 80): Last request was 3513 ms ago, starting another one
D: 19:39:22,649 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.increment_requests:135: ('musicbrainz.org', 80): Incrementing requests to: 1
D: 19:39:22,734 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.decrement_requests:143: ('musicbrainz.org', 80): Decrementing requests to: 0
E: 19:39:22,735 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/oauth2/token: SSL handshake failed (QT code 6, HTTP code 0)
E: 19:39:22,735 /usr/lib64/python3.7/site-packages/picard/oauth.on_refresh_access_token_finished:181: OAuth: access_token refresh failed: b''
D: 19:39:22,735 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.increment_requests:135: ('musicbrainz.org', 80): Incrementing requests to: 1
D: 19:39:22,736 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol._out_of_backoff:226: ('musicbrainz.org', 80): oobackoff; delay: 1000ms -> 1000ms; slow start; window size 3.000 -> 4.000
D: 19:39:22,815 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol.decrement_requests:143: ('musicbrainz.org', 80): Decrementing requests to: 0
E: 19:39:22,815 /usr/lib64/python3.7/site-packages/picard/webservice/__init__._handle_reply:387: Network request error for https://musicbrainz.org:443/ws/2/release/f9f83ecb-842f-4120-ad57-e858396a62aa?inc=release-groups+media+discids+recordings+artist-credits+artists+aliases+labels+isrcs+collections+user-collections+artist-rels+release-rels+url-rels+recording-rels+work-rels+recording-level-rels+work-level-rels: SSL handshake failed (QT code 6, HTTP code 0)
E: 19:39:22,815 /usr/lib64/python3.7/site-packages/picard/album.error_append:259: SSL handshake failed
D: 19:39:22,817 /usr/lib64/python3.7/site-packages/picard/webservice/ratecontrol._out_of_backoff:226: ('musicbrainz.org', 80): oobackoff; delay: 1000ms -> 1000ms; slow start; window size 4.000 -> 5.000
D: 19:39:24,403 /usr/lib64/python3.7/site-packages/picard/tagger.exit:355: Picard stopping
D: 19:39:24,404 /usr/lib64/python3.7/site-packages/picard/browser/browser.stop:76: Stopping the browser integration

outsidecontext · November 15, 2019, 9:54pm

I have no good idea right now, might be a QT issue. Worth a try could be to clear Qt’s HTTP cache. Out of my head I don’t know where this is located, but likely somewhere in ~/.cache. If needed I can check that later this weekend.

alex_s7 · November 16, 2019, 3:04pm

Tried:

Removed from ~/.cache all directories starting with “qt”, as well as “MusicBrainz”. Does not help, the same error.
Created a new user, logged in as that user, started Picard. Does not help, the same error.
Installed a fresh version of Fedora 30 in VirtualBox (as opposed to a native installation I am normally using), performed full update, installed Picard - works correctly, so in fresh “plain vanilla” Fedora 30 installation there is no problem.
Attempted to roll back all updates to mid-October when Picard still worked - unfortunately impossible since old RPMs are already purged from the local cache and are not available on standard Fedora repository.

Since the error happens with a new user as well, it is definitely not caused by something in user’s directory, but by some error on the system level.

I suppose that’s it, if I want to use Picard, I have to re-install the OS.

Thank you for your time.