search

micro-nova / AmpliPi

Whole House Audio System 🔊
https://amplipi.com
GNU General Public License v3.0
284 stars 23 forks source link

Update to 0.1.9 broke Spotify connecting #377

Closed Shwall closed 1 year ago

Shwall commented 1 year ago

It looks like updating to release 0.1.9 broke Spotify support on my Amplipi. Previously I could configure an input as a Spotify stream then connect to it from within Spotify as a Spotify connect device. Today I updated my Amplipi and Spotify still shows up as an available stream on the Amplipi however the Spotify connect device for the Amplipi no longer shows up as an option in Spotify. Previously I had experienced this and it was due to the Spotify stream being paused in the Amplipi app clicking the play button on the stream would allow the Spotify connect device to show up in Spotify. With this new update the play/pause button on the Amplipi app is grayed out. I tried reverting to several of the previous releases, Spotify streams had the same behavior on each of them.

linknum23 commented 1 year ago

Sorry to hear that. It sounds like something might be failing while starting up the underlying Spotify process. Can you try resetting the Spotify stream and if that doesn't work send us a log?

To "reset' a Spotify stream, select a different stream then select the Spotify stream again.

In 0.1.9 you should be able to access a log of everything that has happened since boot by clicking on the Logs link in the bottom of the AmpliPi web app. Can you post the logs that happened during the Spotify reset?

2022-09-26_1182x924

linknum23 commented 1 year ago

Any luck on this?

Shwall commented 1 year ago

Still experiencing the same issue here is the logs section from resetting the stream:

Sep 28 19:48:06 amplipi systemd[1]: Started Journal Gateway Service.
Sep 28 19:48:09 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:11 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:13 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:15 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:17 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:19 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:21 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:23 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:25 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:27 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:28 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:30 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:32 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:33 amplipi authbind[816]: vollibrespot v0.2.4 61563b7 2021-07-22 (librespot 08d8bcc 2020-10-07) -- Built On 2021-07-22
Sep 28 19:48:33 amplipi authbind[816]: Reading Config from "config.toml"
Sep 28 19:48:33 amplipi authbind[816]: [Vollibrespot] : Using Alsa backend with device: ch0
Sep 28 19:48:33 amplipi authbind[816]: Amplipi disconnected
Sep 28 19:48:33 amplipi authbind[816]: Amplipi connected to 0
Sep 28 19:48:33 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "PATCH /api/sources/0 HTTP/1.1" 200 OK
Sep 28 19:48:33 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /static/imgs/spotify.png HTTP/1.1" 200 OK
Sep 28 19:48:34 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:37 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:39 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:41 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:43 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:45 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:47 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:49 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:51 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:53 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:55 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:56 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:58 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:48:58 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "PATCH /api/groups/101 HTTP/1.1" 200 OK
Sep 28 19:49:00 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:02 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:04 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:06 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:08 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:10 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:12 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:15 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:17 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:19 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:20 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:22 amplipi authbind[816]: Amplipi disconnected
Sep 28 19:49:22 amplipi authbind[816]: INFO:     192.168.0.5:64218 - "PATCH /api/sources/0 HTTP/1.1" 200 OK
Sep 28 19:49:22 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:25 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:27 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:29 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:31 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:33 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:35 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:37 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:39 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:41 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:42 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
Sep 28 19:49:43 amplipi authbind[816]: vollibrespot v0.2.4 61563b7 2021-07-22 (librespot 08d8bcc 2020-10-07) -- Built On 2021-07-22
Sep 28 19:49:43 amplipi authbind[816]: Reading Config from "config.toml"
Sep 28 19:49:43 amplipi authbind[816]: [Vollibrespot] : Using Alsa backend with device: ch0
Sep 28 19:49:43 amplipi authbind[816]: Amplipi disconnected
Sep 28 19:49:43 amplipi authbind[816]: Amplipi connected to 0
Sep 28 19:49:43 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "PATCH /api/sources/0 HTTP/1.1" 200 OK
Sep 28 19:49:44 amplipi authbind[816]: INFO:     192.168.0.5:64237 - "GET /api HTTP/1.1" 200 OK
linknum23 commented 1 year ago

