search

jellyfin / mopidy-jellyfin

Jellyfin Extension for Mopidy
https://jellyfin.org
Apache License 2.0
93 stars 16 forks source link

mopidy-jellyfin suddenly not working anymore #99

Closed sseneca closed 3 years ago

sseneca commented 3 years ago

I'm using mopidy-mpd in conjunction with mopidy-jellyfin. I can't figure out why, but this set up randomly broke a few days ago. I'm confused because there were no package upgrades for Mopidy, mopidy-mpd, mopidy-jellyfin, or my Jellyfin server. But it doesn't work any more.

Specifically, when I open ncmpcpp, the Album Artists is now blank, and if I try to view just Albums I get MPD: "lastallinfo" has been disabled in the server.

If this is more likely a fault in mopidy-mpd please let me know and I'll close this issue here and open an issue there instead.

mcarlton00 commented 3 years ago

What version of mopidy-mpd do you have installed? I'm lagging behind on updates right now, but I'm on 3.1.0-2 and don't see any issues with it.

Does browsing work (the 2 pane), or is it just using the library feature that's messed up (the 4 pane)?

listall and listallinfo are blacklisted by mopidy and have never worked, due to it being dependent on remote services and that it's likely too slow to be effective. It's possible something changed in a recent release and something got shuffled, though.

sseneca commented 3 years ago

I have version 3.1.0 of mopidy-mpd installed, which is the latest version afaik.

No, browsing does not work. I would have thought it could be something in an update, but like I said, none of Mopidy/mopidy-mpd/mopidy-jellyfin got updated recently. The latest upgrade was Jellyfin itself to 10.7, but that was a while ago and it was working with 10.7 for some time.

Not sure how to get a hold of logs or something that could be helpful?

mcarlton00 commented 3 years ago

How are you launching mopidy? The plugin logs to the same output as mopidy itself. If you're running mopidy in a terminal, you should see it. If you're using systemd, then journalctl -u mopidy should do it, iirc.

sseneca commented 3 years ago

Yeah, I use systemd, so here are the logs from journalctl:

