Sage hangs on client asking server to record

jimbobuk · #1 06-28-2003, 06:47 PM

Firstly thanks for the network fix.. aside from this actual playback has been very smooth... i am very happy so far with Sage in client based mode.. great stuff

Ok, i asked sage client to record a programme, no yellow border appeared, so i went thru right click menus to ask it to record programme again... following this sage had hung... i had to ctrl-alt-del kill it... here is the log, i've gone back a few more lines to see the occurence of more NOOPs.. the ones that follow scheduling recording i guess are relevant..

Quote:

Sun 6/29 1:33:59.625 VF processing job null nPlayin=true
Sun 6/29 1:33:59.625 VF thread is now waiting for 0:26:43.966
Sun 6/29 1:34:11.782 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:34:11.782 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:34:26.784 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:34:26.784 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:34:41.786 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:34:41.786 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:34:56.787 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:34:56.787 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:35:11.789 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:35:11.789 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:35:26.790 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:35:26.790 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:35:41.792 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:35:41.792 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:35:56.793 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:35:56.793 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:36:11.795 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:36:11.795 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:36:24.754 setUI(sage.ai@2505b7)
Sun 6/29 1:36:24.764 VF.submitJob(VFJob[Pause r=0.0 t=0 file=null ifn=null])
Sun 6/29 1:36:24.764 VF.submitJob(VFJob[WatchCompleteCheck r=0.0 t=0 file=null ifn=null])
Sun 6/29 1:36:24.764 VF processing job VFJob[Pause r=0.0 t=0 file=null ifn=null] nPlayin=true
Sun 6/29 1:36:24.854 VF processing on UI Thread VFJob[Pause r=0.0 t=0 file=null ifn=null]
Sun 6/29 1:36:24.854 VF processing job VFJob[WatchCompleteCheck r=0.0 t=0 file=null ifn=null] nPlayin=false
Sun 6/29 1:36:24.874 VF Watch Complete Check currFile=MediaFile[A[79530,79529,"Top of the Pops",6162@0627.19:30,30] host=jims-tv F:\SageTV\TopofthePops-79530-0.mpg, Seg0[Fri 6/27 19:30:00.003-Fri 6/27 20:00:00.001]] loggedWatch=false
Sun 6/29 1:36:24.874 VF processing job null nPlayin=false
Sun 6/29 1:36:24.874 VF thread is now waiting for 0:00:00.000
Sun 6/29 1:36:26.797 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:36:26.797 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:36:32.214 PopupChoice [Close, Detailed Info, Watched, Add to Favorites, Don't Like, Record, Additional Airings] default=Detailed Info
Sun 6/29 1:36:34.488 PopupChoice=Record
Sun 6/29 1:36:34.488 Sending record to server for A[87155,81772,"Glastonbury 2003",33264@0628.23:10,170]
Sun 6/29 1:36:39.415 PopupChoice [Close, Detailed Info, Watched, Add to Favorites, Don't Like, Record, Additional Airings] default=Detailed Info
Sun 6/29 1:36:40.877 PopupChoice=Record
Sun 6/29 1:36:40.877 Sending record to server for A[87155,81772,"Glastonbury 2003",33264@0628.23:10,170]
Sun 6/29 1:36:41.798 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:36:41.798 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:36:56.800 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:36:56.800 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:37:11.791 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:37:11.801 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]
Sun 6/29 1:37:26.793 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1060]
Sun 6/29 1:37:26.803 Received command of:NOOP from Socket[addr=/192.168.0.10,port=42024,localport=1062]

I assume the NOOPs are what you fixed in the video stream.. perhaps issuing commands should protect against it?!? what exactly do they mean?

God WinXP or explorer is annoying... I am used to coding in VI, so used some escape key presses by accident in editing this post... windows went ahead and undid my post with each press back to nothing... WHY!!!

Narflex · #2 06-29-2003, 01:32 PM

The NOOPs are just commands to keep the network connection alive so it doesn't timeout. They stand for 'no operation'.

Can I see the server logfile too? The client isn't showing me any error, so it's probably in the server's log.

jimbobuk · #3 06-29-2003, 02:48 PM

server logs.. around that area i think... just ask if you want full logs... the thing is it was the client that crashed/hung..

Quote:

