Loops all songs on album, only plays each for 2 seconds

[alfalfascout]

Steps to reproduce: Connect to DLNA server. Browse music by albums, pick an album. Tap a song.

Now, the player will cycle through all the songs on the album, playing each one for less than two seconds. Or it might crash after a few songs. Had that happen too.

I kind of want to listen to the whole song, specifically the song that I tapped. I wonder if that's not what a DLNA server is for. This is my first time using one. I tried changing the default item duration to 60 seconds but that hasn't made a difference.

For reference, I'm on a BLU R1 HD running Android 6. The server is shown as Buffalo Inc Linkstation 7.1.1.

[tobexyz]

maybe it's a problem parsing the duration information of the songs given by the DLNA server. Please take a look in the log of yaacc and look for any error messages.

[alfalfascout]

I get a bunch of errors like this one:

04-01 22:33:22.288 11251 11251 E MediaPlayer: java.io.FileNotFoundException: No content provider: http://SERVER_IP/disk/NON-DLNA-OP01-FLAGS01700000/O0$1$8I10507.flac
04-01 22:33:22.288 11251 11251 E MediaPlayer: setDataSource: IOException! uri=http://SERVER_IP/disk/NON-DLNA-OP01-FLAGS01700000/O0$1$8I10507.flac
04-01 22:33:22.223 11251 11262 W MediaHTTPConnection: readAt 6139520 / 20864 => java.net.ProtocolException: unexpected end of stream
04-01 22:33:20.165 11251 11251 I DefaultOmaSettingHelper: setOmaSettingHeader(de.yaacc.musicplayer.BackgroundMusicService@c8267cf,null)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:679)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:789)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at java.lang.reflect.Method.invoke(Native Method)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.app.ActivityThread.main(ActivityThread.java:5765)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.os.Looper.loop(Looper.java:207)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.os.Handler.dispatchMessage(Handler.java:104)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.os.Handler.handleCallback(Handler.java:815)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:922)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at de.yaacc.musicplayer.BackgroundMusicBroadcastReceiver.onReceive(BackgroundMusicBroadcastReceiver.java:70)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at de.yaacc.musicplayer.BackgroundMusicService.setMusicUri(BackgroundMusicService.java:187)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.media.MediaPlayer.setDataSource(MediaPlayer.java:983)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.media.MediaPlayer.setDataSource(MediaPlayer.java:1018)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.content.ContentResolver.openAssetFileDescriptor(ContentResolver.java:881)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.content.ContentResolver.openAssetFileDescriptor(ContentResolver.java:958)
04-01 22:33:20.164 11251 11251 E MediaPlayer: at android.content.ContentResolver.openTypedAssetFileDescriptor(ContentResolver.java:1123)
04-01 22:33:20.164 11251 11251 E MediaPlayer: java.io.FileNotFoundException: No content provider: http://SERVER_IP/disk/NON-DLNA-OP01-FLAGS01700000/O0$1$8I10251.flac
04-01 22:33:20.164 11251 11251 E MediaPlayer: setDataSource: IOException! uri=http://SERVER_IP/disk/NON-DLNA-OP01-FLAGS01700000/O0$1$8I10251.flac
04-01 22:33:20.112 11251 11263 W MediaHTTPConnection: readAt 5564664 / 5896 => java.net.ProtocolException: unexpected end of stream

It strikes me as strange, because I can listen to the same DLNA server in foobar2000 and it sounds normal.

Here's more of the log from when the program started up:

