Skip to main content

Encountering unexpected 'start-of-file' during trickplay at -16X

7 replies [Last post]
abysubin
Offline
Joined: 2011-07-31
Points: 0

For testing the trickplay at -16x (16X rewind) , i ran a test which does the following sequence:

  1. Select a service
  2. After succesfully attaching a time shift buffer, wait for 20 seconds for buffering to build
  3. Set the rate as -16X

The issue that i'm facing is, intermittently (very very rarely) the trick play reaches the start of file very soon after the start of trick play. (within 1 second ) and then sets the current rate as 1X. The relevant log is added below:

20110720 08:51:59.439 INFO RI.Stack- 2821703 [Thread-36] INFO player.AbstractPlayer - setRate(-16.0) [Started, Presenting]
20110720 08:51:59.439 INFO RI.Stack- 2821703 [Thread-36] INFO presentation.AbstractPresentation - setRate(-16.0), current mediatime: 25.281000000000002s (25281000000ns)
20110720 08:51:59.439 INFO RI.Stack- 2821703 [Thread-36] INFO presentation.TSBServicePresentation - switchToTimeShift - mediaTime: 25.281000000000002s (25281000000ns), rate: -16.0
20110720 08:51:59.439 INFO RI.Stack- 2821703 [Thread-36] INFO presentation.TSBServicePresentation - attaching for bufferplayback use
20110720 08:51:59.455 INFO RI.Stack- 2821719 [Thread-36] INFO presentation.AbstractDVRServicePresentation - setLive: false, was: true
20110720 08:51:59.455 INFO RI.Stack- 2821719 [Thread-36] INFO presentation.AbstractServicePresentation - doStopInternal - calling doStop: true
20110720 08:51:59.455 INFO RI.Stack- 2821719 [Thread-36] INFO presentation.AbstractServicePresentation - updateState - from: STATE_NORMAL_CONTENT_SESSION_STARTED to STATE_PRESENTATION_NOT_STARTED
20110720 08:51:59.455 INFO RI.Stack- 2821719 [Thread-36] INFO presentation.AbstractServicePresentation - doStop - shutting down: false - stopping currentSession and setting to null: BroadcastSession - networkInterface:org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@988a601b, decodehandle: 226523024 decryptHandle=null, 7adb7d7a, started: true, lock=java.lang.Object@1e0b01a6, details(id)=ServiceDetailsImpl430362136, video=0xd79af80, started=true, blocked=false
20110720 08:51:59.455 INFO RI.Stack- 2821719 [Thread-36] INFO session.BroadcastSession - stop: BroadcastSession - networkInterface:org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@988a601b, decodehandle: 226523024 decryptHandle=null, 7adb7d7a, started: true, lock=java.lang.Object@1e0b01a6, details(id)=ServiceDetailsImpl430362136, video=0xd79af80, started=true, blocked=false
20110720 08:51:59.455 INFO RI.Stack- 2821719 [Thread-36] INFO session.BroadcastSession - stop - hold frame: true
20110720 08:51:59.455 INFO RI.Stack- mpeos_mediaStop() - called
20110720 08:51:59.455 INFO RI.Display.VideoDevice- decode_bin_modify_link -- Detaching video device to pipeline: live pipeline
20110720 08:51:59.455 WARN RI.GStreamer- gstesassembler.c gst_es_assembler_event:498 Received EOS event
20110720 08:51:59.455 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:417 Received EOS event.
20110720 08:52:00.455 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:422 Received FLUSH_START event.
20110720 08:52:00.455 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:426 Received FLUSH_STOP event.
20110720 08:52:00.455 INFO RI.Stack- 2822719 [Thread-36] INFO session.BroadcastSession - stopped decode: BroadcastSession - networkInterface:org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@988a601b, decodehandle: -1 decryptHandle=null, 7adb7d7a, started: false, lock=java.lang.Object@1e0b01a6, details(id)=ServiceDetailsImpl430362136, video=0xd79af80, started=false, blocked=false
20110720 08:52:00.455 INFO RI.Stack- 2822719 [Thread-36] INFO presentation.AbstractServicePresentation - resourcesValid: true
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.Selection - isAcceptableDefaultComponents - result: true
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.AbstractServicePresentation - componentsValid: true
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.AbstractServicePresentation - doStopInternal - calling doStop: false
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.AbstractServicePresentation - updateState - from: STATE_PRESENTATION_NOT_STARTED to STATE_NORMAL_CONTENT_SESSION_STARTING
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.AbstractDVRServicePresentation - doCreateSession: Selection { trigger=MODE, svcDetails=org.cablelabs.impl.service.javatv.navigation.ServiceDetailsImpl@138e1ebe[uniqueID=ServiceDetailsImpl430362136, locator=ocap://0x44c, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$ServiceDetailsHandleImpl@19a6ce18[handle=19a6ce18], sourceID=1100, programNumber=2, appID=0, longName=, deliverySystemType=CABLE, serviceInformationType=SCTE_SI, updateTime=Wed Jul 20 01:05:01 GMT-06:00 2011, caSystemIDs=[ ], isFree=true, lsData[language=]], locators=null, isDefault=true, full media access auth: true, conditional access auth: true, hashCode: 0x2f4009f8}, mediaTime: 25.281000000000002s (25281000000ns), rate: -16.0, live: false
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.TSBServicePresentation - createTimeshiftSession(time=25.281000000000002s, rate=-16.0)
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.TSBServicePresentation - createTimeShiftSession - tsb found - creating TSBsession for mediaTime: 25.281000000000002s (25281000000ns), rate: -16.0
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO presentation.AbstractDVRServicePresentation - starting timeshift session
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO session.TSBSession - present: org.cablelabs.impl.service.javatv.navigation.ServiceDetailsImpl@138e1ebe[uniqueID=ServiceDetailsImpl430362136, locator=ocap://0x44c, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$ServiceDetailsHandleImpl@19a6ce18[handle=19a6ce18], sourceID=1100, programNumber=2, appID=0, longName=, deliverySystemType=CABLE, serviceInformationType=SCTE_SI, updateTime=Wed Jul 20 01:05:01 GMT-06:00 2011, caSystemIDs=[ ], isFree=true, lsData[language=]], [ org.cablelabs.impl.service.ServiceComponentExt$DavicElementaryStream@85afe7e1[service=org.cablelabs.impl.service.ServiceDetailsExt$DavicService@85afec59[transportStream=org.cablelabs.impl.service.TransportStreamExt$DavicTransportStream@85afec5b[ni=org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@988a601b, frequency=489000000, modulationFormat=16], serviceId=2], pid=3000, associationTag=null], org.cablelabs.impl.service.ServiceComponentExt$DavicElementaryStream@85afe7e0[service=org.cablelabs.impl.service.ServiceDetailsExt$DavicService@85afec59[transportStream=org.cablelabs.impl.service.TransportStreamExt$DavicTransportStream@85afec5b[ni=org.cablelabs.impl.davic.net.tuning.NetworkInterfaceImpl@988a601b, frequency=489000000, modulationFormat=16], serviceId=2], pid=3001, associationTag=null] ], TSBSession - tsw: TSWC 0x702bec01:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResourceUsageImpl@610318081[id=11127133,prio=220,org.davic.net.tuning.NetworkInterfaceController,org.havi.ui.HVideoDevice,],tsw TSW 0x1f96d5e0:[service ServiceImpl430362136 (ocap://0x44c) ,state BUFFERING,tuner 1,tbst 2753203ms,btsb TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON], nclients 3, TSC:[uses BUFFERING+BUFFPLAYBACK,res NI+LIVEPLAYBACK+BUFFPLAYBACK,mind 10,desd 0,maxd MAX_VAL]],constrain TSC:[uses BUFFPLAYBACK,res LIVEPLAYBACK+BUFFPLAYBACK,mind 0,desd 0,maxd MAX_VAL],1st tsb: none], tsb:TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON], 13020613, time: 23.031000000000002s (23031000000ns), rate: -16.0, playback: null, 13020613, lock=java.lang.Object@1e0b01a6, details(id)=ServiceDetailsImpl430362136, video=0xd79af80, started=false, blocked=false
20110720 08:52:00.471 INFO RI.Stack- 2822735 [Thread-36] INFO mpe.DVRAPIImpl - decodeTSB(): vd=0xd79af80, tsb=0x19c5adf0, pidMapTable=PidMapTable 0xf6dcce03:[0:[streamType: 1, SrcElemType 2, SrcPID 480, RecElemType 0, RecPID -1, ServiceComp org.cablelabs.impl.service.javatv.navigation.ServiceComponentImpl@b19465cb[uniqueID=ServiceComponentImpl431389904, locator=ocap://0x44c.+0xbb8, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$ServiceComponentHandleImpl@19b67cd0[handle=19b67cd0], pid=3000, componentTag=100000000, associationTag=100000000, carouselID=100000000, componentName=, associatedLanguage=, streamType=VIDEO, serviceInformationType=SCTE_SI, updateTime=Wed Jul 20 01:05:50 GMT-06:00 2011, lsData[language=], sdsData=null]],1:[streamType: 2, SrcElemType 129, SrcPID 736, RecElemType 0, RecPID -1, ServiceComp org.cablelabs.impl.service.javatv.navigation.ServiceComponentImpl@faa72580[uniqueID=ServiceComponentImpl432331744, locator=ocap://0x44c.+0xbb9, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$ServiceComponentHandleImpl@19c4dbe0[handle=19c4dbe0], pid=3001, componentTag=100000000, associationTag=100000000, carouselID=100000000, componentName=, associatedLanguage=eng, streamType=AUDIO, serviceInformationType=SCTE_SI, updateTime=Wed Jul 20 01:05:50 GMT-06:00 2011, lsData[language=], sdsData=null]],2:[streamType: 6, SrcElemType 0, SrcPID 480, RecElemType 0, RecPID -1, ServiceComp org.cablelabs.impl.service.javatv.navigation.ServiceComponentImpl@8424d4fe[uniqueID=ServiceComponentImpl431389904, locator=ocap://0x44c.+0xbb8, handle=org.cablelabs.impl.manager.service.SIDatabaseImpl$ServiceComponentHandleImpl@19b67cd0[handle=19b67cd0], pid=3000, componentTag=100000000, associationTag=100000000, carouselID=100000000, componentName=, associatedLanguage=, streamType=VIDEO, serviceInformationType=SCTE_SI, updateTime=Wed Jul 20 01:05:50 GMT-06:00 2011, lsData=null, sdsData=null]]], start=23031000000, rate=-16.0, blocked=false
20110720 08:52:00.486 INFO RI.Stack- jniutil_convertToDvrPidInfoArray - ENTER -
20110720 08:52:00.486 INFO RI.Stack- <<DVR>> mpeos_dvrTsbPlayStart - TSB = 19C5ADF0, mediaTime = 23031000000, playRate = -16.000000
20110720 08:52:00.486 INFO RI.Pipeline.TSB- tsb_playback_start -- Dump of PIDs:
20110720 08:52:00.486 INFO RI.Pipeline.TSB- 0x01E0, type is RI_MEDIA_TYPE_VIDEO
20110720 08:52:00.486 INFO RI.Pipeline.TSB- 0x02E0, type is RI_MEDIA_TYPE_AUDIO
20110720 08:52:00.486 INFO RI.Pipeline.TSB- 0x01E0, type is RI_MEDIA_TYPE_PCR
20110720 08:52:00.486 INFO RI.Pipeline- recording_playback_start -- Requested: filepath = C:/w/ridev--REL_CL1.1.4RELI_NDSRI0.11.1--tdk_0.11.2_TCs--RI_Tu2HnDvr_w32/ri.inst/ocap/bin/CableLabs/simulator/Win32/debug/env/storage/I1/TSB, filename = 4E267E44_0029, position = 23031000000, rate = -16.000000
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:321 New filepath set: "C:/w/ridev--REL_CL1.1.4RELI_NDSRI0.11.1--tdk_0.11.2_TCs--RI_Tu2HnDvr_w32/ri.inst/ocap/bin/CableLabs/simulator/Win32/debug/env/storage/I1/TSB".
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:332 New filename set: "4E267E44_0029".
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:354 New time position set: 0:00:23.031000000.
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:347 New playrate set: -16.000000.
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:341 New framerate set: 2.
20110720 08:52:00.486 INFO RI.Display.VideoDevice- decode_bin_modify_link -- Attaching video device to pipeline: playback-local pipeline
20110720 08:52:00.486 INFO RI.Pipeline- bus_call -- flushing pipeline due to EOS
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_reset:1026 resetting
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:700 IfsOpenReader succeeded, handle: 25F11F38.
20110720 08:52:00.486 WARN RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:724 calling IfsSeekToTime using end_offset since it is not IFS_UNDEFINED_CLOCK.
20110720 08:52:00.486 WARN RI.IFS- IfsReturnCodeSeekOutsideFile: 1311148287.504219000 < 1311148295.425638000 (begClock) in line 2467 of IfsImpl.c
20110720 08:52:00.486 WARN RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:730 Initial IfsSeek to end position 364207:51:35.425638000 returned Seek Outside File for IFS handle 25F11F38.
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_close:772 Non-NULL IFS handle 25F11F38, closing.
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_close:782 IfsClose succeeded for handle 25F11F38.
20110720 08:52:00.486 INFO RI.Pipeline- bus_call -- beginning of file encountered

20110720 08:52:00.486 INFO RI.Pipeline- decode() -- video pid 0x01E0 (remapped to 1E0)
20110720 08:52:00.486 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:700 IfsOpenReader succeeded, handle: 25F11F38.
20110720 08:52:00.502 WARN RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:736 ignoring end_offset
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:739 calling IfsSeekToTime IFS Recording: path "C:/w/ridev--REL_CL1.1.4RELI_NDSRI0.11.1--tdk_0.11.2_TCs--RI_Tu2HnDvr_w32/ri.inst/ocap/bin/CableLabs/simulator/Win32/debug/env/storage/I1/TSB", name "4E267E44_0029", start 364207:51:35.425638000, end 364207:52:00.486695000.
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_create:502 File settings change detected, opening new resource.
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_close:772 Non-NULL IFS handle 25F11F38, closing.
20110720 08:52:00.502 INFO RI.Stack- 2822766 [Thread-36] INFO presentation.TSBServicePresentation - TSBsession started - native mediatime: 23031000000, tsb startTimeOffset: 2250000000, native rate: -16.0, updating clock with mediatime: 25281000000 and rate: -16.0
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_close:782 IfsClose succeeded for handle 25F11F38.
20110720 08:52:00.502 INFO RI.Stack- 2822766 [Thread-36] INFO player.AbstractPlayer - clock rate changed from: 1.0 to -16.0
20110720 08:52:00.502 INFO RI.Stack- 2822766 [Thread-36] INFO player.AbstractPlayer - clock mediatime changed from: 26.344s (26344000000ns) to 25.281000000000002s (25281000000ns)
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:700 IfsOpenReader succeeded, handle: 25F11F38.
20110720 08:52:00.502 WARN RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:704 ifs_offset is not IFS_UNDEFINED_CLOCK.
20110720 08:52:00.502 WARN RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:736 ignoring end_offset
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:739 calling IfsSeekToTime IFS Recording: path "C:/w/ridev--REL_CL1.1.4RELI_NDSRI0.11.1--tdk_0.11.2_TCs--RI_Tu2HnDvr_w32/ri.inst/ocap/bin/CableLabs/simulator/Win32/debug/env/storage/I1/TSB", name "4E267E44_0029", start 364207:51:35.425638000, end 364207:52:00.486695000.
20110720 08:52:00.502 INFO RI.Stack- 2822766 [Thread-36] INFO presentation.AbstractServicePresentation - currentSession set to: TSBSession - tsw: TSWC 0x702bec01:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResourceUsageImpl@610318081[id=11127133,prio=220,org.davic.net.tuning.NetworkInterfaceController,org.havi.ui.HVideoDevice,],tsw TSW 0x1f96d5e0:[service ServiceImpl430362136 (ocap://0x44c) ,state BUFFERING,tuner 1,tbst 2753203ms,btsb TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON], nclients 3, TSC:[uses BUFFERING+BUFFPLAYBACK,res NI+LIVEPLAYBACK+BUFFPLAYBACK,mind 10,desd 0,maxd MAX_VAL]],constrain TSC:[uses BUFFPLAYBACK,res LIVEPLAYBACK+BUFFPLAYBACK,mind 0,desd 0,maxd MAX_VAL],1st tsb:TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON]], tsb:TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON], 13020613, time: 23.031000000000002s (23031000000ns), rate: -16.0, playback: 0x25121ec0, 13020613, lock=java.lang.Object@1e0b01a6, details(id)=ServiceDetailsImpl430362136, video=0xd79af80, started=true, blocked=false
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_create:535 Attemping to execute requested time seek to 0:00:23.031000000.
20110720 08:52:00.502 INFO RI.Stack- 2822766 [Thread-36] INFO presentation.AbstractDVRServicePresentation - doSetRate - returning rate: -16.0
20110720 08:52:00.502 INFO RI.Stack- 2822766 [Thread-36] INFO player.AbstractPlayer - clock rate changed from: -16.0 to -16.0
20110720 08:52:00.502 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:422 Received FLUSH_START event.
20110720 08:52:00.502 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:426 Received FLUSH_STOP event.
20110720 08:52:00.502 INFO RI.Pipeline- playbackStateStarting -- state = PLAYBACK_STATE_STARTING - playback rate is -16.000000
20110720 08:52:00.502 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:422 Received FLUSH_START event.
20110720 08:52:00.502 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:426 Received FLUSH_STOP event.
20110720 08:52:00.502 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_create:623 Switch from 1x playback to trick-play: buffer timestamps will restart from 0:00:00.000000000.
20110720 08:52:00.517 INFO RI.Stack- 2822781 [pool-1] INFO presentation.AbstractDVRServicePresentation - handleSessionEventAsync - session: TSBSession - tsw: TSWC 0x702bec01:[nlist 1,ru org.cablelabs.impl.service.ServiceContextResourceUsageImpl@610318081[id=11127133,prio=220,org.davic.net.tuning.NetworkInterfaceController,org.havi.ui.HVideoDevice,],tsw TSW 0x1f96d5e0:[service ServiceImpl430362136 (ocap://0x44c) ,state BUFFERING,tuner 1,tbst 2753203ms,btsb TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON], nclients 3, TSC:[uses BUFFERING+BUFFPLAYBACK,res NI+LIVEPLAYBACK+BUFFPLAYBACK,mind 10,desd 0,maxd MAX_VAL]],constrain TSC:[uses BUFFPLAYBACK,res LIVEPLAYBACK+BUFFPLAYBACK,mind 0,desd 0,maxd MAX_VAL],1st tsb:TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON]], tsb:TSB 0xbda3a4f6[size 5010,ntsb 0x19c5adf0,sysbufstart/end Wed Jul 20 01:51:36 GMT-06:00 2011/Wed Jul 20 01:52:00 GMT-06:00 2011,tbstart/end 2755453ms/9223372036854ms,tswoffset 2250ms,bufstopreason NOREASON], 13020613, time: 23.031000000000002s (23031000000ns), rate: -16.0, playback: 0x25121ec0, 13020613, lock=java.lang.Object@1e0b01a6, details(id)=ServiceDetailsImpl430362136, video=0xd79af80, started=true, blocked=false, event: DVR.START_OF_FILE, data1: 0, data2: 0
20110720 08:52:00.517 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:413 Received NEWSEGMENT event.
20110720 08:52:00.517 WARN RI.GStreamer- gstpad.c gst_pad_buffer_alloc_unchecked:2724 Buffer allocation function did not set caps. Setting
20110720 08:52:00.517 WARN RI.IFS- IfsReturnCodeSeekOutsideFile: 1311148294.502434000 < 1311148295.425638000 (begClock) in line 2467 of IfsImpl.c
20110720 08:52:00.517 INFO RI.Stack.StdOut- [DCLI-CLIENT] [INFO] [PlayerUtil$ControllerListenerImpl.controllerUpdate: 254] - controllerEventorg.ocap.shared.media.LeavingLiveModeEvent[source=TSBServiceMediaHandler@51c72851]
20110720 08:52:00.517 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_seek_to_time:954 Attempt to seek outside of the file, generating EOS.
20110720 08:52:00.517 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_reset:1026 resetting
20110720 08:52:00.517 WARN RI.GStreamer- gstesassembler.c gst_es_assembler_event:498 Received EOS event
20110720 08:52:00.517 INFO RI.Stack- 2822781 [pool-1] INFO presentation.TSBServicePresentation - startOfFile - no preceedingTSB - notifying beginning of content and setting rate to 1.0 - current mediatime: 25.281000000000002s (25281000000ns)
20110720 08:52:00.517 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:347 New playrate set: 1.000000.
20110720 08:52:00.517 INFO RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_set_property:341 New framerate set: 30.
20110720 08:52:00.517 INFO RI.Stack- 2822781 [pool-1] INFO player.AbstractPlayer - clock rate changed from: -16.0 to 1.0
20110720 08:52:00.517 INFO RI.GStreamer- gstmpegdecoder.c gst_mpeg_decoder_event:417 Received EOS event.
20110720 08:52:00.549 INFO RI.Stack.StdOut- [DCLI-CLIENT] [INFO] [PlayerUtil$ControllerListenerImpl.controllerUpdate: 254] - controllerEventjavax.media.RateChangeEvent[source=TSBServiceMediaHandler@51c72851,rate=-16.0]

The complete log is attached here with (error_log.txt)

Since i'm waiting for 20 seconds for buffering, it should do trickplay at -16x for atleast 1+ seconds theoretically. right? Or am i missing something ? Can someone help me in getting the reason for encountering this unexpected start-of-file ?

AttachmentSize
error_log.txt71.98 KB

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
mkorzen
Offline
Joined: 2008-03-05
Points: 0

Could you provide a full log from a run when this situation occurs? It should include the RI start-up messages.

Is this particular attempt of TSB playback preceeded by another one (either recording or TSB)?

What I suspect is occuring is this:

1. A successful TSB/recording playback with positive rate reaches EOS (end of stream).

2. gst_trick_play_file_src_reset is called, which sets the end_offset to something other than IFS_UNDEFINED_CLOCK. This happens in anticipation of a playback restart, using _the same_ underlying IFS file resource.

3. Instead of another playback/rewind/fast-forward command for the current TSB/recording, a request to issue new playback from a different TSB/recording is made. This causes new filepath and new filename properties to be set but does not reset the end_offset value to IFS_UNDEFINED_CLOCK (potential bug).

4. When a playback of -16x is requested is made, the end_offset value from previous TSB/recording session is used - causing a seek attempt to time prior to the begClock of the current TSB:

20110720 08:52:00.486 WARN RI.GStreamer- gsttrickplayfilesrc.c gst_trick_play_file_src_open:724 calling IfsSeekToTime using end_offset since it is not IFS_UNDEFINED_CLOCK.
20110720 08:52:00.486 WARN RI.IFS- IfsReturnCodeSeekOutsideFile: 1311148287.504219000 < 1311148295.425638000 (begClock) in line 2467 of IfsImpl.c

As you can see there is an attempt to seek to 1311148287.504219000 (364207:51:27.504219000), which is 7s before the start of the current TSB:

20110720 08:51:35.425 INFO RI.IFS- set begClock to 1311148295.425638000 at line 1545 of IfsImpl.c

abysubin
Offline
Joined: 2011-07-31
Points: 0

Thank you for your reply.

Please find attached the complete logs that include the RI start-up messages. In line 23078 (at time stamp 20110720 08:52:00.486 ), we come across the info log -" RI.Pipeline- bus_call -- beginning of file encountered "

scottdeboy
Offline
Joined: 2009-02-02
Points: 0

I see a few other issues in your log that I'd like to examine more closely - would you mind generating a log with JAVA DEBUG verbosity enabled in mpeenv.ini?

Thanks

Scott

abysubin
Offline
Joined: 2011-07-31
Points: 0

Hi Scott,

This issue is very very intermittent and i could not reproduce with debug enabled. I will continue trying the same and will provide the logs if i come across this issue again.

Thanks

Aby

mkorzen
Offline
Joined: 2008-03-05
Points: 0

Thank you for the full log. This is definitely a bug:

1. The said error occurs for a TSB "4E267E44_0029", which starts at 1311148295.425638000.

2. The requested before-beginning-of-file seek to 1311148287.504219000 happens because end_offset is set when playback starts.

3. end_offset is set, when a 16x fast forward is performed on the TSB "4E267E44_4823", which goes from 1311148261.974440000 to 1311148287.504219000.

20110720 08:51:27.566 WARN RI.IFS- IfsReturnCodeSeekOutsideFile: 1311148288.989440000 > 1311148287.504219000 (endClock) in line 2476 of IfsImpl.c

Please file an Jira issue for this...

abysubin
Offline
Joined: 2011-07-31
Points: 0

Thank you for your cofirmation. Jira issue is raised for the same : http://java.net/jira/browse/OCAP_RI-544

abysubin
Offline
Joined: 2011-07-31
Points: 0

Any updates from anyone?