I'm not seeing any failures when vollibrespot (AmpliPi's Sptoify Connect daemon) is started.

This smells like an MDNS/networking issue caused by a package update that happened during the upgrade to 0.1.9.

Is there anything special about your network setup? Did you have anything special installed on AmpliPi's pi?

Shwall commented 1 year ago

Not that I'm aware of i have a modem router combo box wired directly to the amplipi and so far have only used the web front end to access the amplipi.

linknum23 commented 1 year ago

Hmm I will need some help to debug this a little further, can you do the following?:

  1. Set source 1 to a Spotify stream
  2. Set source 1 to blank (this will stop Spotify but leave the old config)
  3. SSH into AmpliPi
    • use an ssh client such as Putty to ssh into pi@amplipi.local
    • use the password found on amplipi’s display, you will have to touch the display to show it
  4. Run the following commands in the SSH terminal: 
    cd amplipi-dev/config/srcs/0
./../../../streams/vollibrespot

This should start up spotify with the last configuration/device-name used. Try to connect to it and report the output and results.

Here's what the output looked like on one of our AmpliPis running 0.1.9:

pi@amplipi:~ $ cd amplipi-dev/config/srcs/0
pi@amplipi:~/amplipi-dev/config/srcs/0 $ ./../../../streams/vollibrespot
vollibrespot v0.2.4 61563b7 2021-07-22 (librespot 08d8bcc 2020-10-07) -- Built On 2021-07-22
Reading Config from "config.toml"
[Vollibrespot] : Using Alsa backend with device: ch0
[Vollibrespot] : Connecting to AP "ap-gue1.spotify.com:443"
[Vollibrespot] : Authenticated as "1232441019" !
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: "US"
[Vollibrespot] : Event: Volume { volume_to_mixer: 65535 }
[Vollibrespot] : Event: SessionActive { became_active_at: 1664471211364 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Resolving uri "spotify:station:track:7zJi6HnUzxo2J4La1yTFj3"
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 204381105707282777001474785076204285381, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 204381105707282777001474785076204285381, audio_type: Track } }
[Vollibrespot] : Event: GotToken { token: Token { access_token: "BQC8rJhzLIiUYL-wMEA0ztqy0QXdOo-ldD83jfkckQpJRjVPBovpLKS5Qc1wdQNWe5QmRDT_tOBQX7NZBLfH5pF6HXcqdHpT9N7FJeXT16B-TcnwSAHqs_T6FrrHVIv3ZxDduJi465F34urI5V8P2IHAicifO3ekv31-cd4b1d_I9MGSMcGR7qms-1ULXrCq9kDyMw", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } }
[Vollibrespot] : Loading <Sheep Go To Heaven> with Spotify URI <spotify:track:4G8Eu3EDQZYhHPfJMFCv8V>
[Vollibrespot] : Resolved 50 tracks from <"spotify:station:track:7zJi6HnUzxo2J4La1yTFj3">
[Vollibrespot] : <Sheep Go To Heaven> (228093 ms) loaded
[Vollibrespot] : Event: SinkActive
Shwall commented 1 year ago

It looks like it just hangs here, Let me know if there is anything else I could try. I checked my Router config and it is all still in the factory default settings like before I updated the Amplipi. 

Last login: Sat Sep 24 14:33:11 2022
pi@amplipi:~ $ cd amplipi-dev/config/srcs/0/
pi@amplipi:~/amplipi-dev/config/srcs/0 $ ls
config.toml  currentSong  spot_meta_log.txt
pi@amplipi:~/amplipi-dev/config/srcs/0 $ ./../../../streams/vollibrespot
vollibrespot v0.2.4 61563b7 2021-07-22 (librespot 08d8bcc 2020-10-07) -- Built On 2021-07-22
Reading Config from "config.toml"
[Vollibrespot] : Using Alsa backend with device: ch0
linknum23 commented 1 year ago

