Playback of Bandcamp ALAC songs cut off prematurely

[numinit 0]

When playing certain ALAC songs downloaded from Bandcamp, the playback abruptly stops ~86% through the song. Moving the seek bar forward does nothing.

 

 

Logs are attached. If you would like an example song, let me know.

server.txt

ffmpeg-transcode-7285ff4d-bf0f-4ed2-921d-bc7b5d8bf908.txt

Edited September 10, 2018 by numinit

[numinit 0]

OK, did some debugging myself. This seems like a client issue.

 

The M3U8 playlist generated ends like this:

#EXTINF:3.0000, nodesc
hls1/main/90.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXTINF:3.0000, nodesc
hls1/main/91.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXTINF:3.0000, nodesc
hls1/main/92.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXTINF:3.0000, nodesc
hls1/main/93.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXTINF:3.0000, nodesc
hls1/main/94.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXTINF:3.0000, nodesc
hls1/main/95.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXTINF:1.8980, nodesc
hls1/main/96.ts?UserId=7eb7544e9e3245fba42efb682895bb9b&DeviceId=TW96aWxsYS81LjAgKE1hY2ludG9zaDsgSW50ZWwgTWFjIE9TIFggMTBfMTNfNikgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzY4LjAuMzQ0MC4xMDYgU2FmYXJpLzUzNy4zNnwxNTM0ODM2MTkwNDE1&MaxStreamingBitrate=140000000&Container=opus%2Cmp3%7Cmp3%2Caac%2Cm4a%7Caac%2Cflac%2Cwebma%2Cwebm%2Cwav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&api_key=04fc489ae24a43a1aa52e86fb00c4d82&PlaySessionId=1536554922762&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false&SegmentContainer=ts&AudioBitrate=384000&TranscodeReasons=AudioCodecNotSupported
#EXT-X-ENDLIST

This is what I see in the network inspector.

 

 

84 is the last one fetched in the first batch. Later, it fetches the ones at the end (95/96.ts), which are indeed the end of the song (I verified with VLC), but never seems to play them.

[Luke 37112]

Hi, yes an example would be great, thanks.

[numinit 0]

Attached. Thanks for taking a look.

 

edit: Let me know once you download it so I can delete it.

edit 2: deleted

Edited September 20, 2018 by numinit

[Luke 37112]

Can you update to the latest version of Emby Server? Thanks.

[numinit 0]

Still appears to be happening. Here's the transcode log for Emby 3.5.2.

ffmpeg-transcode-4ae20226-e690-4059-962d-f69d4db33515.txt

[Luke 37112]

What install package are you using? that is not the ffmpeg build we are shipping.

[numinit 0]

I'm using the version of Emby packaged with NixOS. Yeah, the maintainers of that package used the ffmpeg bundled with NixOS. That sounds like it might be the problem.

Here's the startup log - notice that they have a wrapper around Emby that adds the -ffmpeg and -ffprobe arguments. Those paths are NixOS' ffmpeg and ffprobe packages; wonder if there's some known issue with those involving timestamping.

In any case, thanks for the help; I'll see if I can bring that issue up with the maintainers.
 

2018-09-20 06:30:52.882 Info Main: Emby
Command line: /nix/store/npzdaccqd0k37zb6zv6hzva5y5ifkjsj-emby-3.5.2.0/bin/MediaBrowser.Server.Mono.exe -ffmpeg /nix/store/3274k30sa4zfcprgy37dv4nazyal4lnj-ffmpeg-3.4.4-bin/bin/ffmpeg -ffprobe /nix/store/3274k30sa4zfcprgy37dv4nazyal4lnj-ffmpeg-3.4.4-bin/bin/ffprobe
Operating system: Unix 4.14.67.1
64-Bit OS: True
64-Bit Process: True
User Interactive: False
Mono: 5.4.1.6 (tarball Sat Sep 1 11:04:27 UTC 2018)
Processor count: 12
Program data path: /var/lib/emby/ProgramData-Server
Application directory: /nix/store/npzdaccqd0k37zb6zv6hzva5y5ifkjsj-emby-3.5.2.0/bin
2018-09-20 06:30:53.105 Info App: Application version: 3.5.2.0
2018-09-20 06:30:53.106 Info App: Loading assemblies
2018-09-20 06:30:53.109 Info App: File /var/lib/emby/ProgramData-Server/plugins/Emby.Server.CinemaMode.dll has version 1.0.2.0
2018-09-20 06:30:53.110 Info App: File /nix/store/npzdaccqd0k37zb6zv6hzva5y5ifkjsj-emby-3.5.2.0/bin/plugins/Emby.Server.CinemaMode.dll has version 1.0.2.0
2018-09-20 06:30:53.110 Info App: File /var/lib/emby/ProgramData-Server/plugins/IMVDb.dll has version 1.0.1.0
2018-09-20 06:30:53.110 Info App: File /nix/store/npzdaccqd0k37zb6zv6hzva5y5ifkjsj-emby-3.5.2.0/bin/plugins/IMVDb.dll has version 1.0.1.0
2018-09-20 06:30:53.110 Info App: File /var/lib/emby/ProgramData-Server/plugins/OpenSubtitles.dll has version 1.0.2.0
2018-09-20 06:30:53.110 Info App: File /nix/store/npzdaccqd0k37zb6zv6hzva5y5ifkjsj-emby-3.5.2.0/bin/plugins/OpenSubtitles.dll has version 1.0.2.

[snip]

2018-09-20 06:30:56.136 Info MediaEncoder: FFMpeg: /nix/store/3274k30sa4zfcprgy37dv4nazyal4lnj-ffmpeg-3.4.4-bin/bin/ffmpeg
2018-09-20 06:30:56.136 Info MediaEncoder: FFProbe: /nix/store/3274k30sa4zfcprgy37dv4nazyal4lnj-ffmpeg-3.4.4-bin/bin/ffprobe
2018-09-20 06:30:56.137 Info MediaEncoder: Validating media encoder at /nix/store/3274k30sa4zfcprgy37dv4nazyal4lnj-ffmpeg-3.4.4-bin/bin/ffmpeg
2018-09-20 06:30:56.138 Info MediaEncoder: Running /nix/store/3274k30sa4zfcprgy37dv4nazyal4lnj-ffmpeg-3.4.4-bin/bin/ffmpeg -decoders

Edited September 20, 2018 by numinit

[Luke 37112]

It still could be an issue within Emby, I'm not trying to point fingers.

[Luke 37112]

What browser were you playing in?

[numinit 0]

Did some more testing. I'm using Chrome 69.0.3497.100. I also tried a completely separate user profile in Chrome without any extensions (to isolate adblock, etc); the same problematic song stops on 4:11.

 

Tried Firefox, it works there.

 

Re-attaching the zipped song; this doesn't really seem like ffmpeg anymore.

 

edit: song once again deleted.

Edited September 24, 2018 by numinit

[Luke 37112]

And just this one song?

[numinit 0]

Songs from the same album seem affected as well. I've seen a few other ALAC songs from Bandcamp exhibit similar behavior, but not all of them.

[Luke 37112]

Ok yes i can reproduce this. The problem might be in the hls.js library that we're using as this is only happening in browsers that require us to use that.