songs stop several seconds before end #361

flostru · 2021-05-23T20:15:28Z

Im using librespot-java (spocon) on armhf to output to pipe/pipe.metadata and pick up from forked-daapd, it all works perfectly except that with nearly all songs it chops the last 2-3 seconds (mainly songs that dont fade out)
I have been playing around with crossfading, no difference.
I have been as well trying without preload, still no difference.

Not sure if this is a spotify, spocon, librespot-java or forked-daapd issue, so forgive me if this is not the right place to ask.

To Reproduce

Install spocon from http://ppa.launchpad.net/spocon/spocon/ubuntu bionic/main armhf Packages

Make pipes

mkfifo /srv/dev-disk-by-label-shares/Media/Audio/librespot-java.metadata
mkfifo /srv/dev-disk-by-label-shares/Media/Audio/librespot-java

spocon config.toml

deviceType = "COMPUTER"
deviceName = "SpoCon-Spotify"
deviceId = ""
logLevel = "TRACE"
preferredLocale = "de"

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

[auth]
        credentialsFile = "credentials.json"
        password = ""
        blob = ""
        storeCredentials = false
        strategy = "ZEROCONF"
        username = "

[preload]
        enabled = true

[network]
        connectionTimeout = 10

[proxy]
        password = ""
        address = ""
        port = 0
        auth = false
        type = "HTTP"
        enabled = false
        username = ""

[zeroconf]
        listenAll = true
        interfaces = ""
        listenPort = -1

[shell]
        onTrackSeeked = ""
        onConnectionDropped = ""
        onMetadataAvailable = ""
        onTrackChanged = ""
        onPanicState = ""
        enabled = false
        onPlaybackResumed = ""
        onConnectionEstablished = ""
        onPlaybackEnded = ""
        onContextChanged = ""
        onPlaybackPaused = ""
        onInactiveSession = ""
        onVolumeChanged = ""

[time]
        manualCorrection = 0
        synchronizationMethod = "NTP"

[api]
        port = 24879
        host = "0.0.0.0"

[player]
        enableNormalisation = false
        initialVolume = 20536
        bypassSinkVolume = true
        releaseLineDelay = 20
        normalisationPregain = 0.0
        metadataPipe = "/srv/dev-disk-by-label-shares/Media/Audio/librespot-java.metadata"
        autoplayEnabled = true
        preferredAudioQuality = "VERY_HIGH"
        localFilesPath = ""
        output = "PIPE"
        crossfadeDuration = 0
        retryOnChunkError = true
        outputClass = ""
        pipe = "/srv/dev-disk-by-label-shares/Media/Audio/librespot-java"
        mixerSearchKeywords = ""
        logAvailableMixers = true
        volumeSteps = 64

Start librespot/spocon

/usr/bin/java -jar /opt/spocon/librespot-java-api-v1.6.0.jar

Stream playlist from any spotify app to SpoCon-Spotify

Expected behavior
Play with no/minimal gaps but without truncations.

Actual behaviour
It plays but truncates the last 2-3 seconds of previous songs, especially annoying when song has no fadeout.

May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,101 DEBUG PlayerQueueEntry:234 - PlayerQueueEntry{01e79412cf4e7720b6f8bbd7f13240ca} has been removed from output.

Too early

Screenshots/Stracktraces/Logs