04-01 22:33:04.635 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:33:04.635 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:33:03.587 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:33:03.587 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:33:02.710 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:33:02.710 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:33:00.430 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:33:00.430 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:33:00.326 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:33:00.325 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:32:59.477 11251 11251 W InputEventReceiver: Attempted to finish an input event but the input event receiver has already been disposed.
04-01 22:32:52.751 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:32:52.751 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:32:51.310 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:32:51.310 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:32:51.269 11251 11269 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:32:51.269 11251 11269 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:32:51.171 11251 11251 E MultiWindowProxy: getServiceInstance failed!
04-01 22:32:45.123 11251 11301 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:32:45.123 11251 11301 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:32:44.994 11251 11301 I SAXParser: can't set factory.setXIncludeAware(false);
04-01 22:32:44.993 11251 11301 I SAXParser: Feature disallow-doctype-decl not known
04-01 22:32:43.985 11251 11251 I Router : No actual network change... ignoring event!
04-01 22:32:43.984 11251 11251 I Router : EXTRA_EXTRA_INFO: null
04-01 22:32:43.984 11251 11251 I Router : EXTRA_OTHER_NETWORK_INFO: none
04-01 22:32:43.984 11251 11251 I Router : EXTRA_NETWORK_INFO: [type: VPN[], state: DISCONNECTED/DISCONNECTED, reason: (unspecified), extra: (none), roaming: false, failover: false, isAvailable: false]
04-01 22:32:43.984 11251 11251 I Router : EXTRA_IS_FAILOVER: false
04-01 22:32:43.983 11251 11251 I Router : EXTRA_REASON: null
04-01 22:32:43.983 11251 11251 I Router : EXTRA_NO_CONNECTIVITY: false
04-01 22:32:43.983 11251 11251 I Router : Connectivity change detected...
04-01 22:32:43.922 11251 11251 I UpnpServiceImpl: <<< UPnP service started successfully
04-01 22:32:43.918 11251 11251 I Router : WiFi lock acquired
04-01 22:32:43.903 11251 11251 I Router : WiFi multicast lock acquired
04-01 22:32:43.884 11251 11251 I StreamClient: Starting Jetty HttpClient...
04-01 22:32:43.881 11251 11269 I JettyServletContainer: Starting Jetty server...
04-01 22:32:43.880 11251 11251 I DatagramIO: Creating bound socket (for datagram input/output) on: 192.168.50.243/192.168.50.243
04-01 22:32:43.867 11251 11251 I JettyServletContainer: Registering UPnP servlet under context path: /upnp
04-01 22:32:43.760 11251 11251 I MulticastReceiver: Joining multicast group: /239.255.255.250:1900 on network interface: wlan0
04-01 22:32:43.757 11251 11251 I MulticastReceiver: Creating wildcard socket (for receiving multicast datagrams) on port: 1900
04-01 22:32:43.732 11251 11251 I Router : Creating Router: org.fourthline.cling.android.AndroidRouter
04-01 22:32:43.730 11251 11251 I UpnpServiceImpl: Using configuration: de.yaacc.upnp.UpnpRegistryService$1
04-01 22:32:43.730 11251 11251 I UpnpServiceImpl: >>> Starting UPnP service...
04-01 22:32:43.659 11251 11251 E MultiWindowProxy: getServiceInstance failed!
04-01 22:32:43.595 11251 11251 E MultiWindowProxy: getServiceInstance failed!
--------- beginning of main

[tobexyz]

I think the problem is in the configuration of your upnp server. This line of the log java.io.FileNotFoundException: No content provider: http://SERVER_IP/disk/NON-DLNA-OP01-FLAGS01700000/O0$1$8I10251.flac points out that the file can't be loaded. I think you have to set the Variable SERVER_IP in the configuration of the upnp server

[ccpp]

I found the same issue and found out: it's the silence duration setting that controls how many seconds of a song are played

[tobexyz]

The silence duration is the time between two tracks. If the file can't be loaded or maybe not played, yaacc switches automatically to the next track after the silence duration. So the root cause might be found in the log. Maybe there is an error reported while loading the file

[tobexyz]

@ccpp does your problem persist with version 3.0.0?

[ccpp]

Sorry for the late answer, I could test tag 3.0.0 now. The problem persists. My log file is similar to the one posted by @alfalfascout , but has an explicit and correct IP address:

(...) mediaplayer went away with unhandled events
01-10 19:02:38.091  1036  1036 W MediaPlayer: mediaplayer went away with unhandled events
01-10 19:02:36.237  1036  1036 W MediaPlayer: Couldn't open http://192.168.178.1:49200/AUDIO/DLNA-1-0/Generic-FlashDisk-01/Radiosendungen/oe1-2018-09-19_2100_tl_51_7DaysWed46_768561-Seeanemone.mp3: java.io.FileNotFoundException: No content provider: http://192.168.178.1:49200/AUDIO/DLNA-1-0/Generic-FlashDisk-01/Radiosendungen/oe1-2018-09-19_2100_tl_51_7DaysWed46_768561-Seeanemone.mp3
01-10 19:02:34.174  1036  1036 W MediaPlayer: Couldn't open http://192.168.178.1:49200/AUDIO/DLNA-1-0/Generic-FlashDisk-01/Radiosendungen/oe1-2018-09-19_2100_tl_51_7DaysWed46_768561-Seeanemone.mp3: java.io.FileNotFoundException: No content provider: http://192.168.178.1:49200/AUDIO/DLNA-1-0/Generic-FlashDisk-01/Radiosendungen/oe1-2018-09-19_2100_tl_51_7DaysWed46_768561-Seeanemone.mp3
01-10 19:02:34.156  1036  1036 W MediaPlayer: mediaplayer went away with unhandled events
01-10 19:02:34.156  1036  1036 W MediaPlayer: mediaplayer went away with unhandled events
01-10 19:02:32.152  1036  1036 W MediaPlayer: Couldn't open http://192.168.178.1:49200/AUDIO
(...)

