HD-200 and HD-300 frozen some time after V9 Upgrade

[atchoo]

I recently upgraded to v9. Always had SageTV and my extenders (I have 5 extenders 3 x HD-200 and 2 x HD-300) running fine. It has also been running fine until today when I had to reboot my server. The extenders were not seeing the server anymore so I rebooted and the server was again seen by the extenders but now when they connect to my SageTV server it freezes on "HD theater starting up..."

I tried unplugging one of the extender and waiting for a while before powering it up again but it changes nothing. Should I unplug all 5 extenders from the power? Will it change something? What else should I try?

Here's something from the log that refers to an exception....

mer. 9/6 17:44:58.685 [MiniUIServerConnection@1063cce] MiniClient CRYPTO_ALGORITHMS=RSA,Blowfish
mer. 9/6 17:44:59.601 [MiniUIClientReceiver@10def64] Server got notification to update the output modes...
mer. 9/6 17:45:05.175 [MiniUIClientReceiver@10def64] Exception in the MiniUIClientReceiver of: java.io.EOFException
mer. 9/6 17:45:05.176 [KillUIMgr@82063e] Killing UIMgr UIManager:localhost@@0023a5000284-67ec67
mer. 9/6 17:45:05.176 [KillUIMgr@82063e] Error calling finishWatch from VF goodbye:java.lang.NullPointerException
mer. 9/6 17:45:05.176 [KillUIMgr@82063e] Killed VideoFrame
mer. 9/6 17:45:05.177 [KillUIMgr@82063e] Saving properties file to clients\0023a5000284.properties
mer. 9/6 17:45:05.341 [KillUIMgr@82063e] Done writing out the data to the properties file
mer. 9/6 17:45:16.330 [SageTVMiniDiscoveryServer@56869] Server got broadcast packet: java.net.DatagramPacket@aebb95
mer. 9/6 17:45:16.591 [SageTVMiniDiscoveryServer@56869] Server sent back mini discovery data:java.net.DatagramPacket@aebb95 to /192.168.2.210 8271
mer. 9/6 17:45:27.651 [MiniUIServer@153bb3b] Dropping old MiniPlayer connection because it's old from:0023a5000284
mer. 9/6 17:45:49.807 [Ministry@12aea81] Ministry is waiting for 180 sec
mer. 9/6 17:46:00.020 [ConnRecvQueue@293cea] Increased Thread pool to size=16

[atchoo]

Waited a few hours and retried.... and the extenders now start correctly. I had a similar problem when I first installed v9 ! Could something or some service be delayed and take a long time to restart after reboot? I really did nothing when I installed v9, I couldn't find the problem and went to sleep and the next day the extenders started correctly. This time is the same, extenders could see the server but got blocked at the "is starting up..." screen. I went out for 3 hours and when I got back they loaded correctly.

[stuckless]

I've seen similar issues as this with the extenders when I had a bad network port. They would hang for a very long time.

If you post the server startup logs, people might be able to see if anything is hanging on the server, during startup.

[atchoo]

I've seen this in sagetv_0 which refers to some kind of exception...

mer. 9/6 17:44:58.682 [MiniUIServerConnection@1063cce] MiniClient sending RECONNECT_SUPPORTED=TRUE
mer. 9/6 17:44:58.683 [MiniUIServerConnection@1063cce] MiniClient sending GFX_ASPECT=1.7777778
mer. 9/6 17:44:58.685 [MiniUIClientReceiver@10def64] Got UI size update to 1024x576
mer. 9/6 17:44:58.685 [MiniUIServerConnection@1063cce] MiniClient CRYPTO_ALGORITHMS=RSA,Blowfish
mer. 9/6 17:44:59.601 [MiniUIClientReceiver@10def64] Server got notification to update the output modes...
mer. 9/6 17:45:05.175 [MiniUIClientReceiver@10def64] Exception in the MiniUIClientReceiver of: java.io.EOFException
mer. 9/6 17:45:05.176 [KillUIMgr@82063e] Killing UIMgr UIManager:localhost@@0023a5000284-67ec67
mer. 9/6 17:45:05.176 [KillUIMgr@82063e] Error calling finishWatch from VF goodbye:java.lang.NullPointerException
mer. 9/6 17:45:05.176 [KillUIMgr@82063e] Killed VideoFrame
mer. 9/6 17:45:05.177 [KillUIMgr@82063e] Saving properties file to clients\0023a5000284.properties
mer. 9/6 17:45:05.341 [KillUIMgr@82063e] Done writing out the data to the properties file
mer. 9/6 17:45:16.330 [SageTVMiniDiscoveryServer@56869] Server got broadcast packet: java.net.DatagramPacket@aebb95
mer. 9/6 17:45:16.591 [SageTVMiniDiscoveryServer@56869] Server sent back mini discovery data:java.net.DatagramPacket@aebb95 to /192.168.2.210 8271
mer. 9/6 17:45:27.651 [MiniUIServer@153bb3b] Dropping old MiniPlayer connection because it's old from:0023a5000284
mer. 9/6 17:45:49.807 [Ministry@12aea81] Ministry is waiting for 180 sec
mer. 9/6 17:46:00.020 [ConnRecvQueue@293cea] Increased Thread pool to size=16
mer. 9/6 17:46:55.018 [SageTVMiniDiscoveryServer@56869] Server got broadcast packet: java.net.DatagramPacket@104b2e6
mer. 9/6 17:46:55.286 [SageTVMiniDiscoveryServer@56869] Server sent back mini discovery data:java.net.DatagramPacket@104b2e6 to /192.168.2.210 8271
mer. 9/6 17:47:30.546 [MiniMVP@1d07227] Received mvp packet