Sun 6/29 1:33:24.021 [A[79962,79961,"Jackass",54797@0629.01:30,30], A[81789,81788,"Top of the Pops",6162@0629.02:05,30], A[80440,37417,"MTV2",8885@0629.03:00,180], A[83471,83470,"WideWorld",23277@0629.06:05,25], A[84685,84684,"Batman: The Animated Series",56969@0629.07:00,30], A[84694,84693,"Rescue Heroes",56969@0629.07:30,30], A[84704,84703,"Malo Korrigan",56969@0629.08:00,30], A[87166,86992,"Top 5",50757@0629.08:30,30], A[87168,87167,"Access All Areas Weekend",50757@0629.09:00,120], A[83591,83589,"FAQ",23277@0629.11:30,30], A[83606,83605,"Fresh Hits",50757@0629.12:00,60], A[83639,83638,"Big Brother's Little Brother",35048@0629.13:05,65], A[85485,85484,"EastEnders",6162@0629.14:40,110], A[83702,83701,"Smallville: Superman the Early Years",35048@0629.17:15,55], A[83726,83725,"Smallville: Superman the Early Years",35048@0629.18:10,50], A[85295,85294,"Big Brother's Little Brother",44725@0629.19:00,60], A[85509,85508,"Born and Bred",6162@0629.20:00,60], A[83788,83787,"Big Brother",35048@0629.21:00,60], A[84575,84574,"outTHERE",63440@0629.22:00,30], A[85532,85531,"24",3576@0629.22:45,40], A[83844,83843,"Jackass",54797@0629.23:30,30], A[83855,83854,"Jackass",54797@0630.00:00,30], A[83866,83865,"Jackass",54797@0630.00:30,30], A[87212,87211,"Wannabes",50757@0630.01:00,30], A[83891,83890,"Jackass",54797@0630.02:00,30], A[83901,83900,"Jackass",54797@0630.02:30,30], A[84643,84642,"Ultimate Gamer",64940@0630.03:25,30], A[88625,88623,"Star Trek: Deep Space Nine",56969@0630.06:00,60], A[87868,87867,"Neighbours",63520@0630.07:20,30], A[87888,87887,"EastEnders",63520@0630.08:25,35], A[87375,87374,"Non-Stop MTV Hits",50757@0630.09:30,60], A[89532,89531,"The Witness",33264@0630.10:35,85], A[88753,88752,"Buffy the Vampire Slayer",56969@0630.12:00,60], A[88776,88775,"Dream Team",56969@0630.13:00,60], A[89219,89218,"Big Brother",44725@0630.14:00,60], A[87498,87497,"Punk'd",54797@0630.15:30,30], A[87532,87531,"Richard & Judy",35048@0630.17:00,60], A[87552,87551,"Home and Away",23277@0630.18:00,30], A[87577,87576,"Punk'd",54797@0630.18:30,30], A[88903,88902,"The Simpsons",56969@0630.19:00,30], A[88914,88913,"The Simpsons",56969@0630.19:30,30], A[89586,89585,"EastEnders",6162@0630.20:00,30], A[87636,87635,"Non-Stop MTV Hits",50757@0630.20:30,30], A[89343,89342,"Smallville: Superman the Early Years",44725@0630.21:00,60], A[88135,88134,"CSI: Crime Scene Investigation",20566@0630.22:00,55], A[88542,88541,"outTHERE",63440@0630.23:00,30], A[87714,87713,"Jackass",54797@0630.23:30,30], A[87733,87732,"Jackass",54797@0701.00:00,30], A[87740,87739,"Jackass",54797@0701.00:30,30], A[87753,87752,"Jackass",54797@0701.01:00,60], A[87777,87776,"Big Brother",35048@0701.02:20,30], A[89063,89061,"Hot Summer Down Under",56969@0701.03:55,50]]
Sun 6/29 1:33:24.021 Seeker awoken
Sun 6/29 1:33:24.021 MARK 1 currRecord=A[79962,79961,"Jackass",54797@0629.01:30,30] enc=Hauppauge WinTV PVR PCI II Capture clients=[]
Sun 6/29 1:33:24.021 Seeker in AUTOMATIC mode nextRecord=A[81789,81788,"Top of the Pops",6162@0629.02:05,30] nextTTA=1895979
Sun 6/29 1:33:24.021 newRecord=A[79962,79961,"Jackass",54797@0629.01:30,30]
Sun 6/29 1:33:24.021 Keeping record just the way it is.
Sun 6/29 1:33:24.021 RootFile=F:\ fstype=NTFS fileLength=178253760
Sun 6/29 1:33:24.021 VF processing job null nPlayin=false
Sun 6/29 1:33:24.021 VF thread is now waiting for 0:00:00.000
Sun 6/29 1:33:24.031 needFreeSize = 0.8154 GB currFreeSize=9.849619456 GB
Sun 6/29 1:33:24.031 Seeker waiting for 26 mins.
Sun 6/29 1:33:26.955 Received command of:WATCH_FINISH from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:33:26.955 Seeker.finishWatch(/192.168.0.12:1060)
Sun 6/29 1:33:26.955 Seeker awoken
Sun 6/29 1:33:26.955 Received command of:WATCH_FILE 86327 from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:33:26.955 Seeker.finishWatch(/192.168.0.12:1060)
Sun 6/29 1:33:26.955 MARK 1 currRecord=A[79962,79961,"Jackass",54797@0629.01:30,30] enc=Hauppauge WinTV PVR PCI II Capture clients=[]
Sun 6/29 1:33:26.955 Seeker in AUTOMATIC mode nextRecord=A[81789,81788,"Top of the Pops",6162@0629.02:05,30] nextTTA=1893045
Sun 6/29 1:33:26.955 newRecord=A[79962,79961,"Jackass",54797@0629.01:30,30]
Sun 6/29 1:33:26.955 Keeping record just the way it is.
Sun 6/29 1:33:26.955 RootFile=F:\ fstype=NTFS fileLength=181436352
Sun 6/29 1:33:26.955 VF processing job null nPlayin=false
Sun 6/29 1:33:26.955 VF thread is now waiting for 0:00:00.000
Sun 6/29 1:33:26.965 needFreeSize = 0.8154 GB currFreeSize=9.8464512 GB
Sun 6/29 1:33:26.965 Seeker waiting for 26 mins.
Sun 6/29 1:33:27.096 Error in MediaServerConnection of :java.io.EOFException
java.io.EOFException
Sun 6/29 1:33:27.096 at sage.as.a(Unknown Source)
Sun 6/29 1:33:27.096 at sage.as$a.run(Unknown Source)
Sun 6/29 1:33:27.096 at java.lang.Thread.run(Unknown Source)
Sun 6/29 1:33:28.277 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:33:43.279 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:33:58.280 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:34:13.282 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:34:28.284 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:34:43.285 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:34:58.287 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:35:13.288 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:35:28.290 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:35:43.291 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:35:58.293 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:36:13.295 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:36:28.286 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:36:41.285 Received command of:GET_PRETTYSCHEDULE from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:36:43.288 Received command of:NOOP from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:36:51.009 Received command of:RECORD 87155 from Socket[addr=/192.168.0.12,port=1061,localport=42024]
Sun 6/29 1:36:51.009 Called Seeker.record(A[87155,81772,"Glastonbury 2003",33264@0628.23:10,170])
Sun 6/29 1:36:51.009 findBestEncoderForNow(A[87155,81772,"Glastonbury 2003",33264@0628.23:10,170] record=true host=/192.168.0.12:1060)
Sun 6/29 1:37:54.230 Error communicating with client:java.net.SocketException: Connection reset
Sun 6/29 1:37:54.230 Connection lost from: Socket[addr=/192.168.0.12,port=1061,localport=42024] by:java.net.SocketException: Connection reset by peer: socket write error
Sun 6/29 1:37:54.230 Cleaning up c/s connection
Sun 6/29 1:37:54.230 Scheduler awoken
Sun 6/29 1:37:54.230 Error in MediaServerConnection of :java.net.SocketException: Connection reset
java.net.SocketException: Connection reset
Sun 6/29 1:37:54.230 at java.net.SocketInputStream.read(Unknown Source)
Sun 6/29 1:37:54.230 at java.io.BufferedInputStream.fill(Unknown Source)
Sun 6/29 1:37:54.230 at java.io.BufferedInputStream.read(Unknown Source)
Sun 6/29 1:37:54.230 at sage.as.a(Unknown Source)
Sun 6/29 1:37:54.230 at sage.as$a.run(Unknown Source)
Sun 6/29 1:37:54.230 at java.lang.Thread.run(Unknown Source)
Sun 6/29 1:37:54.230 Scheduler.updateSchedule() called time=Sun 6/29 1:37:54.230 manual=[ManualRecord[A[14990,14988,"Bo' Selecta!",35048@0606.23:15,35] time=Fri 6/6 23:15:00.000 dur=0:35:00], ......

Sun 6/29 1:37:54.250 Evaluating Potentials
Sun 6/29 1:37:54.260 COMPLETE SCHEDULE-----**&^%&*-------COMPLETE SCHEDULE

Narflex · #4 06-30-2003, 11:53 AM

Standard socket communication failure; extremely rare on a LAN, but somewhat common over internet connections. This'll be accounted for when I add error recovery to the networking system (which'll be pretty soon).

jimbobuk · #5 06-30-2003, 02:07 PM

Thanks Narflex...

I have had problems with this hub, i dont know what causes them...

netstat -e tells you this kind of stuff...

error recovery sounds great...

Thanks its pretty rare so far, and thankfully working with a client seems to let the server survive a lot of problems.

Narflex · #6 06-30-2003, 07:50 PM

Added error recovery this afternoon, it'll be in the next release. It's pretty sweet. I unplug the Ethernet cable and SageTVClient pops up a message saying it lost its connection and its attempting to reconnect. After I plug it back in and wait a bit, SageTVClient comes back to life and all is well. Pretty neato.

jimbobuk · #7 07-01-2003, 02:08 PM

great stuff ... look forward to it... its got to help for future internet client work.. for those lucky enough to have the bandwidth to get tv over internet.. which will be about 3 people i guess

but still for me and anyone else with LAN issues its also very very useful...

Thanks thanks thanks

Currently Active Users Viewing This Thread: 1 (0 members and 1 guests)