[tobexyz]

are you able to play the url http://192.168.178.1:49200/AUDIO/DLNA-1-0/Generic-FlashDisk-01/Radiosendungen/oe1-2018-09-19_2100_tl_51_7DaysWed46_768561-Seeanemone.mp3 by pasting it in a browser?

If not, something with the Url is wrong. If you are able to retrieve the content we need to have a deeper look what's wrong with that

[ccpp]

Yes I can play the URL with a different player on the same device. And yaacc plays the same content until "silence duration" is over. Obviously the error message "No content provider" is thrown wrongly

[tobexyz]

Interesting the exception is thrown by the media player. I do not understand what's going wrong. There's nothing special in the code just setting the Uri on the player object, that's all:

https://github.com/tobexyz/yaacc-code/blob/develop/yaacc/src/main/java/de/yaacc/musicplayer/BackgroundMusicService.java#L217

[ccpp]

In logcat, I see a different exception, thrown almost exactly where you pointed:

01-11 22:56:23.769   495   927 D NuPlayerDriver: notifyListener_l(0xaaa9d310), (100, 1, -2147483648, -1), loop setting(0, 0)
01-11 22:56:23.770   642   900 E MediaPlayerNative: error (1, -2147483648)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService: Exception while changing datasource uri
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService: java.io.IOException: Prepare failed.: status=0x1
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.media.MediaPlayer._prepare(Native Method)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.media.MediaPlayer.prepare(MediaPlayer.java:1293)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at de.yaacc.musicplayer.BackgroundMusicService.setMusicUri(BackgroundMusicService.java:223)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at de.yaacc.musicplayer.BackgroundMusicBroadcastReceiver.onReceive(BackgroundMusicBroadcastReceiver.java:66)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.app.LoadedApk$ReceiverDispatcher$Args.lambda$-android_app_LoadedApk$ReceiverDispatcher$Args_53280(LoadedApk.java:1356)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.app.-$Lambda$aS31cHIhRx41653CMnd4gZqshIQ.$m$7(Unknown Source:4)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.app.-$Lambda$aS31cHIhRx41653CMnd4gZqshIQ.run(Unknown Source:39)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.os.Handler.handleCallback(Handler.java:790)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.os.Handler.dispatchMessage(Handler.java:99)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.os.Looper.loop(Looper.java:169)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at android.app.ActivityThread.main(ActivityThread.java:7000)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at java.lang.reflect.Method.invoke(Native Method)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:477)
01-11 22:56:23.771   642   642 E de.yaacc.musicplayer.BackgroundMusicService:   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:809)

[tobexyz]

I found a few post about similar problems, maybe its only a problem with the configuration of the media player object. I changed them on branch feat/issue31 Please install the app based on that branch and try to play the item

[ccpp]

No, that did not solve it.

But I got one step forward with No content provider: Please check this identical bug and accepted answer: Problem is: wrong override of setDataSource is being used; use setDataSource(String) instead of setDataSource(Context, Uri), because the latter expects a content: URI.

diff --git a/yaacc/src/main/java/de/yaacc/musicplayer/BackgroundMusicService.java b/yaacc/src/main/java/de/yaacc/musicplayer/BackgroundMusicService.java
index 2abaaac..bab8887 100644
--- a/yaacc/src/main/java/de/yaacc/musicplayer/BackgroundMusicService.java
+++ b/yaacc/src/main/java/de/yaacc/musicplayer/BackgroundMusicService.java
@@ -219,7 +219,7 @@ public class BackgroundMusicService extends Service {
                             .build());
             player.setOnPreparedListener(mediaPlayer ->
                     duration = player.getDuration());
-            player.setDataSource(this, uri);
+            player.setDataSource(uri.toString());
             //player.prepareAsync();

             player.prepare();

This fixes the FileNotFoundException. However, it does not resolve this "looping" issue, and the _prepare exception now shows up in the yaacc log window: (side question: I just found that log lines are reversed in the log window, so stack traces come before exception message... why is that so?)

