Windows Client Connection Problems

[rickgillyon]

About once a week I get complaints that the windows clients have disconnected and won't reconnect. None of the clients will once this has happened, they just hang on the splash screen. The server is still running, recording etc.

This is an example from the log of a client connecting (I think):

Thu 9/29 19:01:32.009 [SageTVServer@18596bc] Error w/SageTV client connection:java.net.SocketTimeoutException: Read timed out
Thu 9/29 19:01:32.012 [SageTVServer@18596bc] java.net.SocketTimeoutException: Read timed out
Thu 9/29 19:01:32.012 [SageTVServer@18596bc] 	at java.net.SocketInputStream.socketRead0(Native Method)
Thu 9/29 19:01:32.012 [SageTVServer@18596bc] 	at java.net.SocketInputStream.socketRead(Unknown Source)
Thu 9/29 19:01:32.012 [SageTVServer@18596bc] 	at java.net.SocketInputStream.read(Unknown Source)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at java.net.SocketInputStream.read(Unknown Source)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at java.io.BufferedInputStream.fill(Unknown Source)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at java.io.BufferedInputStream.read(Unknown Source)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at sage.SageTVConnection$1.readByte(SageTVConnection.java:233)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at sage.SageTVConnection.readLineBytes(SageTVConnection.java:2852)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at sage.SageTVConnection.initializeListenerData(SageTVConnection.java:807)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at sage.NetworkClient.acceptFromClient(NetworkClient.java:237)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] 	at sage.SageTV$5.run(SageTV.java:839)
Thu 9/29 19:01:32.013 [SageTVServer@18596bc] Cleaning up c/s connection
Thu 9/29 19:01:32.016 [SageTVServer@18596bc] SageTV received connection from:Socket[addr=/192.168.1.53,port=49992,localport=42024]
Thu 9/29 19:01:32.019 [SageTVServer@18596bc] Connection lost from: Socket[addr=/192.168.1.53,port=49992,localport=42024] by:java.net.SocketException: Software caused connection abort: socket write error
Thu 9/29 19:01:32.022 [SageTVServer@18596bc] Cleaning up c/s connection
Thu 9/29 19:01:32.024 [SageTVServer@18596bc] Error w/SageTV client connection:java.net.SocketException: Software caused connection abort: socket write error
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] java.net.SocketException: Software caused connection abort: socket write error
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at java.net.SocketOutputStream.socketWrite0(Native Method)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at java.net.SocketOutputStream.socketWrite(Unknown Source)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at java.net.SocketOutputStream.write(Unknown Source)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at java.io.BufferedOutputStream.flush(Unknown Source)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at sage.SageTVConnection$MyDataOutput.flush(SageTVConnection.java:3822)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at sage.SageTVConnection.checkLogin(SageTVConnection.java:482)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at sage.SageTVConnection.<init>(SageTVConnection.java:42)
Thu 9/29 19:01:32.027 [SageTVServer@18596bc] 	at sage.NetworkClient.acceptFromClient(NetworkClient.java:192)
Thu 9/29 19:01:32.028 [SageTVServer@18596bc] 	at sage.SageTV$5.run(SageTV.java:839)
Thu 9/29 19:01:32.028 [SageTVServer@18596bc] SageTV received connection from:Socket[addr=/192.168.1.84,port=54428,localport=42024]
Thu 9/29 19:01:32.031 [SageTVServer@18596bc] Connection lost from: Socket[addr=/192.168.1.84,port=54428,localport=42024] by:java.io.EOFException
Thu 9/29 19:01:32.033 [SageTVServer@18596bc] Cleaning up c/s connection
Thu 9/29 19:01:32.036 [SageTVServer@18596bc] Error w/SageTV client connection:java.io.EOFException
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] java.io.EOFException
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] 	at sage.SageTVConnection$1.readByte(SageTVConnection.java:235)
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] 	at sage.SageTVConnection.readLineBytes(SageTVConnection.java:2852)
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] 	at sage.SageTVConnection.checkLogin(SageTVConnection.java:512)
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] 	at sage.SageTVConnection.<init>(SageTVConnection.java:42)
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] 	at sage.NetworkClient.acceptFromClient(NetworkClient.java:192)
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] 	at sage.SageTV$5.run(SageTV.java:839)
Thu 9/29 19:01:32.039 [SageTVServer@18596bc] SageTV received connection from:Socket[addr=/192.168.1.53,port=49993,localport=42024]
Thu 9/29 19:01:32.074 [SageTVServer@18596bc] Sending DB to client of size:59134616
Thu 9/29 19:01:38.171 [SageTVServer@18596bc] DONE sending DB to the client and client is now added as a DB sync listener

and

