Client unexpectedly closed connection while loading ... (java.io.IOException: Broken pipe)

[matthewrt]

Problem description

I am frequently experiencing a problem in song playback. Songs often stop partway through. When I look at the log I see a message like:
2021-06-16 20:15:22.681 INFO --- o.a.p.c.StreamController : 192.168.1.137: Client unexpectedly closed connection while loading http://192.168.1.149:8080/stream?player=2&id=19301 (java.io.IOException: Broken pipe)

I'm playing FLAC files without any transcoding.
I'm running Airsonic as root (I know that's a no-no, but I was having trouble with file permissions)
I'm scrobbling to Last.fm

Steps to reproduce

1. Start the Airsonic service.
2. Play a FLAC album from a remote client in a browser
3. Wait for a song to abruptly stop. This can be after only a couple songs. Or it might not happen for a couple hours.

System information

• Airsonic version: 10.6.2-RELEASE – May 3, 2020
• Operating system: Ubuntu 20.04 server (running on an Odroid xu4)
• Java version: Apache Tomcat/8.5.51, java 1.8.0_292, Linux (209.4 MB / 304.5 MB)
• Proxy server: None
• Client: Chrome Version 91.0.4472.106 (Official Build) (64-bit)
• Language: English

Additional notes

Here is the airsonic status information:
root@odroid:/var/airsonic# sudo service airsonic status
● airsonic.service - Airsonic Media Server
Loaded: loaded (/etc/systemd/system/airsonic.service; enabled; vendor preset: enabled)
Active: active (running) since Wed 2021-06-16 19:42:45 UTC; 48min ago
Main PID: 380 (java)
Tasks: 34 (limit: 4448)
Memory: 760.1M
CGroup: /system.slice/airsonic.service
└─380 /usr/bin/java -Xmx1024m -Dairsonic.home=/var/airsonic -Dserver.servlet.contextPath=/airsonic -Dserver.port=8080 -jar /var/airsonic/airsonic.war