May 23 21:45:44 odroid java[4251]:  provider: "context" album_uri: "spotify:album:3l4cjJdGu4pn81pFM5jjGi" artist_uri: "spotify:artist:1xm7iJLJRw7lcRM4MeoebZ" } context_metadata { key: "context_description" value: "Finnish" } context_metadata { key: "context_owner" value: "pj2crjnenb8cir8kl2z5doa69" } context_metadata { key: "image_url" value: "" } context_metadata { key: "track_count" value: "22" } context_metadata { key: "zelda.context_uri" value: "spotify:playlist:0nda5N8gV11RhWbVJA2kNq" } session_id: "Z+1iugQdYsX1HUBUsFaJWw" } } member_type: CONNECT_STATE is_active: true put_state_reason: PLAYER_STATE_CHANGED last_command_sent_by_device_id: "66c518c580c5d0dda96d1f0d6ff21a295c6e76e7" last_command_message_id: 448989416 started_playing_at: 1621799132366 has_been_playing_for_ms: 62962 client_side_timestamp: 1621799143089}
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,099 DEBUG PlayerQueueEntry:330 - Player time offset is 625. {id: 01e79412cf4e7720b6f8bbd7f13240ca}
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,100 TRACE MixingLine:184 - Toggle first channel: false
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,101 DEBUG PlayerQueueEntry:234 - PlayerQueueEntry{01e79412cf4e7720b6f8bbd7f13240ca} has been removed from output.
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,107 TRACE MercuryClient:156 - Send Mercury request, seq: 4, uri: hm://event-service/v1/events, method: POST
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,120 DEBUG CrossfadeController:192 - Changed fade out. {curr: null, custom: false, why: TRACK_DONE, id: 01e79412cf4e7720b6f8bbd7f13240ca}
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,120 DEBUG CrossfadeController:170 - Changed fade in. {curr: null, custom: false, why: TRACK_DONE, id: 0144a92ff466af18e27bff57f7076346}
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,121 TRACE MixingLine:184 - Toggle first channel: true
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,121 DEBUG PlayerSession:283 - PlayerQueueEntry{0144a92ff466af18e27bff57f7076346} has been added to the output. {sessionId: Z+1iugQdYsX1HUBUsFaJWw, pos: 0, reason: TRACK_DONE}
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,132 TRACE PlayerQueueEntry:350 - PlayerQueueEntry{01e79412cf4e7720b6f8bbd7f13240ca} terminated.
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,707 TRACE MercuryClient:199 - Handling packet, cmd: MercuryReq, seq: 4, flags: 1, parts: 1
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,708 DEBUG EventService:51 - Event sent. {body: 12|38|0|a00adceb8082ed6d0c198f77f804405e9782d126|01e79412cf4e7720b6f8bbd7f13240ca|00000000000000000000000000000000|playlist|clickrow|playlist|endplay|2142636|10269100|257121|257121|257746|10|0|0|0|1|52190|0|-1|context|491|0|0|0|0|0|257121|257121|0|176400|spotify:playlist:0nda5N8gV11RhWbVJA2kNq|vorbis|d23be0b3cd8f4db099622da2a48e4f5e||0|1621799132503|0|context|your_library|xpui_2021-05-21_1621590990778_7e04046|com.spotify|crossfade|none|66c518c580c5d0dda96d1f0d6ff21a295c6e76e7|na|none, result: 200}
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,710 TRACE MercuryClient:156 - Send Mercury request, seq: 5, uri: hm://event-service/v1/events, method: POST
May 23 21:45:54 odroid java[4251]: 2021-05-23 21:45:54,751 INFO  DeviceStateHandler:273 - Put state. {ts: 1621799154127, connId: YTAwY...wMkJF, reason: PLAYER_STATE_CHANGED, request: device { device_info { can_play: true volume: 20536 name: "SpoCon-Spotify" capabilities { can_be_player: true gaia_eq_connect_id: true supports_logout: true is_observable: true volume_steps: 64 supported_types: "audio/episode" supported_types: "audio/track" command_acks: true supports_playlist_v2: true is_controllable: true supports_transfer_command: true supports_command_request: true supports_gzip_pushes: true } device_software_version: "librespot-java 1.6.0" device_type: COMPUTER spirc_version: "3.2.6" device_id: "a00adceb8082ed6d0c198f77f804405e9782d126" client_id: "65b708073fc0480ea92a077233ca87bd" } player_state { timestamp: 1621799154125 context_uri: "spotify:playlist:0nda5N8gV11RhWbVJA2kNq" context_url: "context://spotify:playlist:0nda5N8gV11RhWbVJA2kNq" context_restrictions { } play_origin { feature_identifier: "playlist" feature_version: "xpui_2021-05-21_1621590990778_7e04046" referrer_identifier: "your_library" feature_classes: "connect" } index { track: 6 } track { uri: "spotify:track:6ff0XZuZgUMaWusNjv1VQr" uid: "05fdd1a695830110" metadata { key: "added_at" value: "1621764668000" } metadata { key: "added_by_username" value: "pj2crjnenb8cir8kl2z5doa69" } metadata { key: "album_artist_name" value: "Juice Leskinen" } metadata { key: "album_artist_uri" value: "spotify:artist:4W6vvLzFQKixmJXSJK3wLp" } metadata { key: "album_disc_number" value: "1" } metadata { key: "album_title" value: "Ajan henki" } metadata { key: "album_uri" value: "spotify:album:2P8ssBO8PcUJRN2stYH9EZ" } metadata { key: "artist_name" value: "Juice Leskinen Slam" } metadata { key: "artist_uri" value: "spotify:artist:1F5luCKmbkRLdxkqPcZJOc" } metadata { key: "available_file_formats" value: "[\"OGG_VORBIS_320\",\"OGG_VORBIS_160\",\"OGG_VORBIS_96\",\"AAC_24\"]" } metadata { key: "duration" value: "263173" } metadata { key: "image_large_url" value: "spotify:image:ab67616d0000b2730fd7a0f4be1c342

Version/Commit

apt-cache policy spocon
spocon:
  Installed: 1.6.0
  Candidate: 1.6.0
  Version table:
 *** 1.6.0 500
        500 http://ppa.launchpad.net/spocon/spocon/ubuntu bionic/main armhf Packages
        100 /var/lib/dpkg/status

The text was updated successfully, but these errors were encountered:

devgianlu · 2021-05-25T20:03:06Z

That's very strange. Maybe @aleszczynskig or @uvjustin have had a similar issue (sorry for always pinging you on forked-daapd stuff).

gimmiereddy · 2021-05-26T20:21:41Z

I can confirm the same issue.

aleszczynskig · 2021-05-26T22:23:40Z

It also happens for me and I know why. At the end of each track, a pfls message is sent to the metadata pipe. Forked-daapd (now owntone) responds to this message immediately by cutting the output to the speakers but there is a 2-3 second delay in the audio pipeline which is inherit in AirPlay, as a result you lose the last couple of seconds playback. The solution I think is not to send the pfls at the end of the track.

Sorry for the quick write-up. I don't have much time at the moment.

aleszczynskig · 2021-05-26T22:26:15Z

No problem pinging on this btw. Happy to help out where I can.

devgianlu · 2021-05-27T05:55:13Z

@aleszczynskig Is it this one?

librespot-java/player/src/main/java/xyz/gianlu/librespot/player/Player.java

Line 977 in 90a53e6

dacpPipe.sendPipeFlush();

aleszczynskig · 2021-05-27T06:16:42Z

Yes

devgianlu · 2021-05-27T06:31:07Z

Removed

aleszczynskig · 2021-05-27T06:36:33Z

FYI - one down side to removing this is that when you change track in Spotify, there will be a couple of seconds lag before the track changes in owntone due to the inherent airplay lag I described in my previous post.

@devgianlu Is there anyway to have a different event for when the track ends rather than changes mid track so the pfls event is only sent for the latter?

devgianlu · 2021-05-28T17:11:06Z

Fixed! The pipe flush command is not sent only if the track change is user initiated.

…361)

aleszczynskig · 2021-05-29T06:22:29Z

Fantastic! Thank you. I'm away at present but I'll check it out once I'm back home.

flostru · 2021-05-30T10:20:52Z

Just trying your fix, works great, now everything is perfect.
This rocks! You rock!

Marko298 · 2021-07-18T16:42:10Z

Hi guys, is there any estimate when this fix will be live? This bug is very frustrating 😫

devgianlu · 2021-07-18T18:00:23Z

You can use a snapshot version or wait for 1.6.1 which should come in a couple of hours.

Marko298 · 2021-07-19T03:26:50Z

Wow, that was quick, thank you!
SpoCon package will be updated soon too?

devgianlu · 2021-07-19T08:45:29Z

@Marko298 @spocon Yes it should be.

applicature-mark-boychuk · 2021-07-19T09:21:04Z

awesome, thanks a lot!

spocon · 2021-07-19T09:48:46Z

Having troubles with the certificate to upload. Hope I can fix it today

spocon · 2021-07-19T20:20:31Z

new version 1.6.1 online

applicature-mark-boychuk · 2021-07-20T07:08:45Z

🚀

flostru added the bug Something isn't working label May 23, 2021

devgianlu added a commit that referenced this issue May 27, 2021

Removed redundant pfls message (#361)

e3b4f7e

devgianlu added a commit that referenced this issue May 28, 2021

Send DACP pipe flush command only if track change is user initiated (#…

e1eb2f4

…361)

devgianlu closed this as completed May 30, 2021

devgianlu mentioned this issue Jun 30, 2021

Song endings are being truncated spocon/spocon#38

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

songs stop several seconds before end #361

songs stop several seconds before end #361

flostru commented May 23, 2021 •

edited

Loading

devgianlu commented May 25, 2021

gimmiereddy commented May 26, 2021

aleszczynskig commented May 26, 2021 •

edited

Loading

aleszczynskig commented May 26, 2021

devgianlu commented May 27, 2021

aleszczynskig commented May 27, 2021

devgianlu commented May 27, 2021

aleszczynskig commented May 27, 2021

devgianlu commented May 28, 2021

aleszczynskig commented May 29, 2021

flostru commented May 30, 2021

Marko298 commented Jul 18, 2021

devgianlu commented Jul 18, 2021

Marko298 commented Jul 19, 2021

devgianlu commented Jul 19, 2021

applicature-mark-boychuk commented Jul 19, 2021

spocon commented Jul 19, 2021

spocon commented Jul 19, 2021

applicature-mark-boychuk commented Jul 20, 2021

songs stop several seconds before end #361

songs stop several seconds before end #361

Comments

flostru commented May 23, 2021 • edited Loading

devgianlu commented May 25, 2021

gimmiereddy commented May 26, 2021

aleszczynskig commented May 26, 2021 • edited Loading

aleszczynskig commented May 26, 2021

devgianlu commented May 27, 2021

aleszczynskig commented May 27, 2021

devgianlu commented May 27, 2021

aleszczynskig commented May 27, 2021

devgianlu commented May 28, 2021

aleszczynskig commented May 29, 2021

flostru commented May 30, 2021

Marko298 commented Jul 18, 2021

devgianlu commented Jul 18, 2021

Marko298 commented Jul 19, 2021

devgianlu commented Jul 19, 2021

applicature-mark-boychuk commented Jul 19, 2021

spocon commented Jul 19, 2021

spocon commented Jul 19, 2021

applicature-mark-boychuk commented Jul 20, 2021

flostru commented May 23, 2021 •

edited

Loading

aleszczynskig commented May 26, 2021 •

edited

Loading