SocketException when connecting with Zeroconf

[devgianlu]

The connection process is also quite slow and we shouldn't stop the Zeroconf service.

java.net.SocketException: socket closed
	at java.net.DualStackPlainSocketImpl.accept0(Native Method)
	at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
	at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
	at java.net.ServerSocket.implAccept(ServerSocket.java:545)
	at java.net.ServerSocket.accept(ServerSocket.java:513)
	at xyz.gianlu.librespot.core.ZeroconfAuthenticator$HttpRunner.run(ZeroconfAuthenticator.java:254)
	at java.lang.Thread.run(Thread.java:748)

[loeffelpan]

Second connection attemed after above exeption gives no playback.
No further exeption on console. Seems that the connection cannot be established again after socketException.

No problem with USER_PASS strategy.

[devgianlu]

This is due to the fact that I am closing the Zerconf server after the first attempt because I don't know how to handle a connection request if a session is already running. I'll workaround this to fix it.

[loeffelpan]

Sorry, not fixed yet.
First connection attempt is successful without SocketException, but second one cannot complete (Connecting... in Spotify app). There was an exception in the logfile on second attempt.
I stopped the playback an closed the app on 20:34. After that the server handeled pings (and pongs).
I tried to reconnect on 21:14 and got an Exception in thread "zeroconf-http-server"?.

Jan 15 20:36:11 osmc java[26422]: 2019-01-15 20:36:11 TRACE Session:564 - Handled Ping
Jan 15 20:36:11 osmc java[26422]: 2019-01-15 20:36:11 TRACE Session:570 - Handled PongAck
Jan 15 20:38:11 osmc java[26422]: 2019-01-15 20:38:11 TRACE Session:564 - Handled Ping
Jan 15 20:38:11 osmc java[26422]: 2019-01-15 20:38:11 TRACE Session:570 - Handled PongAck
Jan 15 20:40:11 osmc java[26422]: 2019-01-15 20:40:11 TRACE Session:564 - Handled Ping
Jan 15 20:40:11 osmc java[26422]: 2019-01-15 20:40:11 TRACE Session:570 - Handled PongAck
Jan 15 20:42:11 osmc java[26422]: 2019-01-15 20:42:11 TRACE Session:564 - Handled Ping
Jan 15 20:42:11 osmc java[26422]: 2019-01-15 20:42:11 TRACE Session:570 - Handled PongAck
Jan 15 20:44:11 osmc java[26422]: 2019-01-15 20:44:11 TRACE Session:564 - Handled Ping
Jan 15 20:44:11 osmc java[26422]: 2019-01-15 20:44:11 TRACE Session:570 - Handled PongAck
Jan 15 20:46:11 osmc java[26422]: 2019-01-15 20:46:11 TRACE Session:564 - Handled Ping
Jan 15 20:46:11 osmc java[26422]: 2019-01-15 20:46:11 TRACE Session:570 - Handled PongAck
Jan 15 20:48:11 osmc java[26422]: 2019-01-15 20:48:11 TRACE Session:564 - Handled Ping
Jan 15 20:48:11 osmc java[26422]: 2019-01-15 20:48:11 TRACE Session:570 - Handled PongAck
Jan 15 20:50:11 osmc java[26422]: 2019-01-15 20:50:11 TRACE Session:564 - Handled Ping
Jan 15 20:50:11 osmc java[26422]: 2019-01-15 20:50:11 TRACE Session:570 - Handled PongAck
Jan 15 20:52:11 osmc java[26422]: 2019-01-15 20:52:11 TRACE Session:564 - Handled Ping
Jan 15 20:52:11 osmc java[26422]: 2019-01-15 20:52:11 TRACE Session:570 - Handled PongAck
Jan 15 20:54:11 osmc java[26422]: 2019-01-15 20:54:11 TRACE Session:564 - Handled Ping
Jan 15 20:54:11 osmc java[26422]: 2019-01-15 20:54:11 TRACE Session:570 - Handled PongAck
Jan 15 21:14:19 osmc java[26422]: Exception in thread "zeroconf-http-server" java.lang.IllegalStateException: Cannot reuse object!
Jan 15 21:14:19 osmc java[26422]:         at xyz.gianlu.librespot.crypto.DiffieHellman.computeSharedKey(DiffieHellman.java:42)
Jan 15 21:14:19 osmc java[26422]:         at xyz.gianlu.librespot.core.ZeroconfServer.handleAddUser(ZeroconfServer.java:184)
Jan 15 21:14:19 osmc java[26422]:         at xyz.gianlu.librespot.core.ZeroconfServer.access$100(ZeroconfServer.java:34)
Jan 15 21:14:19 osmc java[26422]:         at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.handle(ZeroconfServer.java:325)
Jan 15 21:14:19 osmc java[26422]:         at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.run(ZeroconfServer.java:266)
Jan 15 21:14:19 osmc java[26422]:         at java.lang.Thread.run(Thread.java:748)

[devgianlu]

Check now (c482f9c).

[loeffelpan]

Yess. Now it's working for me.
Thanks again.

First connection attempt is quite slow. Reconnecting is much faster (even from another device).
Could you maybe do some steps with start of the server to speed up the first connection attempt?

[devgianlu]

The Zeroconf server takes a while to start because it needs to dispatch the mDNS service which requires some specific timeouts. Even after waiting for the startup process to finish, I don't see a long delay, but I will fix this issue if I'll encounter it.

[loeffelpan]

Maybe "long" is the wrong word for this. It's about 5-6 seconds (17:55:29 until 17:55:35) at the first attempt. Reconnting only takes a few milliseconds.

Jan 16 17:55:29 osmc java[2175]: 2019-01-16 17:55:29 TRACE ZeroconfServer:294 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.88 iOS/12.1.2 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Jan 16 17:55:31 osmc java[2175]: 2019-01-16 17:55:31 TRACE ZeroconfServer:294 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.88 iOS/12.1.2 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
Jan 16 17:55:32 osmc java[2175]: 2019-01-16 17:55:32 TRACE ZeroconfServer:294 - Handling request: POST / HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.4.88 iOS/12.1.2 (iPhone7,2), Host=172.20.2.4, Accept-Encoding=gzip, Content-Length=689, Content-Type=application/x-www-form-urlencoded}
Jan 16 17:55:32 osmc java[2175]: 2019-01-16 17:55:32 TRACE DiffieHellman:45 - Computed shared key successfully!
Jan 16 17:55:33 osmc java[2175]: 2019-01-16 17:55:33 INFO  Session:68 - Created new session! {deviceId: a3761281-31e7-4a6a-94ae-13b6dc73c61b, ap: gew1-accesspoint-b-w5cc.ap.spotify.com/104.199.64.115}
Jan 16 17:55:33 osmc java[2175]: 2019-01-16 17:55:33 TRACE DiffieHellman:45 - Computed shared key successfully!
Jan 16 17:55:35 osmc java[2175]: 2019-01-16 17:55:35 INFO  Session:196 - Connected successfully!