Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: For cue-backed songs, clients are not aware of track changes. They just keep playing. #195

Closed
yatli opened this issue Apr 25, 2023 · 7 comments · Fixed by #205
Closed

[Bug]: For cue-backed songs, clients are not aware of track changes. They just keep playing. #195

yatli opened this issue Apr 25, 2023 · 7 comments · Fixed by #205
Assignees
@kagemomiji
Labels
bug Something isn't working
Milestone
11.1.2

Comments

@yatli
Copy link

yatli commented Apr 25, 2023 •
edited
Loading

What happened?

First, thank you for this awesome fork! Years of efforts, multiple continuations, it's finally getting there!

I'd like to report an issue with clients, so technically this is not the problem of this fork, but that the clients don't know about CUEs. When a track is finished, the client is not aware, and continues to update the playback timer past the track's total length, without updating "now playing" to the next one. Audio playback works fine. Later content are being served in a gapless way.

Steps to reproduce

Say I have a CUE file backing up multiple tracks:

Song 1 [00:00 - 01:30]
Song 2 [01:30 - 05:00]
Song 3 [05:00 - 18:00]
...

If a track is launched from the client, the offset will be calculated correctly,
so the playback works as expected.

However, when the track ends, the client continues to playback later content,
without updating the current playing track or reset the seekbar/track time etc.

For example:

[Client launches Song1]
...
Now playing: Song 1 [0:01 / 01:30]
...
(later)
Now playing: Song 1 [1:31 / 01:30]
(Song 2 starts playing, but client thinks it's Song 1 having some hidden track content!)
...
(later)
Now playing: Song 1 [19:59 / 01:30]
(If the client wants to cache the songs, it may result in O(n*L) wasted space, 
where n is the nr. of tracks and L is the total length of the disc.)

** Now, if I hit "Next Song", it goes back to "Song 2" because that's the 
logical thing for the client based on its current states. 
But 20mins into the disc we really want to go to some later songs.

---
Update: just finished a whole album. 
The client IS informed that the the track is over, and it then loads "Song 2" :D

I have experimented with Sublime (Linux) and D-sub/Subsonic (Android) and they behave more or less like this.

Version

11.1.1 (Stable)

Version Detail

11.1.1 release

Operating System

Linux, docker image built from source

Java Version

17.something I forgot

Database

Other

DB Detail

Docker default I'm not sure

Configuration paramter

Client problem. Config params not relevant here

Proxy Server

No response

client detail

No response

language

None

Relevant log output

No response
@yatli yatli added the bug Something isn't working label Apr 25, 2023
@kagemomiji
Copy link
Owner

@yatli
I can not reproduce this issue by DSub.
Could you provide me screenshots of Transcoding page and of airsonic.log in About page?

@yatli
Copy link
Author

yatli commented Apr 28, 2023 •
edited
Loading

Sure:

image

Relevant excerpts from docker-compose logs, driven by a sublime-music client:

airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.009  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 130183 | EventType: EXPIRED | Old value: Phantasmagoria mystical expectation | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.009  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 130183 | EventType: CREATED | Old value: null | New value: Phantasmagoria mystical expectation
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.035  INFO --- o.a.p.c.StreamController                 : 167.220.232.52: yatli listening to 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]/Audio CD.tta in folder 2
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.036  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 130183 | EventType: REMOVED | Old value: Phantasmagoria mystical expectation | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.037  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [IOSYS] イオシス/2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]-2--1.0 | EventType: EXPIRED | Old value: 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.037  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [IOSYS] イオシス/2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]-2--1.0 | EventType: CREATED | Old value: null | New value: 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.038  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [IOSYS] イオシス/2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]-2--1.0 | EventType: REMOVED | Old value: 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.038  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 99495 | EventType: EXPIRED | Old value: 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.039  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-ss][0.0][-i][/var/touhou/[IOSYS] イオシス/2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]/Audio CD.tta][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.531  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 130183 | EventType: CREATED | Old value: null | New value: Phantasmagoria mystical expectation
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.531  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [IOSYS] イオシス/2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]-2--1.0 | EventType: CREATED | Old value: null | New value: 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.531  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: MEDIA_FILE-99495 | EventType: EXPIRED | Old value: org.airsonic.player.domain.CoverArt@58913b82 | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:01.531  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: MEDIA_FILE-99495 | EventType: CREATED | Old value: null | New value: org.airsonic.player.domain.CoverArt@58913b82
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:05.856  INFO --- o.a.p.c.DownloadController               : Downloading 'Audio CD.tta' to 14
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:07.562  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 130183 | EventType: REMOVED | Old value: Phantasmagoria mystical expectation | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:55:07.563  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [IOSYS] イオシス/2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3]-2--1.0 | EventType: REMOVED | Old value: 2006.05.21 [IO-0090] 東方風櫻宴 Phantasmagoria mystical expectation [例大祭3] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:56:05.007  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: REMOVED | Old value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 12:56:06.178  INFO --- o.a.p.c.DownloadController               : Transferred 6983680 bytes to user: yatli, player: Sublime Music [yatli]
airsonic-airsonic-advanced-1  | 2023-04-28 12:56:06.178  INFO --- o.a.p.s.LoggingExceptionResolver         : 167.220.232.52: Client unexpectedly closed connection while loading https://music.yatao.info:10443/rest/download.view?id=130183&c=Sublime+Music&f=json&v=1.15.0&p=<hidden>&u=<hidden> (java.io.IOException: Connection reset by peer)
airsonic-airsonic-advanced-1  | 2023-04-28 12:56:06.179  INFO --- o.a.player.filter.RESTFilter             : 167.220.232.52: Client unexpectedly closed connection while loading https://music.yatao.info:10443/rest/download.view?id=130183&c=Sublime+Music&f=json&v=1.15.0&p=<hidden>&u=<hidden> (java.io.IOException: Connection reset by peer)