That behaves identically to a working system that has not been connected to. I wonder if Spotify's (really vollibrepot's) MDNS advertisement is getting to your phone.

REMINDER: your phone needs to be on the same subnet as AmpliPi for MDNS advertisement to work out of the box. In our case both AmpliPi and my phone have 192.168.0.X ip addresses.

Can you check the following after starting up a Spotofy stream on your AmpliPi?:

Here is what "Spotify Group Session" looks like after I clicked on it for more details: Screenshot_20221003-104741

linknum23 commented 1 year ago

Also is anyone else having this issue with 0.1.9? We have not been able to replicate this issue internally on several of our AmpliPi's.

Shwall commented 1 year ago

Sorry for the delayed response. After starting a spotify stream there is no group session showing up i can see one if i start Spotify on another device live my fire TV.

linknum23 commented 1 year ago

This may be a slightly different output, than you see. I apologize for the confusion. This was from our newer Spotify integration that we have been testing. I didn't realize that the spotify mdns advertisement was different on the new version we are testing.

That said there should be a similar mdns advertisement coming out of AmpliPi. Do you see any Spotify mdns advertisements coming from AmpliPi?

Our current Spotify connect solution does not support group sessions, but stay tuned. We are working on integrating this very soon! Check out #366. We are hoping to have it in the next release.

Shwall commented 1 year ago

In the bonjour browser I don't see any advertisments from the Amplipi IP address. No matter which source I set it as or when I start it by hand via the command line. Could this be a problem with firewall or other settings on my router?

linknum23 commented 1 year ago

In that case there are 2 generic causes. Something misconfigured on your AmpliPi, maybe it's time is somehow off? Otherwise mdns is totally blockable by a router I would expect this to be done with a firewall rule or similar setting or it may just not work with well with an old wireless access point.

linknum23 commented 1 year ago

Closing this due to inactivity. Feel free to reopen this if there is still an issue.

Shwall commented 1 year ago

Sorry I had to put this on the backburner for a while. It sounds like this issue is unique to m system. I have also noticed that accessing the amplipi via amplipi.local fails I think this may be related?

It also looks like the time is off by 2 hours is there an easy way to fix that?

pi@amplipi:~ $ date
Sun 05 Feb 2023 12:49:49 PM EST
pi@amplipi:~ $ exit
logout
Connection to 192.168.0.2 closed.
shwall@laptop:~$ date
Sun Feb  5 10:50:00 MST 2023
linknum23 commented 1 year ago

Can you show us the output of:

timedatectl status
Shwall commented 1 year ago

Sorry for not providing an update on this. I think I isolated the issue as a problem with my router not properly forwarding the mDNS. I installed a new router and now the amplipi device shows up in spotify again but it fails to connect. I think this may be due to the error here in the log:

Mar 18 23:09:54 amplipi authbind[815]: Connecting to AP "ap.spotify.com:443"
Mar 18 23:09:54 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:09:55 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:09:56 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:09:57 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:09:58 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:09:59 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:09:59 amplipi authbind[815]: Authenticated as "1261638132" !
Mar 18 23:09:59 amplipi authbind[815]: Country: "US"
Mar 18 23:09:59 amplipi authbind[815]: Using Alsa sink with format: S16
Mar 18 23:09:59 amplipi authbind[815]: error 403 for uri hm://keymaster/token/authenticated?client_id=2c1ea588dfbc4a989e2426f8385297c3&scope=user-read-playback-state,user-modify-playback-state,user-read-currently-playing
Mar 18 23:09:59 amplipi authbind[815]: failed to request a token for the web API
Mar 18 23:10:00 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:01 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:01 amplipi CRON[2612]: pam_unix(cron:session): session opened for user pi by (uid=0)
Mar 18 23:10:01 amplipi CRON[2613]: (pi) CMD (/home/pi/amplipi-dev/scripts/check-online)
Mar 18 23:10:01 amplipi CRON[2612]: pam_unix(cron:session): session closed for user pi
Mar 18 23:10:02 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:03 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
. . .
Mar 18 23:10:28 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:28 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2602 was not provided by any .service files
Mar 18 23:10:28 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2602 was not provided by any .service files
Mar 18 23:10:28 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2602 was not provided by any .service files
Mar 18 23:10:28 amplipi authbind[815]: Traceback (most recent call last):
Mar 18 23:10:28 amplipi authbind[815]:   File "/home/pi/amplipi-dev/streams/MPRIS_metadata_reader.py", line 142, in <module>
Mar 18 23:10:28 amplipi authbind[815]:     MPRISMetadataReader(service_suffix, metadata_path, debug).run()
Mar 18 23:10:28 amplipi authbind[815]:   File "/home/pi/amplipi-dev/streams/MPRIS_metadata_reader.py", line 121, in run
Mar 18 23:10:28 amplipi authbind[815]:     time.sleep(1.0/METADATA_REFRESH_RATE)
Mar 18 23:10:28 amplipi authbind[815]: TypeError: sigterm_handler() takes 1 positional argument but 3 were given
Mar 18 23:10:28 amplipi authbind[815]: amplipi disconnected
Mar 18 23:10:28 amplipi authbind[815]: Failed to stop MPRIS metadata process, killing
Mar 18 23:10:28 amplipi authbind[815]: disconnecting proxy
Mar 18 23:10:28 amplipi authbind[815]: mpris closed
Mar 18 23:10:28 amplipi authbind[815]: Closed MPRIS spotifyd.instance2602
. . . 
Mar 18 23:10:29 amplipi authbind[815]: Using software volume controller.
Mar 18 23:10:29 amplipi authbind[815]: no usable credentials found, enabling discovery
Mar 18 23:10:29 amplipi authbind[815]: amplipi connected to 0
Mar 18 23:10:29 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "PATCH /api/sources/0 HTTP/1.1" 200 OK
Mar 18 23:10:30 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:31 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:32 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:33 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:33 amplipi authbind[815]: Connecting to AP "ap.spotify.com:443"
Mar 18 23:10:34 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:35 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:36 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:37 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:38 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:39 amplipi authbind[815]: Authenticated as "1261638132" !
Mar 18 23:10:39 amplipi authbind[815]: Country: "US"
Mar 18 23:10:39 amplipi authbind[815]: Using Alsa sink with format: S16
Mar 18 23:10:39 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:39 amplipi authbind[815]: error 403 for uri hm://keymaster/token/authenticated?client_id=2c1ea588dfbc4a989e2426f8385297c3&scope=user-read-playback-state,user-modify-playback-state,user-read-currently-playing
Mar 18 23:10:39 amplipi authbind[815]: failed to request a token for the web API
Mar 18 23:10:40 amplipi authbind[815]: INFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:10:41 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
. . . 
Mar 18 23:12:38 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2625 was not provided by any .service files
Mar 18 23:12:38 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2625 was not provided by any .service files
Mar 18 23:12:38 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2625 was not provided by any .service files
Mar 18 23:12:38 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2625 was not provided by any .service files
Mar 18 23:12:38 amplipi authbind[815]: Dbus error getting MPRIS metadata: The name org.mpris.MediaPlayer2.spotifyd.instance2625 was not provided by any .service filesINFO:     192.168.0.54:51278 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:12:39 amplipi authbind[815]: INFO:     192.168.0.36:49006 - "GET /api HTTP/1.1" 200 OK
Mar 18 23:12:40 amplipi authbind[815]: Traceback (most recent call last):
Mar 18 23:12:40 amplipi authbind[815]:   File "/home/pi/amplipi-dev/streams/MPRIS_metadata_reader.py", line 142, in <module>
Mar 18 23:12:40 amplipi authbind[815]:     MPRISMetadataReader(service_suffix, metadata_path, debug).run()
Mar 18 23:12:40 amplipi authbind[815]:   File "/home/pi/amplipi-dev/streams/MPRIS_metadata_reader.py", line 121, in run
Mar 18 23:12:40 amplipi authbind[815]:     time.sleep(1.0/METADATA_REFRESH_RATE)
Mar 18 23:12:40 amplipi authbind[815]: TypeError: sigterm_handler() takes 1 positional argument but 3 were given
Mar 18 23:12:40 amplipi authbind[815]: stealing amplipi from source Player 1
Mar 18 23:12:40 amplipi authbind[815]: amplipi disconnected
Mar 18 23:12:40 amplipi authbind[815]: Failed to stop MPRIS metadata process, killing
Mar 18 23:12:40 amplipi authbind[815]: disconnecting proxy
Mar 18 23:12:40 amplipi authbind[815]: mpris closed
Shwall commented 1 year ago