01-17 00:56:39.459  3987  3987 E de.yaacc.musicplayer.BackgroundMusicService:  at android.media.MediaPlayer._prepare(Native Method)
01-17 00:56:39.459  3987  3987 E de.yaacc.musicplayer.BackgroundMusicService: java.io.IOException: Prepare failed.: status=0x1
01-17 00:56:39.459  3987  3987 E de.yaacc.musicplayer.BackgroundMusicService: Exception while changing datasource uri

(...)

01-17 00:56:30.133  3987  3987 E MediaPlayer: Error (-38,0)
01-17 00:56:30.132  3987  3987 E MediaPlayerNative: error (-38, 0)

According to further research these two lines mean that the media player is "prepared" while already playing (one solution could be to start .play in an onPrepare callback, as in this solution ).

[tobexyz]

Great! Many thanks for your investigation. Maybe we've got two problems with that URLs the way the URL is set and the current state of the media player. What I am wondering about is, that the problem not always occurs.

Regarding the ordering of the log I will take a look at it, it seems to be easy to fix

[ccpp]

Maybe instead of player.release() you should call player.stop() and player.reset(). This would place the player out of the playing state.

(Edit) another possibility would be that, when in playing state, setDataSource alone successfully transits to the next song, and .prepare() is not necessary anymore... it just causes the exception that makes yaacc think the transition was unsuccessful

[tobexyz]

I changed the code a bit based on your recommendation. Please give it another try.

[ccpp]

[edit] Sorry, that was a step back... Now the music player does not even play music and does not even count seconds; still switches after silence duration. Didn't you get the same behaviour?

I have another suspicion. Can it be that getDuration() is called too early, when it is still set to 0, and before onPrepared() is fired? E.g. in AbstractPlayer::loadItem(), you set a timer:

if(playableItem.getDuration() > -1) {   // !!! this includes zero duration
    //Only start timer if automatic track change is active
    startTimer(playableItem.getDuration() + getSilenceDuration());   // !!! Could be the 2 seconds
}

[tobexyz]

Interesting behaviour on your side. On my device the titles are starting correctly. Does your behaviour is the same also for other titles? Maybe there is also a problem depending on the content? But that's all only a guess...

[ccpp]

I played around more with the music player and found:

• Songs do play, except for some cases I am still trying to identify
• If I interact with the music player (skip forward, pause, continue...) the app will still interrupt after silence duration.
• I conclude that the log entries and exceptions we found in this thread have nothing to do with #31. Instead it's the logic that decides when to jump to the next song, implemented in AbstractPlayer in my quote above. Instead, the app should wait until the media player reports to have arrived at the end (wit or without manual skipping forward/backwards), and set the timer with only silence duration in this case.

[tobexyz]

Hi, first of all thank you for your help finding the root cause! I think you are right the 2 seconds are the silence duration. Currently the app is using a duration timer when playing on remote devices. Because the playlist is hold by the app. That's what I understood from UPNP in former times and for remote devices it works more ore less :-) The same solution is used controlling the local media player. That's not the best solution because it should be possible to use event listener instead of the timer. That's also the reason for issue #61 I think.

It would be interesting if the title can be played manually if the timer for the next command will be commend out on line https://github.com/tobexyz/yaacc-code/blob/083a0dfbbe296ce64aa40a565be3b554f0af19aa/yaacc/src/main/java/de/yaacc/player/AbstractPlayer.java#L494

[ccpp]

I tested what you suggested. Removing this line of code permits one to listen to the entire track instead of going to the next track after silence period. So it was really that method that was calling getDuration() too early.

Regarding my statement that music wouldn't play: you were right, that was about content; those were corrupted .m4a files, no clue how that happened. Still, they were indexed by the upnp server, and yaacc music player shows their name and a duration, without switching to the next.

[tobexyz]

Cool, it seems we're getting closer! Now we hat to get a clue how to wait until getDuration() is ready to return a valid value, without refactoring the whole BackgroundMusicPlayer :-)

[ccpp]

My suggestion: forget about getDuration(). Instead, check the receiver's progress.

For local player this would be MusicPlayerActivity::doSetTrackInfo and react on the case progress == 100.

I think this should be possible by tracking uPnP's GetPositionInfo call? And somewhere else also check for player not playing because of unplayable media.

[tobexyz]

ok, let's give it a try. The local music player now is using a callback on completion for switching to the next song instead of the duration timer. That fixes also #61 for local music playback

[ccpp]

👍 c69abbcd838644 works well for me (local player tested only, and even invalid media files automatically skip to the next)

[tobexyz]

great issue completed :-) thanks for your help. fix will be part of next release.