Jun 16 20:12:44 odroid java[380]: 2021-06-16 20:12:44.808 INFO --- o.a.p.c.StreamController : Streaming request for [/media/usb/jukebox/Gabriel, Peter/[1990] Shaking the Tree (FLAC)/07 - Don't Give Up.flac] with range [>
Jun 16 20:12:44 odroid java[380]: 2021-06-16 20:12:44.810 INFO --- o.a.p.io.PlayQueueInputStream : 192.168.1.137: admin listening to [1990] Shaking the Tree (FLAC)/07 - Don't Give Up.flac
Jun 16 20:12:45 odroid java[380]: 2021-06-16 20:12:45.159 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered now playing for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:12:44 UTC 2021
Jun 16 20:13:57 odroid java[380]: 2021-06-16 20:13:57.338 INFO --- o.a.p.c.StreamController : 192.168.1.137: Client unexpectedly closed connection while loading http://192.168.1.149:8080/stream?player=2&id=19301 (java.n>
Jun 16 20:13:57 odroid java[380]: 2021-06-16 20:13:57.811 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered submission for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:13:57 UTC 2021
Jun 16 20:14:35 odroid java[380]: 2021-06-16 20:14:35.588 INFO --- o.a.p.c.StreamController : Streaming request for [/media/usb/jukebox/Gabriel, Peter/[1990] Shaking the Tree (FLAC)/07 - Don't Give Up.flac] with range [>
Jun 16 20:14:35 odroid java[380]: 2021-06-16 20:14:35.591 INFO --- o.a.p.io.PlayQueueInputStream : 192.168.1.137: admin listening to [1990] Shaking the Tree (FLAC)/07 - Don't Give Up.flac
Jun 16 20:14:35 odroid java[380]: 2021-06-16 20:14:35.956 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered now playing for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:14:35 UTC 2021
Jun 16 20:15:22 odroid java[380]: 2021-06-16 20:15:22.681 INFO --- o.a.p.c.StreamController : 192.168.1.137: Client unexpectedly closed connection while loading http://192.168.1.149:8080/stream?player=2&id=19301 (java.i>
Jun 16 20:15:23 odroid java[380]: 2021-06-16 20:15:23.025 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered submission for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:15:22 UTC 2021
lines 1-19/19 (END)

Here are the first few lines from top:
root@odroid:/var/airsonic# top
top - 20:25:18 up 42 min, 1 user, load average: 0.04, 0.06, 0.07
Tasks: 139 total, 1 running, 138 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.1 us, 0.2 sy, 0.0 ni, 99.5 id, 0.0 wa, 0.1 hi, 0.0 si, 0.0 st
MiB Mem : 1992.4 total, 963.5 free, 506.2 used, 522.7 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 1421.6 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
380 root 20 0 1252808 411524 10056 S 1.0 20.2 4:48.51 java
495 root 20 0 41988 15724 13632 S 0.0 0.8 0:00.21 smbd
396 root 20 0 31468 13960 9064 S 0.0 0.7 0:00.24 unattended-upgr
306 root 20 0 56412 12708 11084 S 0.0 0.6 0:00.75 NetworkManager
311 root 20 0 19256 11872 7028 S 0.0 0.6 0:00.23 networkd-dispat
225 root 19 -1 28668 11664 10956 S 0.0 0.6 0:00.85 systemd-journal
499 root 20 0 41988 10468 8376 S 0.0 0.5 0:00.07 lpqd
443 root 20 0 28888 9060 7524 S 0.7 0.4 0:01.29 nmbd
300 systemd+ 20 0 18052 8528 5456 S 0.0 0.4 0:00.25 systemd-resolve
378 root 20 0 53784 8268 6188 S 0.0 0.4 0:00.82 ModemManager
1 root 20 0 33440 7756 5456 S 0.0 0.4 0:05.21 systemd
541 root 20 0 14204 7076 5384 S 0.0 0.3 0:01.06 systemd
538 root 20 0 11504 6024 4876 S 0.3 0.3 0:04.64 sshd

Here are the last few lines from airsonic.log:
2021-06-16 19:44:05.537 INFO --- l.l.StandardLockService : Successfully released change log lock
2021-06-16 19:44:06.178 INFO --- o.a.p.service.SettingsService : Java: 1.8.0_292, OS: Linux
2021-06-16 19:44:07.371 INFO --- org.airsonic.player.Application : Detected Tomcat web server
2021-06-16 19:44:37.121 INFO --- o.a.p.service.PodcastService : Automatic Podcast update scheduled to run every 24 hour(s), starting at Wed Jun 16 19:49:37 UTC 2021
2021-06-16 19:44:38.924 INFO --- o.a.p.s.search.IndexManager : Index was found (index version 18).
2021-06-16 19:44:38.960 INFO --- o.a.p.s.MediaScannerService : Automatic media library scanning scheduled to run every 1 day(s), starting at 2021-06-17T03:00:00.957
2021-06-16 19:44:58.969 INFO --- org.airsonic.player.Application : Started Application in 129.184 seconds (JVM running for 134.32)
2021-06-16 19:45:42.351 INFO --- o.a.p.f.BootstrapVerificationFilter : Servlet container: Apache Tomcat/8.5.51
2021-06-16 19:49:37.120 INFO --- o.a.p.service.PodcastService : Starting scheduled Podcast refresh.
2021-06-16 19:49:37.138 INFO --- o.a.p.service.PodcastService : Completed scheduled Podcast refresh.
2021-06-16 19:49:38.795 INFO --- o.a.p.service.VersionService : Resolved local Airsonic version to: 10.6.2-RELEASE

...

2021-06-16 20:12:45.159 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered now playing for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:12:44 UTC 2021
2021-06-16 20:13:57.338 INFO --- o.a.p.c.StreamController : 192.168.1.137: Client unexpectedly closed connection while loading http://192.168.1.149:8080/stream?player=2&id=19301 (java.net.SocketTimeoutException)
2021-06-16 20:13:57.811 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered submission for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:13:57 UTC 2021
2021-06-16 20:14:35.588 INFO --- o.a.p.c.StreamController : Streaming request for [/media/usb/jukebox/Gabriel, Peter/[1990] Shaking the Tree (FLAC)/07 - Don't Give Up.flac] with range [bytes 12828086-28621490/28621491]
2021-06-16 20:14:35.591 INFO --- o.a.p.io.PlayQueueInputStream : 192.168.1.137: admin listening to [1990] Shaking the Tree (FLAC)/07 - Don't Give Up.flac
2021-06-16 20:14:35.956 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered now playing for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:14:35 UTC 2021
2021-06-16 20:15:22.681 INFO --- o.a.p.c.StreamController : 192.168.1.137: Client unexpectedly closed connection while loading http://192.168.1.149:8080/stream?player=2&id=19301 (java.io.IOException: Broken pipe)
2021-06-16 20:15:23.025 INFO --- o.a.p.s.s.LastFMScrobbler : Successfully registered submission for song 'Don't Give Up' for user mfrt at Last.fm: Wed Jun 16 20:15:22 UTC 2021

[matthewrt]

So, it looks like this is indeed a FLAC decoding issue, possibly relating to this: https://bugzilla.mozilla.org/show_bug.cgi?id=1528265

If I transcode flac to flac [ffmpeg -i %s -c:a flac -f flac -] problematic flac files (or their clones, to be precise) play properly. The drawback here is that there is additional transcoding overhead which delays the start of each track. We also lose track scanning and length data.

The more laborious solution is to manually replace problematic files. I've found that using the flac encoder directly doesn't necessarily fix the problem. Flac re-encoded using ffmpeg seem to play correctly.