Mar 30 08:58:54 sseneca-pc systemd[1]: Started Mopidy music server.
Mar 30 08:58:55 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:55,133 [3454:MainThread] mopidy.__main__
Mar 30 08:58:55 sseneca-pc mopidy[3454]:   Enabled extensions: softwaremixer, jellyfin, stream, http, m3u, mpd, file
Mar 30 08:58:55 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:55,134 [3454:MainThread] mopidy.__main__
Mar 30 08:58:55 sseneca-pc mopidy[3454]:   Disabled extensions: none
Mar 30 08:58:55 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:55,494 [3454:MainThread] mopidy.commands
Mar 30 08:58:55 sseneca-pc mopidy[3454]:   Starting Mopidy mixer: SoftwareMixer
Mar 30 08:58:55 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:55,495 [3454:MainThread] mopidy.commands
Mar 30 08:58:55 sseneca-pc mopidy[3454]:   Starting Mopidy audio
Mar 30 08:58:55 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:55,496 [3454:MainThread] mopidy.commands
Mar 30 08:58:55 sseneca-pc mopidy[3454]:   Starting Mopidy backends: FileBackend, M3UBackend, StreamBackend, JellyfinBackend
Mar 30 08:58:55 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:55,513 [3454:Audio-2] mopidy.audio.actor
Mar 30 08:58:55 sseneca-pc mopidy[3454]:   Audio output set to "tee name=t ! queue ! pulsesink server = 127.0.0.1 t. ! queue ! udpsink host=127.0.0.1 port=5555"
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,257 [3454:MainThread] mopidy_jellyfin.http
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Jellyfin connection on try 0 with problem: Expecting value: line 1 column 1 (char 0)
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,270 [3454:MainThread] mopidy_jellyfin.http
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Jellyfin connection on try 1 with problem: Expecting value: line 1 column 1 (char 0)
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,280 [3454:MainThread] mopidy_jellyfin.http
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Jellyfin connection on try 2 with problem: Expecting value: line 1 column 1 (char 0)
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,290 [3454:MainThread] mopidy_jellyfin.http
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Jellyfin connection on try 3 with problem: Expecting value: line 1 column 1 (char 0)
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,305 [3454:MainThread] mopidy_jellyfin.http
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Jellyfin connection on try 4 with problem: Expecting value: line 1 column 1 (char 0)
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,316 [3454:MainThread] mopidy_jellyfin.http
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Jellyfin connection on try 5 with problem: Expecting value: line 1 column 1 (char 0)
Mar 30 08:58:56 sseneca-pc mopidy[3454]: ERROR    2021-03-30 08:58:56,316 [3454:MainThread] mopidy.commands
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Got un-handled exception from JellyfinBackend
Mar 30 08:58:56 sseneca-pc mopidy[3454]: Traceback (most recent call last):
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy/commands.py", line 241, in _actor_error_handling
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     yield
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy/commands.py", line 405, in start_backends
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     backend = backend_class.start(
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/pykka/_actor.py", line 91, in start
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     obj = cls(*args, **kwargs)
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/backend.py", line 26, in __init__
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     self.remote = JellyfinHandler(config)
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/remote.py", line 70, in __init__
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     self._login()
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/remote.py", line 84, in _login
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     auth_details = self.http.post(
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/http.py", line 83, in post
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     raise Exception('Cant connect to Jellyfin API')
Mar 30 08:58:56 sseneca-pc mopidy[3454]: Exception: Cant connect to Jellyfin API
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,321 [3454:MainThread] mopidy.commands
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Starting Mopidy core
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,336 [3454:MainThread] mopidy.commands
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Starting Mopidy frontends: HttpFrontend, MpdFrontend, EventMonitorFrontend
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,338 [3454:HttpFrontend-8] mopidy.http.actor
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   HTTP server running at [::ffff:127.0.0.1]:6680
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,339 [3454:MainThread] mopidy_mpd.actor
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   MPD server running at [::]:6600
Mar 30 08:58:56 sseneca-pc mopidy[3454]: ERROR    2021-03-30 08:58:56,347 [3454:MainThread] mopidy.commands
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Got un-handled exception from EventMonitorFrontend
Mar 30 08:58:56 sseneca-pc mopidy[3454]: Traceback (most recent call last):
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy/commands.py", line 241, in _actor_error_handling
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     yield
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy/commands.py", line 438, in start_frontends
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     frontend_class.start(config=config, core=core)
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/pykka/_actor.py", line 91, in start
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     obj = cls(*args, **kwargs)
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/frontend.py", line 23, in __init__
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     self.token = self._read_token(config)
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/frontend.py", line 233, in _read_token
Mar 30 08:58:56 sseneca-pc mopidy[3454]:     raise Exception('No authentication token found')
Mar 30 08:58:56 sseneca-pc mopidy[3454]: Exception: No authentication token found
Mar 30 08:58:56 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:56,350 [3454:MainThread] mopidy.commands
Mar 30 08:58:56 sseneca-pc mopidy[3454]:   Starting GLib mainloop
Mar 30 08:58:57 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:57,931 [3454:MpdSession-10] mopidy_mpd.session
Mar 30 08:58:57 sseneca-pc mopidy[3454]:   New MPD connection from [::1]:40804
Mar 30 08:58:57 sseneca-pc mopidy[3454]: INFO     2021-03-30 08:58:57,944 [3454:MpdSession-11] mopidy_mpd.session
Mar 30 08:58:57 sseneca-pc mopidy[3454]:   New MPD connection from [::1]:40806

Not really sure about the authentication token error, or why it can't connect to the Jellyfin API. All I'll say is that I use other clients like jellyfin-mpv-shim and that connects to my Jellyfin instance fine

mcarlton00 commented 3 years ago

The first issue is what's stopping it from working. For some reason whatever URL you have entered isn't working, which then leads to authentication failing.

Try doing this to get more noisy logs, it might have a more relevant detail in them.

$ sudo systemctl stop mopidy
$ sudo mopidy --config /etc/mopidy/mopidy.conf  -v

This will run mopidy in the foreground, using the config file at /etc/mopidy/mopidy.conf (adjust this if needed), and the -v is more verbose logging.

sseneca commented 3 years ago

As far as I can tell, this hasn't revealed anything that wasn't in the previous log. The interesting part follows:

INFO     2021-03-31 16:24:46,699 [78432:Audio-2] mopidy.audio.actor
  Audio output set to "tee name=t ! queue ! pulsesink server = 127.0.0.1 t. ! queue ! udpsink host=127.0.0.1 port=5555"
INFO     2021-03-31 16:24:46,716 [78432:MainThread] mopidy_jellyfin.http
  Jellyfin connection on try 0 with problem: Expecting value: line 1 column 1 (char 0)
INFO     2021-03-31 16:24:46,722 [78432:MainThread] mopidy_jellyfin.http
  Jellyfin connection on try 1 with problem: Expecting value: line 1 column 1 (char 0)
INFO     2021-03-31 16:24:46,729 [78432:MainThread] mopidy_jellyfin.http
  Jellyfin connection on try 2 with problem: Expecting value: line 1 column 1 (char 0)
INFO     2021-03-31 16:24:46,735 [78432:MainThread] mopidy_jellyfin.http
  Jellyfin connection on try 3 with problem: Expecting value: line 1 column 1 (char 0)
INFO     2021-03-31 16:24:46,741 [78432:MainThread] mopidy_jellyfin.http
  Jellyfin connection on try 4 with problem: Expecting value: line 1 column 1 (char 0)
INFO     2021-03-31 16:24:46,747 [78432:MainThread] mopidy_jellyfin.http
  Jellyfin connection on try 5 with problem: Expecting value: line 1 column 1 (char 0)
ERROR    2021-03-31 16:24:46,748 [78432:MainThread] mopidy.commands
  Got un-handled exception from JellyfinBackend
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/mopidy/commands.py", line 241, in _actor_error_handling
    yield
  File "/usr/lib/python3.9/site-packages/mopidy/commands.py", line 405, in start_backends
    backend = backend_class.start(
  File "/usr/lib/python3.9/site-packages/pykka/_actor.py", line 91, in start
    obj = cls(*args, **kwargs)
  File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/backend.py", line 26, in __init__
    self.remote = JellyfinHandler(config)
  File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/remote.py", line 70, in __init__
    self._login()
  File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/remote.py", line 84, in _login
    auth_details = self.http.post(
  File "/usr/lib/python3.9/site-packages/mopidy_jellyfin/http.py", line 83, in post
    raise Exception('Cant connect to Jellyfin API')
Exception: Cant connect to Jellyfin API

In case Expecting value: line 1 column 1 (char 0) is anything to do with the config, this is what mine looks like:

[audio]
output = tee name=t ! queue ! pulsesink server = 127.0.0.1 t. ! queue ! udpsink host=127.0.0.1 port=5555

[core]
cache_dir = /var/cache/mopidy
config_dir = /etc/mopidy
data_dir = /var/lib/mopidy

[logging]
config_file = /etc/mopidy/logging.conf
debug_file = /var/log/mopidy/mopidy-debug.log

[local]
data_dir = /var/lib/mopidy/local
media_dir = /var/lib/mopidy/media

[m3u]
playlists_dir = /var/lib/mopidy/playlists

[mpd]
enabled = true
hostname = ::
password = redacted

[jellyfin]
enabled = true
hostname = https://jellyfin.redacted
username = sseneca
password = redacted
mcarlton00 commented 3 years ago

Hmmm, something isn't making sense here. The error is that it's expecting a json response from the server when trying to authenticate and isn't getting one. Let's try a different route and go directly to python and replicate what the code is doing.

try $ python3 and then enter this

import requests

r = requests.get('https://jellyfin.redacted/system/info/public')
print(r.json())
print(f'url: {r.url}')

Verify that the URL it prints matches what's in your config file (minus the /system/info/public).

It might also be worth checking your server logs to see if it's catching any errors there.

If that all looks correct, you can modify this script with your server and login information and verify if it's working there. https://gist.github.com/mcarlton00/f7bd7218828ed465ce0f309cebf9a247

sseneca commented 3 years ago

Issue appears to be fixed (for now).

Using requests manually from the command line worked fine.

I looked at the server logs, and a massive trace was being outputted each time I tried to start up mopidy, with something about Database operation expected to affect 1 row(s) but actually affected 0 row(s). Taking a look at the Jellyfin issue tracker, people were saying the issue fixed itself, so I restarted the Jellyfin process and the problem is indeed now fixed. I'll keep and eye on this, if it happens again I'll open an issue over at the Jellyfin tracker, this doesn't appear to be an problem with mopidy-jellyfin