running via command line it seems something is missing from the onfig.toml file:

pi@amplipi:~ $ cd amplipi-dev/config/srcs/0/
pi@amplipi:~/amplipi-dev/config/srcs/0 $ ls
config.toml  metadata.txt
pi@amplipi:~/amplipi-dev/config/srcs/0 $ ./../../../streams/vollibrespot 
vollibrespot v0.2.4 61563b7 2021-07-22 (librespot 08d8bcc 2020-10-07) -- Built On 2021-07-22
Reading Config from "config.toml"
Malformed config key: missing field `Authentication` at line 1 column 1
pi@amplipi:~/amplipi-dev/config/srcs/0 $

maybe my previous router was only part of the problem? Checking the timedatectl status shows the time is off:

pi@amplipi:~/amplipi-dev/config/srcs/0 $ timedatectl status
               Local time: Sat 2023-03-18 23:39:31 EDT
           Universal time: Sun 2023-03-19 03:39:31 UTC
                 RTC time: n/a
                Time zone: America/Detroit (EDT, -0400)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
pi@amplipi:~/amplipi-dev/config/srcs/0 $ exit
logout
Connection to amplipi.local closed.
========================
:~/Desktop$ timedatectl status
               Local time: Sat 2023-03-18 20:39:52 MST
           Universal time: Sun 2023-03-19 03:39:52 UTC
                 RTC time: Sun 2023-03-19 03:39:52
                Time zone: America/Phoenix (MST, -0700)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
linknum23 commented 1 year ago

Thanks for getting back to us on this. What version of AmpliPi's software are you running right now?

If you haven't already (as it appears from the logs) I would highly recommend updating to the latest version, 0.2.1.

running via command line it seems something is missing from the onfig.toml file:

Recent versions of AmpliPi no longer use vollibrespot for Spotify streams, I'm guessing vollibrespot was left on your system from an older install. The new Spotify client is called spotifyd and has a slightly difference configuration format but uses the same file.

maybe my previous router was only part of the problem? Checking the timedatectl status shows the time is off:

Let's check the UTC time outputs (to avoid comparing different timezones)

AmpliPi output: Universal time: Sun 2023-03-19 03:39:31 UTC Your system's output: Universal time: Sun 2023-03-19 03:39:52 UTC

Comparing the UTC times, AmpliPi's time looks synchronized, the 21 second difference I only assume is due to the delay in switching back to your computer.

Shwall commented 1 year ago

Thanks for all you're help, I was able to get this working again I'm not sure exactly what steps fixed the issue:

  1. updated amplipi to 0.2.1
  2. replaced router
  3. reset amplipi to factory settings
  4. physically power cycled amplipi