librespot-org / librespot-java

The most up-to-date open source Spotify client
Apache License 2.0
380 stars 93 forks source link

2nd time starting / connecting music after a reboot results in no sound (DAC) #282

Closed Zageron closed 3 years ago

Zageron commented 3 years ago

Describe the bug When librespot / spocon stops playback, I believe the device is left open and is not forcefully reopened or killed when a new playback attempt is made. There are no clear logs that describe this. Spotify continues to play back, but no audio is heard.

To Reproduce

Additionally:

Expected behavior

Screenshots/Stracktraces/Logs

pi@spotipi:~ $ speaker-test -dcard:Device

speaker-test 1.1.8

Playback device is default
Stream parameters are 48000Hz, S16_LE, 1 channels
Using 16 octaves of pink noise
Playback open error: -16,Device or resource busy

Version/Commit 1.5.3

Using alsa.

I did see this in the logs, not sure if it helps.

Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,437 DEBUG PlayerQueueEntry:209 - PlayerQueueEntry{0178c7756e730278d60e63eddecdf07c} has been removed from output.
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,461 TRACE PlayerQueueEntry:325 - PlayerQueueEntry{0178c7756e730278d60e63eddecdf07c} terminated.
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,467 TRACE PlayerQueue:141 - Queue has been cleared.
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,476 TRACE AsyncProcessor:57 - AsyncProcessor{put-state-worker} is shutting down
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,490 INFO  Session:417 - Closing session. {deviceId: 504c79f310ca50f51a6c0400ff9432d5b4fa2206}
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,496 TRACE AsyncProcessor:57 - AsyncProcessor{dealer-worker} is shutting down
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,517 DEBUG DealerClient:319 - Did not dispatch connection invalidated: null != xyz.gianlu.librespot.dealer.DealerClient$ConnectionHolder@ed20b7
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,526 TRACE AsyncProcessor:57 - AsyncProcessor{event-service-sender} is shutting down
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,566 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 82, flags: 1, parts: 1
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,571 DEBUG EventService:35 - Event sent. {body: 12|37|13|504c79f310ca50f51a6c0400ff9432d5b4fa2206|0178c7756e730278d60e63eddecdf07c|00000000000000000000
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,578 TRACE MercuryClient:140 - Send Mercury request, seq: 83, uri: hm://event-service/v1/events, method: POST
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,727 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 83, flags: 1, parts: 1
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,730 DEBUG EventService:35 - Event sent. {body: 10|20|cb14f1eac699da36ffbf0163c5123494892b54c9|0178c7756e730278d60e63eddecdf07c|0|0|0|0|0|0|5242880|117
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,746 TRACE MercuryClient:140 - Send Mercury request, seq: 84, uri: hm://event-service/v1/events, method: POST
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,890 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 84, flags: 1, parts: 1
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,895 DEBUG EventService:35 - Event sent. {body: 372|1|0178c7756e730278d60e63eddecdf07c|spotify:track:5mAitcAt2Z23HIIINIcY0h|0|[[148,123169]], result: 2
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,901 TRACE AsyncProcessor:48 - AsyncProcessor{event-service-sender} is shut down
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,909 TRACE Session:1368 - Session.Receiver stopped
Dec 29 23:55:06 spotipi java[444]: 2020-12-29 23:55:06,931 INFO  Session:476 - Closed session. {deviceId: 504c79f310ca50f51a6c0400ff9432d5b4fa2206}
devgianlu commented 3 years ago

Can you try starting the playback, pausing, waiting 30 seconds and then executing speaker-test -dcard:Device. The device should be released after 20 seconds of inactivity (and also when the session is closed).

Zageron commented 3 years ago

My config: (Note that I changed the releaseLineDelay to 2.)

### Device type (COMPUTER, TABLET, SMARTPHONE, SPEAKER, TV, AVR, STB, AUDIO_DONGLE, GAME_CONSOLE, CAST_VIDEO, CAST_AUDIO, AUTOMOBILE, WEARABLE, UNKNOWN_SPOTIFY, CAR_THING, UNKNOWN) ###
deviceType = "COMPUTER"
### Device name ###
deviceName = "SpotiPi"
### Device ID (40 chars, leave empty for random)  ###
deviceId = ""
### Log level (OFF, FATAL, ERROR, WARN, INFO, DEBUG, TRACE, ALL) ###
logLevel = "TRACE"
### Preferred locale ###
preferredLocale = "en"

### Cache ###
[cache]
        dir = "./cache/"
        # Cache enabled
        enabled = true
        doCleanUp = true

### Authentication ###
[auth]
        # Credentials file (JSON)
        credentialsFile = "credentials.json"
        # Spotify password (USER_PASS only)
        password = ""
        # Spotify authentication blob Base64-encoded (BLOB only)
        blob = ""
        # Whether to store reusable credentials on disk (not a plain password)
        storeCredentials = false
        # Strategy (USER_PASS, ZEROCONF, BLOB, FACEBOOK, STORED)
        strategy = "ZEROCONF"
        # Spotify username (BLOB, USER_PASS only)
        username = ""

### Preload ###
[preload]
        # Preload enabled
        enabled = true

### Proxy ###
[proxy]
        # Basic auth password
        password = ""
        # The proxy hostname
        address = ""
        # The proxy port
        port = 0
        # Whether authentication is enabled on the server
        auth = false
        # The proxy type (HTTP, SOCKS)
        type = "HTTP"
        # Whether the proxy is enabled
        enabled = false
        # Basic auth username
        username = ""

### Zeroconf ###
[zeroconf]
        # Listen on all interfaces (overrides `zeroconf.interfaces`)
        listenAll = true
        # Listen on these interfaces (comma separated list of names)
        interfaces = ""
        # Listen on this TCP port (`-1` for random)
        listenPort = -1

### Time correction ###
[time]
        # Manual time correction in millis
        manualCorrection = 0
        # Time synchronization method (NTP, PING, MELODY, MANUAL)
        synchronizationMethod = "NTP"

### API ###
[api]
        # API port (`api` module only)
        port = 24879
        # API listen interface (`api` module only)
        host = "0.0.0.0"

### Player ###
[player]
        # Whether to apply the Spotify loudness normalisation
        enableNormalisation = true
        # Initial volume (0-65536)
        initialVolume = 65536
        # Release mixer line after set delay (in seconds)
        releaseLineDelay = 2
        # Normalisation pregain in decibels (loud at +6, normal at +3, quiet at -5)
        normalisationPregain = 3.0
        # Output metadata in Shairport Sync format (https://github.com/mikebrady/shairport-sync-metadata-reader)
        metadataPipe = ""
        # Autoplay similar songs when your music ends
        autoplayEnabled = true
        # Preferred audio quality (NORMAL, HIGH, VERY_HIGH)
        preferredAudioQuality = "VERY_HIGH"
        # Audio output device (MIXER, PIPE, STDOUT)
        output = "MIXER"
        # Crossfade overlap time (in milliseconds)
        crossfadeDuration = 0
        # Whether the player should retry fetching a chuck if it fails
        retryOnChunkError = true
        # Mixer/backend search keywords (semicolon separated)
        mixerSearchKeywords = "Device [plughw:1,0]"
        # Output raw (signed) PCM to this file (`player.output` must be PIPE)
        pipe = ""
        # Log available mixers
        logAvailableMixers = true
        # Number of volume notches
        volumeSteps = 64

speaker-test 1.1.8

Playback device is default Stream parameters are 48000Hz, S16_LE, 2 channels Using 16 octaves of pink noise Rate set to 48000Hz (requested 48000Hz) Buffer size range from 96 to 262144 Period size range from 48 to 131072 Using max buffer size 262144 Periods = 4 was set period_size = 65536 was set buffer_size = 262144 Hardware PCM card 1 'USB Modi Device' device 0 subdevice 0 Its setup is: stream : PLAYBACK access : RW_INTERLEAVED format : S16_LE subformat : STD channels : 2 rate : 48000 exact rate : 48000 (48000/1) msbits : 16 buffer_size : 262144 period_size : 65536 period_time : 1365333 tstamp_mode : NONE tstamp_type : MONOTONIC period_step : 1 avail_min : 65536 period_event : 0 start_threshold : 262144 stop_threshold : 262144 silence_threshold: 0 silence_size : 0 boundary : 1073741824 appl_ptr : 0 hw_ptr : 0 0 - Front Left 1 - Front Right Time per period = 5.539558 0 - Front Left 1 - Front Right Time per period = 4.040951

*Plays Sound* ^

- `speaker-test -dcard:Device -c2` works.
- `sudo speaker-test` or `speaker-test -c2` works.

Alright, time to open spotify.

- On my PC, I select SpotiPi. (On an android and iphone device SpotiPi does not appear until it has been activated on the PC.)
![image](https://user-images.githubusercontent.com/1892473/103375913-27e50a80-4a90-11eb-89fd-72b91514b951.png)
- This connection tool 50 seconds to appear in desktop spotify.
- Pressing play on a file resulted in no output on the speakers.
- Pausing and unpausing resulted in the connection switching to my phone's instance with no prompt.
- I am not unable to switch to SpotiPi from the PC.
- Attempting from my phone resulted in no success.
- Closing and reopening Spotify on my PC allowed me to connect to SpotiPi.
- Playing audio at this point does not function.

Back to speaker-test.
- Wait 30 seconds:
```zsh
❯ speaker-test -c2

speaker-test 1.1.8

Playback device is default
Stream parameters are 48000Hz, S16_LE, 2 channels
Using 16 octaves of pink noise
Playback open error: -16,Device or resource busy

speaker-test 1.1.8

Playback device is default Stream parameters are 48000Hz, S16_LE, 2 channels Using 16 octaves of pink noise Rate set to 48000Hz (requested 48000Hz) Buffer size range from 96 to 262144 Period size range from 48 to 131072 Using max buffer size 262144 Periods = 4 was set period_size = 65536 was set buffer_size = 262144 0 - Front Left 1 - Front Right Time per period = 20.341798



## Fresh Reboot
- `sudo reboot`
- Connect to SpotiPi (connection took about 30 seconds)
- Pressing play results in audio.
- Pause spotify.
- Wait 30 seconds.
- `speaker-test -c2`: Pink noise outputs.
- Repeat test results in the same audio.
- Pressing play in spotify results in no audio.
- Pause spotify.
- Immediate `speaker-test -c2` results in `Playback open error: -16,Device or resource busy`
- Wait 30 seconds.
- `speaker-test -c2`: No audio.

## Another fresh reboot attempt
- `sudo reboot`
- Connect to SpoiPi (connection took 60 seconds)
- Pressing play resulted in 1 second of audio, and then nothing.
- Pause spotify.
- Wait 30 seconds.
- `speaker-test -c2`: Device Busy
- `sudo systemctl restart spocon`
- `speaker-test -c2`: No audio.

## Attempt number 3:
- Reboot
- Connect to SpotiPi
- Play
- Pause
- speaker-test: (good, period 3 seconds)
- Play (Got audio)
- Pause
- speaker-test: (no audio, not busy, period 20 seconds again)
- Play (no audio)

https://pastebin.com/u5ayZSBD
Zageron commented 3 years ago

I've ordered a Raspberry Pi 4 so I can use the likely better supported Java11 to see if it works better.

devgianlu commented 3 years ago

As you can see there is no clear pattern in what's happening. The fact is that a Raspberry Pi Zero can't run a Java program properly and in a reliable way. You'll see many of this problems disappear on the Raspberry Pi 4 (hopefully).

Zageron commented 3 years ago

Yeah everything worked flawlessly on the first try with rpi4 and performance is far superior. Perhaps you should add a warning at the front that using a Raspberry Pi Zero W is unsupported and wont work as expected.

Thanks!