It's a tta encoded disc so the transcoder command is put together with random ffmpeg tutorials online.
The download manager logs 6983680 bytes transferred but my local network activity says otherwise. It was going at 2MB/s for a solid minute or more so apparently it downloaded the whole disc.

When there should be a track change, nothing is being logged on the server.

I also tried D-sub again, the client seems to be able to recognize a track change (sorry about the inaccurate initial report, must've been bad memory of me), but the track lengths are a bit off: the tail of the first track includes a bit of the following track, and when the track is being changed, it "rewinds" a little bit to the correct offset in the disc.

Taking a guess, the TTA encoder command is ignoring the lengths?

@kagemomiji
Copy link
Owner

@yatli
Could you replace Downsample command to ffmpeg %S -i %s -map 0:0 -b:a %bk -v 0 -f mp3 -

%S option is unique option of this repository. It will be replaced to the split option if audio file is indexed by cue sheet.

@yatli
Copy link
Author

yatli commented Apr 28, 2023 •
edited
Loading

Got it. Thank you!
Note to self:
was: ffmpeg -i %s -map 0:0 -b:a %bk -v 0 -f mp3 -
now: ffmpeg %S -i %s -map 0:0 -b:a %bk -v 0 -f mp3 -

@kagemomiji do I need to refresh the cache on the server somehow?

@kagemomiji
Copy link
Owner

@yatli
Yes. If you have cached audio files on your external player, you should clear them.

@yatli
Copy link
Author

yatli commented Apr 28, 2023 •
edited
Loading

looks like it's working now:

airsonic-airsonic-advanced-1  | 2023-04-28 15:48:05.210  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-ss][0.0][-t][540.0][-i][/var/music/Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:22.268  INFO --- o.a.p.c.StreamController                 : 167.220.232.52: yatli listening to 2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac in folder 0
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:22.269  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: CREATED | Old value: null | New value: 2007 - Systematic Chaos [RRCAR 7992-1]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:22.269  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: REMOVED | Old value: 2007 - Systematic Chaos [RRCAR 7992-1] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:22.270  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-ss][0.0][-t][540.0][-i][/var/music/Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:22.274  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: REMOVED | Old value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.415  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: CREATED | Old value: null | New value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.530  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 29194 | EventType: CREATED | Old value: null | New value: Constant Motion
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.531  INFO --- o.a.p.c.StreamController                 : 167.220.232.52: yatli listening to 2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac in folder 0
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.531  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 29194 | EventType: REMOVED | Old value: Constant Motion | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.531  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: CREATED | Old value: null | New value: 2007 - Systematic Chaos [RRCAR 7992-1]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.532  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: REMOVED | Old value: 2007 - Systematic Chaos [RRCAR 7992-1] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:43.533  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-ss][876.0][-t][416.0][-i][/var/music/Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:48.511  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 29193 | EventType: CREATED | Old value: null | New value: Forsaken
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:48.511  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 29193 | EventType: REMOVED | Old value: Forsaken | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:48.512  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: CREATED | Old value: null | New value: 2007 - Systematic Chaos [RRCAR 7992-1]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:48.512  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: REMOVED | Old value: 2007 - Systematic Chaos [RRCAR 7992-1] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:57.101  INFO --- o.a.p.c.StreamController                 : 167.220.232.52: yatli listening to 2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac in folder 0
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:57.102  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: CREATED | Old value: null | New value: 2007 - Systematic Chaos [RRCAR 7992-1]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:57.103  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]-0--1.0 | EventType: REMOVED | Old value: 2007 - Systematic Chaos [RRCAR 7992-1] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:57.103  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-ss][876.0][-t][416.0][-i][/var/music/Dream Theater/2007 - Systematic Chaos [RRCAR 7992-1]/Systematic Chaos.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-28 15:48:57.107  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: REMOVED | Old value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"] | New value: null

Track 1 length is 9:00, 540s
That [876.0][416.0] is probably the client prefetching.

@kagemomiji kagemomiji moved this from NoStatus to Todo in kagemomiji/airsonic-advanced project Apr 29, 2023
@kagemomiji kagemomiji added this to the 11.1.2 milestone Apr 29, 2023
@kagemomiji
Copy link
Owner

Todo: Write about this issue to document.

@kagemomiji kagemomiji self-assigned this Apr 29, 2023
kagemomiji added a commit that referenced this issue Apr 29, 2023
@kagemomiji
#195 add troubleshooting for cue sheet tracks do not end
6c630d7
@kagemomiji kagemomiji mentioned this issue Apr 29, 2023
Merged
kagemomiji added a commit that referenced this issue Apr 29, 2023
@kagemomiji
Merge pull request #205 from kagemomiji/issue195-documentation-cue-sheet
f34416d 
#195 add troubleshooting for cue sheet tracks do not end
@kagemomiji kagemomiji mentioned this issue Apr 30, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kagemomiji kagemomiji

Labels
bug Something isn't working
Projects
kagemomiji/airsonic-advanced project
Status: Done
Milestone
11.1.2
Development

Successfully merging a pull request may close this issue.

#195 add troubleshooting for cue sheet tracks do not end kagemomiji/airsonic-advanced
2 participants
@kagemomiji @yatli