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
- Start the Airsonic service.
- Play a FLAC album from a remote client in a browser
- 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
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
System information
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