Thu 9/29 19:25:00.106 [ClientListenerParallelizer@13fe5f7] Error communicating with client:java.net.SocketException: Software caused connection abort: socket write error
Thu 9/29 19:25:00.109 [ClientListenerParallelizer@1b5bb79] Error communicating with client:java.net.SocketException: Software caused connection abort: socket write error
Thu 9/29 19:25:00.112 [ClientListenerParallelizer@29e9ca] Error communicating with client:java.net.SocketException: Software caused connection abort: socket write error
Thu 9/29 19:25:00.116 [ClientListenerParallelizer@1b5bb79] Cleaning up c/s connection
Thu 9/29 19:25:00.118 [ClientListenerParallelizer@13fe5f7] Cleaning up c/s connection
Thu 9/29 19:25:00.121 [Seeker@17afd84] Seeker channel string=2
Thu 9/29 19:25:00.123 [ClientListenerParallelizer@13fe5f7] NetworkManager CommunicationFailure : /192.168.1.53:49869 type=2
Thu 9/29 19:25:00.126 [ClientListenerParallelizer@1b5bb79] NetworkManager CommunicationFailure : /192.168.1.53:49880 type=2
Thu 9/29 19:25:00.128 [ClientListenerParallelizer@1b5bb79] NetworkClient fullCleanup /192.168.1.53:49880
Thu 9/29 19:25:00.131 [ClientListenerParallelizer@1b5bb79] Cleaning up c/s connection
Thu 9/29 19:25:00.133 [ClientListenerParallelizer@29e9ca] Cleaning up c/s connection
Thu 9/29 19:25:00.135 [ClientListenerParallelizer@13fe5f7] NetworkClient fullCleanup /192.168.1.53:49869
Thu 9/29 19:25:00.138 [ClientListenerParallelizer@13fe5f7] Cleaning up c/s connection
Thu 9/29 19:25:00.141 [main@1f4acd0] autotune0 digital tuner 'TBS 6284 BDA Digital Capture DVBT-0' num=2 (ver 3.1)
Thu 9/29 19:25:00.141 [main@1f4acd0] Splitter Filter set output mpeg2 format 
Thu 9/29 19:25:00.141 [ClientListenerParallelizer@29e9ca] NetworkManager CommunicationFailure : /192.168.1.53:49851 type=2
Thu 9/29 19:25:00.143 [ClientListenerParallelizer@29e9ca] NetworkClient fullCleanup /192.168.1.53:49851
T

and

Thu 9/29 19:25:30.112 [TimeoutHandler@1a408d8] TIMEOUT occurred - close the socket asynchronously for Socket[addr=/192.168.1.53,port=49880,localport=42024]
Thu 9/29 19:25:30.116 [TimeoutHandler@1a408d8] TIMEOUT occurred - close the socket asynchronously for Socket[addr=/192.168.1.53,port=49869,localport=42024]
Thu 9/29 19:25:30.118 [TimeoutHandler@1a408d8] TIMEOUT occurred - close the socket asynchronously for Socket[addr=/192.168.1.53,port=49851,localport=42024]
Thu 9/29 19:27:41.497 [ThreadMonitor@597e71] Top 10 Cumulative CPU(sec) MsgManager:50 Scheduler:49 main:25 Carny:16 Seeker:16 EPG:8 ReProcessHook:7 ReProcessHook:7 PooledThread:6 LuceneShowTransactionTask:6
Thu 9/29 19:27:41.500 [ThreadMonitor@597e71] Top 10 %CPU (last 300s)

Heap seems okay:

Thu 9/29 19:00:03.197 [Seeker@17afd84] MemStats: Used=558MB Total=758MB Max=1037MB

Any ideas?

[wnjj]

That first log shows the server not getting a response after sending the Wizard DB to the client. Does the client have a log file showing what went wrong on its end?

[rickgillyon]

Looking at all the clients, none has logging turned on. I've switched it on on one, will update the next time they all crap out.

[Narflex]

If all the clients reconnect at once...it is normal to log a bunch of disconnection events as well. Client connections have a 2 part init process, and each of these require a separate connection to the server. So when a client connects, the server does the first init step. During that time period it queues up any other connection attempts. When it finishes that first part for the one client...it then goes through the list and will disconnect anybody who is not that same client; so it can then finish the second part of that client's init when it connects the second time. This works fine because clients will just reconnect and try again.

If you have 3 clients..it goes something like this:

Client 1 connects - do init phase 1
Client 2 connects - queue connection
Client 3 connects - queue connection
Phase 1 finishes for client 1
Server processes queue and disconnects clients 2 & 3 since it needs to finish 1 still
Client 1 connects - do init phase 2
Client 2 connects - queue connection
Client 3 connects - queue connection
Phase 2 finishes for client 1
Server processes queue, starts phase 1 for Client 2
Server finishes phase 1 for Client 2
Server processes queue, disconnects Client 3 because Client 2 isn't done yet
Client 2 connects - do phase 2
Client 3 connects - queue connection
Client 2 phase 2 done
Server processes queue, starts Client 3 phase 1
Finish Client 3 phase 1
Client 3 connects, do phase 2
All 3 clients connected now

There's 2 connections between each client and the server which is why this was needed. I probably explained too much here though.

But anyways...to help resolve the problem, just post the complete log from the server and all the clients next time it happens....I debugged tons of issues in this area on Fiber so have seen pretty much every possibility.

[rickgillyon]

Thanks, will do.

[gclayto]

I'm experiencing the same problem, the clients just refuse to connect just sitting there on the splash screen. How do I find and submit the logs?

[rickgillyon]

You need logging in Settings, Advanced set to On/On. This should give you a file sagetvclient_0.txt in the client's SageTV folder, and sagetv_0.txt in the server's SageTV folder. Zip these up, upload them and share them here.

If you don't have logging set for both, you'll need to restart Sage on the server and then the client, set it, and wait for the problem to happen again. I'm still waiting...