{"action":"created","issue":{"url":"https://api.github.com/repos/daneren2005/Subsonic/issues/481","labels_url":"https://api.github.com/repos/daneren2005/Subsonic/issues/481/labels{/name}","comments_url":"https://api.github.com/repos/daneren2005/Subsonic/issues/481/comments","events_url":"https://api.github.com/repos/daneren2005/Subsonic/issues/481/events","html_url":"https://github.com/daneren2005/Subsonic/issues/481","id":65960456,"number":481,"title":"Sometimes when connected to a bluetooth audio device, DSub fails to play and must be force-closed.","user":{"login":"dpedu","id":1266188,"avatar_url":"https://avatars.githubusercontent.com/u/1266188?v=3","gravatar_id":"","url":"https://api.github.com/users/dpedu","html_url":"https://github.com/dpedu","followers_url":"https://api.github.com/users/dpedu/followers","following_url":"https://api.github.com/users/dpedu/following{/other_user}","gists_url":"https://api.github.com/users/dpedu/gists{/gist_id}","starred_url":"https://api.github.com/users/dpedu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dpedu/subscriptions","organizations_url":"https://api.github.com/users/dpedu/orgs","repos_url":"https://api.github.com/users/dpedu/repos","events_url":"https://api.github.com/users/dpedu/events{/privacy}","received_events_url":"https://api.github.com/users/dpedu/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2015-04-02T16:12:51Z","updated_at":"2015-04-07T00:17:33Z","closed_at":"2015-04-06T15:46:45Z","body":"DSub: 4.9.5\r\nAndroid: 5.1\r\nDevice: Nexus 5\r\n\r\nSometimes, when I connect my phone to a bluetooth audio device while DSub is open, DSub fails to play audio. With an already-cached piece of media: after pressing play, the play button turns to the pause button as normal. However, the time does not advance, and no audio is heard. DSub must then be force closed for it to work again; simply swiping it out of the task switcher does not work. It must be completely relaunched.\r\n\r\nLogs:\r\n\r\n```\r\n--------- beginning of system\r\n04-01 16:41:36.091 W/ResourcesManager(25396): Asset path '/system/framework/android.test.runner.jar' does not exist or contains no resources.\r\n--------- beginning of main\r\n04-01 16:41:45.396 E/MediaPlayer(25396): Should have subtitle controller already set\r\n04-01 16:41:45.396 I/DownloadService(25396): Next: PREPARING -> PREPARED (DownloadFile (Bloodstream))\r\n04-01 16:41:46.527 W/RESTMusicService(25396): Got IOException java.net.UnknownHostException: Unable to resolve host \"myserver.com\": No address associated with hostname (4), will retry\r\n04-01 16:41:48.529 E/DownloadServiceLifecycleSupport(25396): Failed to save playing queue to server\r\n04-01 16:45:09.064 I/DownloadService(25396): STARTED -> PAUSED (DownloadFile (Exit))\r\n04-01 16:45:09.098 I/DownloadServiceLifecycleSupport(25396): Serialized currentPlayingIndex: 1, currentPlayingPosition: 208429\r\n04-01 16:45:09.100 I/RESTMusicService(25396): https://myserver.com/rest/savePlayQueue.view?v=1.2.0&c=DSub\r\n04-01 16:45:09.172 W/RESTMusicService(25396): Got IOException java.net.UnknownHostException: Unable to resolve host \"myserver.com\": No address associated with hostname (1), will retry\r\n04-01 16:45:11.174 W/RESTMusicService(25396): Got IOException java.net.UnknownHostException: Unable to resolve host \"myserver.com\": No address associated with hostname (2), will retry\r\n04-01 16:45:13.184 W/RESTMusicService(25396): Got IOException java.net.UnknownHostException: Unable to resolve host \"myserver.com\": No address associated with hostname (3), will retry\r\n04-01 16:45:15.187 W/RESTMusicService(25396): Got IOException java.net.UnknownHostException: Unable to resolve host \"myserver.com\": No address associated with hostname (4), will retry\r\n04-01 16:45:17.204 E/DownloadServiceLifecycleSupport(25396): Failed to save playing queue to server\r\n04-01 16:45:19.169 I/art     (25396): Background sticky concurrent mark sweep GC freed 15900(779KB) AllocSpace objects, 2(32KB) LOS objects, 0% free, 50MB/50MB, paused 12.434ms total 59.721ms\r\n04-01 16:45:19.305 W/SupportMenuInflater(25396): Ignoring attribute 'actionProviderClass'. Action view already specified.\r\n04-01 16:45:31.961 I/Router  (25396): Connectivity change detected...\r\n04-01 16:45:31.961 I/Router  (25396): EXTRA_NO_CONNECTIVITY: false\r\n04-01 16:45:31.961 I/Router  (25396): EXTRA_REASON: null\r\n04-01 16:45:31.961 I/Router  (25396): EXTRA_IS_FAILOVER: false\r\n04-01 16:45:31.961 I/Router  (25396): EXTRA_NETWORK_INFO: [type: MOBILE[HSPA], state: CONNECTED/CONNECTED, reason: (unspecified), extra: fast.t-mobile.com, roaming: false, failover: false, isAvailable: true, isConnectedToProvisioningNetwork: false]\r\n04-01 16:45:31.961 I/Router  (25396): EXTRA_OTHER_NETWORK_INFO: none\r\n04-01 16:45:31.961 I/Router  (25396): EXTRA_EXTRA_INFO: fast.t-mobile.com\r\n04-01 16:45:32.024 I/Router  (25396): Network type changed  => MOBILE\r\n04-01 16:45:32.095 W/tworkAddressFactoryImpl(25396): Network interface may not be multicast capable: rmnet0\r\n04-01 16:45:32.166 I/MulticastReceiver(25396): Creating wildcard socket (for receiving multicast datagrams) on port: 1900\r\n04-01 16:45:32.176 I/MulticastReceiver(25396): Joining multicast group: /239.255.255.250:1900 on network interface: rmnet0\r\n04-01 16:45:32.225 I/StreamServer(25396): Setting executor service on servlet container adapter\r\n04-01 16:45:32.226 I/StreamServer(25396): Adding connector: 22.165.198.176/22.165.198.176:0\r\n04-01 16:45:32.799 I/JettyServletContainer(25396): Registering UPnP servlet under context path: /upnp\r\n04-01 16:45:32.805 I/DatagramIO(25396): Creating bound socket (for datagram input/output) on: 22.165.198.176/22.165.198.176\r\n04-01 16:45:32.805 I/JettyServletContainer(25396): Starting Jetty server... \r\n04-01 16:45:32.819 I/StreamClient(25396): Starting Jetty HttpClient...\r\n04-01 16:45:32.842 I/Router  (25396): Enabled router on network type change (new network: MOBILE)\r\n04-01 16:45:34.405 W/ResourcesManager(26893): Asset path '/system/framework/android.test.runner.jar' does not exist or contains no resources.\r\n04-01 16:45:34.884 W/SubsonicSyncAdapter(26893): Not running sync, not connected to wifi\r\n04-01 16:45:35.173 W/SubsonicSyncAdapter(26893): Not running sync, not connected to wifi\r\n04-01 16:45:47.032 I/DownloadService(25396): PAUSED -> STARTED (DownloadFile (Exit))\r\n04-01 16:45:47.208 I/RESTMusicService(25396): https://myserver.com/rest/scrobble.view?v=1.2.0&c=DSub&id=7524&submission=false\r\n04-01 16:45:49.044 I/Scrobbler(25396): Scrobbled 'now playing' for DownloadFile (Exit)\r\n04-01 16:45:52.993 I/DownloadService(25396): STARTED -> PAUSED (DownloadFile (Exit))\r\n04-01 16:45:52.999 I/DownloadServiceLifecycleSupport(25396): Serialized currentPlayingIndex: 1, currentPlayingPosition: 208496\r\n04-01 16:45:53.051 I/RESTMusicService(25396): https://myserver.com/rest/savePlayQueue.view?v=1.2.0&c=DSub\r\n04-01 16:45:54.565 W/IInputConnectionWrapper(25396): showStatusIcon on inactive InputConnection\r\n04-01 16:45:58.412 I/DownloadService(25396): PAUSED -> STARTED (DownloadFile (Exit))\r\n04-01 16:46:00.822 I/DownloadService(25396): STARTED -> PAUSED (DownloadFile (Exit))\r\n04-01 16:46:00.823 I/DownloadServiceLifecycleSupport(25396): Serialized currentPlayingIndex: 1, currentPlayingPosition: 208496\r\n04-01 16:46:00.898 I/RESTMusicService(25396): https://myserver.com/rest/savePlayQueue.view?v=1.2.0&c=DSub\r\n04-01 16:46:01.131 I/DownloadService(25396): PAUSED -> STARTED (DownloadFile (Exit))\r\n04-01 16:46:01.886 I/RESTMusicService(25396): https://myserver.com/rest/getUser.view?v=1.2.0&c=DSub&username=dave\r\n04-01 16:46:13.847 W/InputEventReceiver(25396): Attempted to finish an input event but the input event receiver has already been disposed.\r\n04-01 16:46:20.805 W/InputEventReceiver(25396): Attempted to finish an input event but the input event receiver has already been disposed.\r\n04-01 16:46:22.928 I/RESTMusicService(25396): https://myserver.com/rest/getAlbumList.view?v=1.2.0&c=DSub&type=newest&size=20&offset=0\r\n04-01 16:46:24.803 I/WebViewFactory(25396): Loading com.google.android.webview version 40 (1808730-arm) (code 423501)\r\n04-01 16:46:24.838 I/LibraryLoader(25396): Time to load native libraries: 2 ms (timestamps 847-849)\r\n04-01 16:46:24.838 I/LibraryLoader(25396): Expected native library version number \"\",actual native library version number \"\"\r\n04-01 16:46:24.881 I/LibraryLoader(25396): Expected native library version number \"\",actual native library version number \"\"\r\n04-01 16:46:24.889 I/chromium(25396): [INFO:library_loader_hooks.cc(108)] Chromium logging enabled: level = 0, default verbosity = 0\r\n04-01 16:46:24.904 I/BrowserStartupController(25396): Initializing chromium process, singleProcess=true\r\n04-01 16:46:24.910 W/art     (25396): Attempt to remove local handle scope entry from IRT, ignoring\r\n04-01 16:46:25.060 W/chromium(25396): [WARNING:resource_bundle.cc(304)] locale_file_path.empty()\r\n04-01 16:46:25.061 I/chromium(25396): [INFO:aw_browser_main_parts.cc(63)] Load from apk succesful, fd=107 off=49196 len=3229\r\n04-01 16:46:25.063 I/chromium(25396): [INFO:aw_browser_main_parts.cc(76)] Loading webviewchromium.pak from, fd:108 off:390788 len:1143511\r\n04-01 16:46:25.075 I/art     (25396): Background sticky concurrent mark sweep GC freed 118337(6MB) AllocSpace objects, 36(1186KB) LOS objects, 15% free, 42MB/50MB, paused 791us total 129.497ms\r\n04-01 16:46:25.217 W/chromium(25396): [WARNING:data_reduction_proxy_settings.cc(328)] SPDY proxy OFF at startup\r\n04-01 16:46:25.234 W/art     (25396): Attempt to remove local handle scope entry from IRT, ignoring\r\n04-01 16:46:25.239 W/AwContents(25396): onDetachedFromWindow called when already detached. Ignoring\r\n04-01 16:46:25.354 W/InputEventReceiver(25396): Attempted to finish an input event but the input event receiver has already been disposed.\r\n04-01 16:46:25.354 I/Choreographer(25396): Skipped 36 frames!  The application may be doing too much work on its main thread.\r\n04-01 16:46:25.560 W/BindingManager(25396): Cannot call determinedVisibility() - never saw a connection for the pid: 25396\r\n04-01 16:46:26.042 W/UnimplementedWebViewApi(25396): Unimplemented WebView method onKeyDown called from: android.webkit.WebView.onKeyDown(WebView.java:2310)\r\n04-01 16:46:36.630 W/InputEventReceiver(25396): Attempted to finish an input event but the input event receiver has already been disposed.\r\n```"},"comment":{"url":"https://api.github.com/repos/daneren2005/Subsonic/issues/comments/90294858","html_url":"https://github.com/daneren2005/Subsonic/issues/481#issuecomment-90294858","issue_url":"https://api.github.com/repos/daneren2005/Subsonic/issues/481","id":90294858,"user":{"login":"dpedu","id":1266188,"avatar_url":"https://avatars.githubusercontent.com/u/1266188?v=3","gravatar_id":"","url":"https://api.github.com/users/dpedu","html_url":"https://github.com/dpedu","followers_url":"https://api.github.com/users/dpedu/followers","following_url":"https://api.github.com/users/dpedu/following{/other_user}","gists_url":"https://api.github.com/users/dpedu/gists{/gist_id}","starred_url":"https://api.github.com/users/dpedu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dpedu/subscriptions","organizations_url":"https://api.github.com/users/dpedu/orgs","repos_url":"https://api.github.com/users/dpedu/repos","events_url":"https://api.github.com/users/dpedu/events{/privacy}","received_events_url":"https://api.github.com/users/dpedu/received_events","type":"User","site_admin":false},"created_at":"2015-04-07T00:17:33Z","updated_at":"2015-04-07T00:17:33Z","body":"I see this is closed, were able to reproduce or fix it?\r\n\r\nTo answer your question - not recently, but if I had to guess it popped up about 6-8 months ago. \r\n\r\nRegarding the connection messages - the media itself was cached, as mentioned in the original issue. Not sure what DSub would be trying to do. I reproduced the issue today, without any connection-related messages:\r\n\r\n```\r\n--------- beginning of system\r\n04-06 15:40:44.572 W/ResourcesManager( 8806): Asset path '/system/framework/android.test.runner.jar' does not exist or contains no resources.\r\n04-06 16:49:50.420 W/ResourcesManager(18796): Asset path '/system/framework/android.test.runner.jar' does not exist or contains no resources.\r\n--------- beginning of main\r\n04-06 16:50:08.170 W/MediaPlayer(19035): info/warning (2, 0)\r\n04-06 16:50:08.208 I/DownloadService(19035): STARTED -> COMPLETED (DownloadFile (Lights))\r\n04-06 16:50:08.223 I/DownloadService(19035): Ending position 247451 of 248000\r\n04-06 16:50:08.224 I/DownloadService(19035): nextMediaPlayer already playing\r\n04-06 16:50:08.231 I/RESTMusicService(19035): https://myserver.com/rest/scrobble.view?v=1.2.0&c=DSub&id=6841&submission=true\r\n04-06 16:50:08.354 I/DownloadService(19035): COMPLETED -> STARTED (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:50:08.388 I/DownloadService(19035): Next: PREPARED -> IDLE (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:50:08.389 I/RESTMusicService(19035): https://myserver.com/rest/scrobble.view?v=1.2.0&c=DSub&id=6842&submission=false\r\n04-06 16:50:08.695 I/Scrobbler(19035): Scrobbled 'now playing' for DownloadFile (E.T. (Katy Perry))\r\n04-06 16:50:08.695 I/Scrobbler(19035): Scrobbled 'submission' for DownloadFile (Lights)\r\n04-06 16:50:13.391 I/DownloadService(19035): Buffering next /storage/emulated/0/Android/data/github.daneren2005.dsub/files/music/Klaypex/Loose Dirt/03-Not Getting Any Better (Innerpatysystem).partial.mp3 (0): true\r\n04-06 16:50:13.405 I/DownloadService(19035): Next: IDLE -> PREPARING (DownloadFile (Not Getting Any Better (Innerpatysystem)))\r\n04-06 16:50:13.434 E/MediaPlayer(19035): Should have subtitle controller already set\r\n04-06 16:50:13.436 I/DownloadService(19035): Next: PREPARING -> PREPARED (DownloadFile (Not Getting Any Better (Innerpatysystem)))\r\n04-06 16:53:08.002 I/DownloadService(19035): STARTED -> PAUSED (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:53:08.006 I/DownloadServiceLifecycleSupport(19035): Serialized currentPlayingIndex: 13, currentPlayingPosition: 178482\r\n04-06 16:53:08.034 I/RESTMusicService(19035): https://myserver.com/rest/savePlayQueue.view?v=1.2.0&c=DSub\r\n04-06 16:53:20.528 I/Choreographer(19035): Skipped 40 frames!  The application may be doing too much work on its main thread.\r\n04-06 16:53:20.589 W/SupportMenuInflater(19035): Ignoring attribute 'actionProviderClass'. Action view already specified.\r\n04-06 16:53:37.956 I/DownloadService(19035): PAUSED -> STARTED (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:53:48.256 I/DownloadService(19035): STARTED -> PAUSED (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:53:48.257 I/DownloadServiceLifecycleSupport(19035): Serialized currentPlayingIndex: 13, currentPlayingPosition: 179465\r\n04-06 16:53:48.288 I/RESTMusicService(19035): https://myserver.com/rest/savePlayQueue.view?v=1.2.0&c=DSub\r\n04-06 16:53:48.855 I/DownloadService(19035): PAUSED -> STARTED (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:53:49.220 I/DownloadService(19035): STARTED -> PAUSED (DownloadFile (E.T. (Katy Perry)))\r\n04-06 16:53:49.220 I/DownloadServiceLifecycleSupport(19035): Serialized currentPlayingIndex: 13, currentPlayingPosition: 179465\r\n04-06 16:53:49.223 I/RESTMusicService(19035): https://myserver.com/rest/savePlayQueue.view?v=1.2.0&c=DSub\r\n04-06 16:53:54.747 W/InputEventReceiver(19035): Attempted to finish an input event but the input event receiver has already been disposed.\r\n04-06 16:53:56.039 I/RESTMusicService(19035): https://myserver.com/rest/getAlbumList.view?v=1.2.0&c=DSub&type=newest&size=20&offset=0\r\n04-06 16:53:58.100 I/Util    (19035): Deleted file /storage/emulated/0/Android/data/github.daneren2005.dsub/files/logcat.txt\r\n```\r\n\r\nThe environment and symptoms are identical to that in the original issue."}}