mer. 9/6 17:47:30.810 [MiniMVP@1d07227] Sending mvp reply
mer. 9/6 17:47:31.607 [MiniUIServer@153bb3b] MiniUI got connection from java.nio.channels.SocketChannel[connected local=/192.168.2.40:31099 remote=/192.168.2.210:35947]
mer. 9/6 17:47:31.608 [MiniUIServer@153bb3b] MiniUI got connection from java.nio.channels.SocketChannel[connected local=/192.168.2.40:31099 remote=/192.168.2.210:35948]
mer. 9/6 17:47:31.608 [MiniUIServerConnection@1f34fb6] MiniUI is adding to its map:0023a5000284
mer. 9/6 17:47:31.609 [MiniUIServerConnection@1f34fb6] Creating new UI for client:0023a5000284
mer. 9/6 17:47:31.609 [MiniUIServerConnection@f661cf] MiniPlayer is adding to its map:0023a5000284
mer. 9/6 17:47:31.610 [MiniUIServerConnection@1f34fb6] Creating-2 new UI for client:0023a5000284 UIManager:localhost@@0023a5000284-18f8aaa
mer. 9/6 17:47:31.872 [MiniUIClientReceiver@14500c0] Got UI size update to 1024x576
mer. 9/6 17:47:32.622 [MiniUIServerConnection@1f34fb6] MiniUI established for 0023a5000284 status=true
mer. 9/6 17:47:32.624 [MiniUIServerConnection@1f34fb6] MiniClient GFX_TEXTMODE=NONE

Also a lot of references to weather updates in sagetvclient_0 ... maybe it was trying to update the weather data but network problem or very slow caused it not to be able to complete it? Could this freeze the startup process?

6 17:43:14.620 [Fork-OPUS4-108092@1a245b8] Updating weather
mer. 9/6 17:43:14.620 [Fork-BASE-71232@41ce27] Full Weather Update string URL = http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:43:14.620 [Fork-BASE-71232@41ce27] downloading from:http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:46:40.345 [ThreadMonitor@96ac5e] Top 10 Cumulative CPU(sec) AWT-EventQueue-0:9 FinalRender-SAGETV_PROCESS_LOCAL_UI:6 ActiveRender-SAGETV_PROCESS_LOCAL_UI:6 main:2 cling-2:1
mer. 9/6 17:46:40.346 [ThreadMonitor@96ac5e] Top 10 %CPU (last 300s)
mer. 9/6 17:48:15.545 [Fork-OPUS4-108092@1a245b8] Updating weather
mer. 9/6 17:48:15.545 [Fork-BASE-71232@41ce27] Full Weather Update string URL = http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:48:15.545 [Fork-BASE-71232@41ce27] downloading from:http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:51:40.270 [ThreadMonitor@96ac5e] Top 10 Cumulative CPU(sec) AWT-EventQueue-0:9 FinalRender-SAGETV_PROCESS_LOCAL_UI:6 main:2 cling-2:1
mer. 9/6 17:51:40.271 [ThreadMonitor@96ac5e] Top 10 %CPU (last 300s)
mer. 9/6 17:53:15.560 [Fork-OPUS4-108092@1a245b8] Updating weather
mer. 9/6 17:53:15.561 [Fork-BASE-71232@41ce27] Full Weather Update string URL = http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:53:15.561 [Fork-BASE-71232@41ce27] downloading from:http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:56:40.286 [ThreadMonitor@96ac5e] Top 10 Cumulative CPU(sec) AWT-EventQueue-0:9 FinalRender-SAGETV_PROCESS_LOCAL_UI:6 ActiveRender-SAGETV_PROCESS_LOCAL_UI:6 main:2 cling-2:1
mer. 9/6 17:56:40.287 [ThreadMonitor@96ac5e] Top 10 %CPU (last 300s)
mer. 9/6 17:56:49.315 [Seeker@989b32] Saving properties file to C:\Program Files\SageTV\SageTV\SageClient.properties
mer. 9/6 17:56:49.449 [Seeker@989b32] Done writing out the data to the properties file
mer. 9/6 17:58:15.576 [Fork-OPUS4-108092@1a245b8] Updating weather
mer. 9/6 17:58:15.577 [Fork-BASE-71232@41ce27] Full Weather Update string URL = http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:58:15.577 [Fork-BASE-71232@41ce27] downloading from:http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 17:59:03.764 [Timer-1@28e7bb] Screen Saver Timeout expired....tv=false playin=false fs=false sleepy=false currSS=false fsVideo=false
mer. 9/6 18:01:40.302 [ThreadMonitor@96ac5e] Top 10 Cumulative CPU(sec) AWT-EventQueue-0:9 ActiveRender-SAGETV_PROCESS_LOCAL_UI:6 FinalRender-SAGETV_PROCESS_LOCAL_UI:6 main:2 cling-2:1
mer. 9/6 18:01:40.303 [ThreadMonitor@96ac5e] Top 10 %CPU (last 300s)
mer. 9/6 18:03:15.592 [Fork-OPUS4-108092@1a245b8] Updating weather
mer. 9/6 18:03:15.593 [Fork-BASE-71232@41ce27] Full Weather Update string URL = http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 18:03:15.593 [Fork-BASE-71232@41ce27] downloading from:http://api.wunderground.com/api/f577e42a17aabb02/conditions/forecast10day/astronomy/alerts/lang:fr/q/BROSSARD.xml
mer. 9/6 18:06:40.318 [ThreadMonitor@96ac5e] Top 10 Cumulative CPU(sec) AWT-EventQueue-0:9 ActiveRender-SAGETV_PROCESS_LOCAL_UI:6 FinalRender-SAGETV_PROCESS_LOCAL_UI:6 main:2 cling-2:1
mer. 9/6 18:06:40.319 [ThreadMonitor@96ac5e] Top 10 %CPU (last 300s)