0.20.0 stops playback when adding/removing 3.5mm cable. Recovery only by restarting the service
almostserious opened this issue · 4 comments
almostserious commented
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
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
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
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
Will be fixed in v0.22
badaix/snapcast@869a9a2