search

badaix / snapdroid

Snapcast client for Android
GNU General Public License v3.0
124 stars 25 forks source link

0.20.0 stops playback when adding/removing 3.5mm cable. Recovery only by restarting the service #26

Closed almostserious closed 3 years ago

almostserious commented 4 years ago

This is similar to the issue I had with the first Version of 0.19.0. Which was fixed after installing a Test Version. With the newest 0.20.0 apk the Playback on my Android 10 Tablet stops after some time. The server still shows the Tablet as connected and playing, but there is no sound coming. Stopping and reconnecting fixes this.

Here is a log from just now:

06-26 08:20:06.020  6784 29500 I chatty  : uid=10018(de.badaix.snapcast) Thread-13 identical 4 lines
06-26 08:20:07.020  6784 29500 D Main    : [Info] (Stream) no chunks available
06-26 08:20:08.019  6784 29500 D Main    : [Info] (Stream) no chunks available
06-26 08:20:09.020  6784 29500 D Main    : [Info] (Stream) no chunks available
06-26 08:20:10.021  6784 29500 D Main    : [Info] (Stream) no chunks available
06-26 08:20:11.001  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_RESIZED_REPORT: frame=(0,0,2560,1600) ci=(0,54,0,34) vi=(0,54,0,34) or=2
06-26 08:20:11.018  6784 29500 D Main    : [Info] (Stream) no chunks available
06-26 08:20:11.068  6784  6784 E ViewRootImpl@2c404dd[MainActivity]: Surface is not valid.
06-26 08:20:11.081  6784  6807 W badaix.snapcas: Reducing the number of considered missed Gc histogram windows from 149 to 100
06-26 08:20:11.092  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=true
06-26 08:20:11.114  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7ca90a5180
06-26 08:20:11.116  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7cb5680cc0
06-26 08:20:11.124  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=8 res=0x40001 s={true 535406936064} ch=true
06-26 08:20:11.124  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: RELAYOUT_RES_KEEP_ALIVE_SURFACE on 40001
06-26 08:20:11.125  6784 18111 D OpenGLRenderer: createReliableSurface : 0x7cb5680cc0(0x7ca8bd8000)
06-26 08:20:11.132  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x0 -> 0x7ca90a5c80
06-26 08:20:11.133  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=false
06-26 08:20:11.134  6784  6784 D Main    : lastRunVersion: 2000, version: 2000
06-26 08:20:11.171  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=11 res=0x40001 s={true 535406936064} ch=false
06-26 08:20:11.271  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1 1
06-26 08:20:11.271  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:20:11.271  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:20:11.274  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:20:11.274  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:20:11.274  6784  6784 V InputMethodManager: Starting input: tba=de.badaix.snapcast ic=null mNaviBarColor -855310 mIsGetNaviBarColorSuccess true , NavVisible : true , NavTrans : false
06-26 08:20:11.274  6784  6784 D InputMethodManager: startInputInner - Id : 0
06-26 08:20:11.274  6784  6784 I InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
06-26 08:20:11.283  6784  6784 D InputTransport: Input channel destroyed: 'ClientS', fd=77
06-26 08:20:12.061  6784 29500 D Main    : [Info] (Stream) no chunks available
06-26 08:20:14.955  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 08:20:15.081  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 08:20:15.081  6784  6784 D AbsListView: onTouchUp() mTouchMode : 1
06-26 08:20:15.911  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 08:20:16.037  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 08:20:16.037  6784  6784 D AbsListView: onTouchUp() mTouchMode : 1
06-26 08:20:16.814  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 08:20:16.931  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 08:20:16.933  6784 28819 D TCP     : Sending: {"jsonrpc":"2.0","method":"Client.SetVolume","id":38,"params":{"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3","volume":{"percent":100,"muted":false}}}
06-26 08:20:16.938  6784 28817 D TCP     : Received Message: '{"id":38,"jsonrpc":"2.0","result":{"volume":{"muted":false,"percent":100}}}'
06-26 08:20:16.938  6784 28817 D RC      : Response to: Client.SetVolume
06-26 08:20:16.938  6784 29500 D Main    : [Info] (Controller) ServerSettings - buffer: 400, latency: -318, volume: 100, muted: 0
06-26 08:20:19.169  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_RESIZED_REPORT: frame=(0,0,2560,1600) ci=(0,54,0,34) vi=(0,54,0,34) or=2
06-26 08:20:19.190  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=7 res=0x40003 s={true 535406936064} ch=false
06-26 08:20:19.190  6784 18111 D OpenGLRenderer: createReliableSurface : 0x7ca900f5c0(0x7ca8bd8000)
06-26 08:20:19.190  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x7ca90a5c80 -> 0x0
06-26 08:20:19.190  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7ca90a5c80
06-26 08:20:19.193  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7cb5680cc0
06-26 08:20:19.199  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x0 -> 0x7cb555c100
06-26 08:20:19.333  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 0
06-26 08:20:19.395  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 1
06-26 08:20:19.833  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 0
06-26 08:20:19.905  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 1
06-26 08:20:20.593  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 0
06-26 08:20:20.645  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 1
06-26 08:20:21.101  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 0
06-26 08:20:21.104  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme key 1
06-26 08:20:21.674  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_RESIZED_REPORT: frame=(0,0,2560,1600) ci=(0,54,0,34) vi=(0,54,0,34) or=2
06-26 08:20:21.696  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=4 res=0x40003 s={true 535406936064} ch=false
06-26 08:20:21.696  6784 18111 D OpenGLRenderer: createReliableSurface : 0x7ca8a1e840(0x7ca8bd8000)
06-26 08:20:21.697  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x7cb555c100 -> 0x0
06-26 08:20:21.697  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7cb555c100
06-26 08:20:21.698  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7ca900f5c0
06-26 08:20:21.701  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x0 -> 0x7ca90a5400
06-26 08:20:44.303  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 0 1
06-26 08:20:44.303  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:20:44.303  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:20:45.753  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1 1
06-26 08:20:45.753  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:20:45.753  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:20:45.778  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 0 1
06-26 08:20:45.778  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:20:45.778  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:20:46.371  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x7ca90a5400 -> 0x0
06-26 08:20:46.372  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7ca90a5400
06-26 08:20:46.373  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7ca8a1e840
06-26 08:20:46.381  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)8 dur=8 res=0x5 s={false 0} ch=true
06-26 08:20:46.396  6784  6784 D InputTransport: Input channel destroyed: 'ClientS', fd=74
06-26 08:20:46.418  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(true) old=false
06-26 08:20:46.455  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)8 dur=4 res=0x5 s={false 0} ch=false
06-26 08:28:32.696  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:28:32.696  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:28:32.696  6784  6784 V InputMethodManager: Starting input: tba=de.badaix.snapcast ic=null mNaviBarColor -855310 mIsGetNaviBarColorSuccess true , NavVisible : true , NavTrans : false
06-26 08:28:32.696  6784  6784 D InputMethodManager: startInputInner - Id : 0
06-26 08:28:32.696  6784  6784 I InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
06-26 08:28:32.701  6784  6784 D InputTransport: Input channel destroyed: 'ClientS', fd=74
06-26 08:28:33.117  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(true) old=false
06-26 08:28:33.118  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x7cb555c500 -> 0x0
06-26 08:28:33.516  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 0 1
06-26 08:28:33.516  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:28:33.516  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:29:00.616  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_RESIZED_REPORT: frame=(0,0,2560,1600) ci=(0,54,0,34) vi=(0,54,0,34) or=2
06-26 08:29:00.655  6784  6784 E ViewRootImpl@2c404dd[MainActivity]: Surface is not valid.
06-26 08:29:00.669  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=true
06-26 08:29:00.688  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7cb555c500
06-26 08:29:00.689  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7cb52d1800
06-26 08:29:00.696  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=6 res=0x40001 s={true 535618355200} ch=true
06-26 08:29:00.696  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: RELAYOUT_RES_KEEP_ALIVE_SURFACE on 40001
06-26 08:29:00.696  6784 18111 D OpenGLRenderer: createReliableSurface : 0x7cb52d1800(0x7cb5578000)
06-26 08:29:00.699  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x0 -> 0x7d02443000
06-26 08:29:00.700  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=false
06-26 08:29:00.700  6784  6784 D Main    : lastRunVersion: 2000, version: 2000
06-26 08:29:00.718  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=4 res=0x40001 s={true 535618355200} ch=false
06-26 08:29:00.732  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1 1
06-26 08:29:00.732  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:29:00.732  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:29:00.733  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 08:29:00.733  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 08:29:00.733  6784  6784 V InputMethodManager: Starting input: tba=de.badaix.snapcast ic=null mNaviBarColor -855310 mIsGetNaviBarColorSuccess true , NavVisible : true , NavTrans : false
06-26 08:29:00.733  6784  6784 D InputMethodManager: startInputInner - Id : 0
06-26 08:29:00.733  6784  6784 I InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
06-26 08:29:00.735  6784  6784 D InputTransport: Input channel destroyed: 'ClientS', fd=75
06-26 08:29:02.091  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 08:29:02.226  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 08:29:02.649  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 08:29:02.712  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 08:29:02.728  6784  6784 D Service : stopPlayer
06-26 08:29:02.729  6784  6784 D Service : stopService
06-26 08:29:02.729  6784  6784 D Service : stop
06-26 08:29:02.729  6784  6784 D Service : stopProcess
06-26 08:29:02.731  6784 29500 W System.err: java.io.InterruptedIOException: read interrupted
06-26 08:29:02.736  6784 29500 W System.err:    at libcore.io.Linux.readBytes(Native Method)
06-26 08:29:02.736  6784 29500 W System.err:    at libcore.io.Linux.read(Linux.java:190)
06-26 08:29:02.736  6784 29500 W System.err:    at libcore.io.ForwardingOs.read(ForwardingOs.java:177)
06-26 08:29:02.736  6784 29500 W System.err:    at libcore.io.BlockGuardOs.read(BlockGuardOs.java:303)
06-26 08:29:02.736  6784 29500 W System.err:    at libcore.io.ForwardingOs.read(ForwardingOs.java:177)
06-26 08:29:02.736  6784 29500 W System.err:    at libcore.io.IoBridge.read(IoBridge.java:513)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.FileInputStream.read(FileInputStream.java:313)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.BufferedInputStream.read(BufferedInputStream.java:347)
06-26 08:29:02.736  6784 29500 W System.err:    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:291)
06-26 08:29:02.736  6784 29500 W System.err:    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:355)
06-26 08:29:02.736  6784 29500 W System.err:    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:181)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.InputStreamReader.read(InputStreamReader.java:184)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.BufferedReader.fill(BufferedReader.java:172)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.BufferedReader.readLine(BufferedReader.java:335)
06-26 08:29:02.736  6784 29500 W System.err:    at java.io.BufferedReader.readLine(BufferedReader.java:400)
06-26 08:29:02.736  6784 29500 W System.err:    at de.badaix.snapcast.SnapclientService$1.run(SnapclientService.java:246)
06-26 08:29:02.736  6784 29500 W System.err:    at java.lang.Thread.run(Thread.java:919)
06-26 08:29:02.855  6784 28817 D TCP     : Received Message: '{"jsonrpc":"2.0","method":"Client.OnDisconnect","params":{"client":{"config":{"instance":1,"latency":-318,"name":"Bett","volume":{"muted":false,"percent":100}},"connected":false,"host":{"arch":"arm64-v8a","ip":"192.168.10.107","mac":"08:ae:d6:5d:7f:ed","name":"SM-T835","os":"Android 10"},"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3","lastSeen":{"sec":1593152940,"usec":182057},"snapclient":{"name":"Snapclient","protocolVersion":2,"version":"0.20.0"}},"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3"}}'
06-26 08:29:03.395  6784  6784 D Main    : onPlayerStop
06-26 08:29:03.403  6784  6784 D Main    : updateStartStopMenuItem: ic_media_play
06-26 08:29:03.427  6784  6784 I Choreographer: Skipped 41 frames!  The application may be doing too much work on its main thread.
06-26 08:29:03.444  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=10 res=0x40001 s={true 535618355200} ch=false
06-26 08:29:04.168  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 08:29:04.279  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 08:29:04.322  6784  6784 D Service : start host: 192.168.1.100, port: 1704
06-26 08:29:04.323  6784  6784 D Service : Running on a non-TV Device
06-26 08:29:04.326  6784  6784 D Service : startProcess
06-26 08:29:04.327  6784  6784 I Service : Configured engine: Auto, active engine: oboe, sampleformat: 48000:16:*
06-26 08:29:04.715  6784 32600 D Main    : onPlayerStart
06-26 08:29:04.716  6784 32600 D Main    : [Info] (Connection) Resolving host IP for: 192.168.1.100
06-26 08:29:04.716  6784 32600 D Main    : [Info] (Connection) Connecting
06-26 08:29:04.716  6784  6784 D Main    : updateStartStopMenuItem: ic_media_stop
06-26 08:29:04.720  6784 32600 D Main    : [Notice] (Connection) Connected to 192.168.1.100
06-26 08:29:05.996  6784 32600 D Main    : [Info] (Connection) My MAC: "08:ae:d6:5d:7f:ed", socket: 7
06-26 08:29:06.001  6784 28817 D TCP     : Received Message: '{"jsonrpc":"2.0","method":"Client.OnConnect","params":{"client":{"config":{"instance":1,"latency":-318,"name":"Bett","volume":{"muted":false,"percent":100}},"connected":true,"host":{"arch":"arm64-v8a","ip":"192.168.10.107","mac":"08:ae:d6:5d:7f:ed","name":"SM-T835","os":"Android 10"},"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3","lastSeen":{"sec":1593152943,"usec":327750},"snapclient":{"name":"Snapclient","protocolVersion":2,"version":"0.20.0"}},"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3"}}'
06-26 08:29:06.006  6784 32600 D Main    : [Info] (Controller) ServerSettings - buffer: 400, latency: -318, volume: 100, muted: 0
06-26 08:29:06.008  6784 32600 D Main    : [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
06-26 08:29:06.008  6784 32600 D Main    : [Info] (Player) Player name: oboe, device: default, description: <none>, idx: -1, sharing mode: shared
06-26 08:29:06.008  6784 32600 D Main    : [Info] (Player) Mixer mode: software, parameters: <none>
06-26 08:29:06.008  6784 32600 D Main    : [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
06-26 08:29:06.009  6784 32600 D Main    : [Info] (OboePlayer) Init start
06-26 08:29:06.009  6784 32600 D Main    : [Info] (OboePlayer) DefaultStreamValues::SampleRate: 48000, DefaultStreamValues::FramesPerBurst: 192
06-26 08:29:06.032  6784 32600 D Main    : [Info] (OboePlayer) BufferSizeInFrames: 1764, FramesPerBurst: 882
06-26 08:29:06.032  6784 32600 D Main    : [Info] (OboePlayer) AudioApi: AAudio
06-26 08:29:06.032  6784 32600 D Main    : [Info] (OboePlayer) Init done
06-26 08:29:06.032  6784 32600 D Main    : [Info] (OboePlayer) Start
06-26 08:29:06.032  6784 32600 D Main    : [Info] (Stream) no chunks available
06-26 08:29:06.296  6784 32600 D Main    : [Info] (Controller) diff to server [ms]: 2.0607e+09
06-26 08:29:07.005  6784 32600 D Main    : [Debug] (Stats) Chunk: -2    -2      -1      -1      28      89      0
06-26 08:29:08.007  6784 32600 D Main    : [Debug] (Stats) Chunk: -2    -2      -2      -2      100     87      0
06-26 08:29:09.005  6784 32600 D Main    : [Debug] (Stats) Chunk: 0     0       -2      -2      172     89      3
06-26 08:29:10.005  6784 32600 D Main    : [Debug] (Stats) Chunk: -1    -1      0       -1      243     89      1

I don't have the exact point of failure, the log doesn't seem to go back that far. However, when it happens i get this when playing content (without sound)

06-26 07:46:10.686  6784 28817 D TCP     : Received Message: '{"jsonrpc":"2.0","method":"Client.OnVolumeChanged","params":{"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3","volume":{"muted":false,"percent":8}}}'
06-26 07:46:10.689  6784 28836 D Main    : [Info] (Controller) ServerSettings - buffer: 400, latency: -318, volume: 8, muted: 0
06-26 07:46:10.696  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:10.836  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 10 lines
06-26 07:46:10.836  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:10.855  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:11.576  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 51 lines
06-26 07:46:11.576  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:11.596  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:11.616  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:12.556  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 68 lines
06-26 07:46:12.576  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:12.596  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:12.836  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 18 lines
06-26 07:46:12.855  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:12.876  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:13.575  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 50 lines
06-26 07:46:13.576  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:13.595  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:13.635  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 2 lines
06-26 07:46:13.635  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:13.655  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:13.675  6784 28836 D Main    : [Info] (Stream) outputBufferDacTime > bufferMs: 2147483 > 718
06-26 07:46:13.676  6784 28836 I chatty  : uid=10018(de.badaix.snapcast) identical 1 line

After restarting the service it looks normal:

06-26 08:38:10.012  6784  5303 I chatty  : uid=10018(de.badaix.snapcast) Thread-16 identical 1 line
06-26 08:38:11.012  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:12.013  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:13.012  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:14.013  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:15.012  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:16.013  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:17.013  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:18.012  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:19.012  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:20.012  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0
06-26 08:38:21.014  6784  5303 D Main    : [Debug] (Stats) Chunk: 0     0       0       0       500     112     0

Could it be an issue with the buffer?

almostserious commented 4 years ago

Ok, so when I am running the snapdroid without a speaker connected to 3.5mm out and then while playing plugging in the 3.5mm plug the same happens. The Playback stops and can only be recovered by stopping and restarting.

Log Output:

06-26 10:59:41.297  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_RESIZED_REPORT: frame=(0,0,2560,1600) ci=(0,54,0,34) vi=(0,54,0,34) or=2
06-26 10:59:41.393  6784  6784 E ViewRootImpl@2c404dd[MainActivity]: Surface is not valid.
06-26 10:59:41.398  6784  6784 E ViewRootImpl@2c404dd[MainActivity]: Surface is not valid.
06-26 10:59:41.448  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=true
06-26 10:59:41.477  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7d0e577d00
06-26 10:59:41.481  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7cb52d1800
06-26 10:59:41.487  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=5 res=0x40001 s={true 535287267328} ch=true
06-26 10:59:41.487  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: RELAYOUT_RES_KEEP_ALIVE_SURFACE on 40001
06-26 10:59:41.487  6784 18111 D OpenGLRenderer: createReliableSurface : 0x7cb52d1800(0x7ca19b8000)
06-26 10:59:41.495  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x0 -> 0x7d0e577a80
06-26 10:59:41.496  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=false
06-26 10:59:41.497  6784  6784 D Main    : lastRunVersion: 2000, version: 2000
06-26 10:59:41.526  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=6 res=0x40001 s={true 535287267328} ch=false
06-26 10:59:41.546  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1 1
06-26 10:59:41.546  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 10:59:41.546  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 10:59:41.548  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 10:59:41.548  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 10:59:41.548  6784  6784 V InputMethodManager: Starting input: tba=de.badaix.snapcast ic=null mNaviBarColor -855310 mIsGetNaviBarColorSuccess true , NavVisible : true , NavTrans : false
06-26 10:59:41.548  6784  6784 D InputMethodManager: startInputInner - Id : 0
06-26 10:59:41.548  6784  6784 I InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
06-26 10:59:41.549  6784  6784 D InputTransport: Input channel destroyed: 'ClientS', fd=58
06-26 10:59:41.958  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 10:59:41.994  6784  6784 D AbsListView: reportScrollStateChange() newState : 1
06-26 10:59:42.133  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 10:59:42.133  6784  6784 D AbsListView: onTouchUp() mTouchMode : 3
06-26 10:59:42.133  6784  6784 D AbsListView: onTouchUp() TOUCH_MODE_SCROLL initialVelocity : 0
06-26 10:59:42.133  6784  6784 D AbsListView: reportScrollStateChange() newState : 0
06-26 10:59:46.652  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 10:59:46.906  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 10:59:46.908  6784 28819 D TCP     : Sending: {"jsonrpc":"2.0","method":"Client.SetVolume","id":41,"params":{"id":"26c6d10e-cae9-44a1-ae47-0da4b7a36ea3","volume":{"percent":15,"muted":false}}}
06-26 10:59:46.912  6784  5303 D Main    : [Info] (Controller) ServerSettings - buffer: 400, latency: -318, volume: 15, muted: 0
06-26 10:59:46.912  6784 28817 D TCP     : Received Message: '{"id":41,"jsonrpc":"2.0","result":{"volume":{"muted":false,"percent":15}}}'
06-26 10:59:46.912  6784 28817 D RC      : Response to: Client.SetVolume
06-26 10:59:48.493  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0
06-26 10:59:48.653  6784  6784 D AbsListView: reportScrollStateChange() newState : 1
06-26 10:59:48.837  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 1
06-26 10:59:48.837  6784  6784 D AbsListView: onTouchUp() mTouchMode : 3
06-26 10:59:48.837  6784  6784 D AbsListView: onTouchUp() TOUCH_MODE_SCROLL initialVelocity : 288
06-26 10:59:48.837  6784  6784 D AbsListView: reportScrollStateChange() newState : 2
06-26 10:59:48.984  6784  6784 D AbsListView: reportScrollStateChange() newState : 0
06-26 10:59:49.184  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: ViewPostIme pointer 0

Log when i have it running with 3.5mm and remove the plug (also stops playback)

06-26 11:05:33.586  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_RESIZED_REPORT: frame=(0,0,2560,1600) ci=(0,54,0,34) vi=(0,54,0,34) or=2
06-26 11:05:33.594  6784  6784 E ViewRootImpl@2c404dd[MainActivity]: Surface is not valid.
06-26 11:05:33.603  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=true
06-26 11:05:33.657  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: stopped(false) old=false
06-26 11:05:33.661  6784  6784 D Main    : lastRunVersion: 2000, version: 2000
06-26 11:05:33.664  6784 18111 D OpenGLRenderer: destroyEglSurface : 0x7d0e58d180
06-26 11:05:33.668  6784 18111 D OpenGLRenderer: ~ReliableSurface : 0x7cb52d1800
06-26 11:05:33.676  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: Relayout returned: old=(0,0,2560,1600) new=(0,0,2560,1600) req=(2560,1600)0 dur=8 res=0x40001 s={true 535408058368} ch=true
06-26 11:05:33.676  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: RELAYOUT_RES_KEEP_ALIVE_SURFACE on 40001
06-26 11:05:33.676  6784 18111 D OpenGLRenderer: createReliableSurface : 0x7cb52d1800(0x7ca8cea000)
06-26 11:05:33.680  6784 18111 D OpenGLRenderer: makeCurrent EglSurface : 0x0 -> 0x7d0e577d80
06-26 11:05:33.756  6784  6784 D ViewRootImpl@2c404dd[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1 1
06-26 11:05:33.756  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 11:05:33.756  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 11:05:33.761  6784  6784 D InputMethodManager: prepareNavigationBarInfo() DecorView@fb6098c[MainActivity]
06-26 11:05:33.761  6784  6784 D InputMethodManager: getNavigationBarColor() -855310
06-26 11:05:33.761  6784  6784 V InputMethodManager: Starting input: tba=de.badaix.snapcast ic=null mNaviBarColor -855310 mIsGetNaviBarColorSuccess true , NavVisible : true , NavTrans : false
06-26 11:05:33.761  6784  6784 D InputMethodManager: startInputInner - Id : 0
06-26 11:05:33.761  6784  6784 I InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
06-26 11:05:33.766  6784  6784 D InputTransport: Input channel destroyed: 'ClientS', fd=76
badaix commented 4 years ago

Looks like snapclient must listen to such events: https://github.com/google/oboe/blob/master/docs/notes/disconnect.md I will check next week when I'm back from my vacation.

almostserious commented 4 years ago

Going back to 19.0.1 and manually choosing the OpenSL this does not happen. So the link above sounds correct. Only happens on AAudio. I can confirm the same behavior as well once more with a FireTV Device. Changing the source will stop the stream with no way to recover but to manually stop and restart the service if running on AAudio with 0.20.0

badaix commented 3 years ago

Will be fixed in v0.22 https://github.com/badaix/snapcast/commit/869a9a276ed3f11ba9e63c2687594cc36df29bb7