Packager stops packetizing from live sources in live profile #93

peyoh · 2016-02-29T15:06:44Z

Hello,
I'm using edash-packager ver. 1.3.1. But sometimes, it just stops.
On the ethernet interface I'm able to see the input sources. The multicast groups are joined and the UDP streams comes to the interface.

After restart it continues to work.

Command line is:
Debug/packager --udp_interface_address=10.0.8.33 input=udp://239.204.6.121:7000,stream=audio,init_segment=/storage/web/dash/662/edash-audio.mp4,segment_template=/storage/web/dash/662/edash-audio-$Number$.mp4 input=udp://239.204.6.121:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-576.mp4,segment_template=/storage/web/dash/662/edash-video-576-$Number$.mp4 input=udp://239.204.6.122:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-512.mp4,segment_template=/storage/web/dash/662/edash-video-512-$Number$.mp4 input=udp://239.204.6.123:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-384.mp4,segment_template=/storage/web/dash/662/edash-video-384-$Number$.mp4 input=udp://239.204.6.124:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-288.mp4,segment_template=/storage/web/dash/662/edash-video-288-$Number$.mp4 --profile live --mpd_output /storage/web/dash/662/662.mpd -time_shift_buffer_depth 86400 -dump_stream_info -availability_time_offset 10

Manifest is:


<?xml version="1.0" encoding="UTF-8"?>
<!--Generated with https://github.com/google/edash-packager version 0d3951f-debug-->
<MPD xmlns="urn:mpeg:dash:schema:mpd:2011" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xlink="http://www.w3.org/1999/xlink" xsi:schemaLocation="urn:mpeg:dash:schema:mpd:2011 DASH-MPD.xsd" xmlns:cenc="urn:mpeg:cenc:2013" minBufferTime="PT2S" type="dynamic" profiles="urn:mpeg:dash:profile:isoff-live:2011" publishTime="2016-02-29T15:01:32Z" availabilityStartTime="2016-02-28T19:17:08Z" minimumUpdatePeriod="PT5S" timeShiftBufferDepth="PT86400S">
  <Period id="0" start="PT0S">
    <AdaptationSet id="0" contentType="audio" segmentAlignment="true">
      <Representation id="0" bandwidth="138659" codecs="mp4a.40.2" mimeType="audio/mp4" audioSamplingRate="48000">
        <AudioChannelConfiguration schemeIdUri="urn:mpeg:dash:23003:3:audio_channel_configuration:2011" value="2"/>
        <SegmentTemplate timescale="90000" initialization="edash-audio.mp4" media="edash-audio-$Number$.mp4" startNumber="1">
          <SegmentTimeline>
            <S t="6000483536" d="900480" r="195"/>
          </SegmentTimeline>
        </SegmentTemplate>
      </Representation>
    </AdaptationSet>
    <AdaptationSet id="1" contentType="video" maxWidth="720" maxHeight="576" frameRate="90000/3600" par="16:9">
      <Representation id="1" bandwidth="479716" codecs="avc1.4d0015" mimeType="video/mp4" sar="64:45" width="360" height="288">
        <SegmentTemplate timescale="90000" initialization="edash-video-288.mp4" media="edash-video-288-$Number$.mp4" startNumber="1">
          <SegmentTimeline>
            <S t="6000804416" d="950400" r="344"/>
            <S t="6328692416" d="12787200"/>
            <S t="6341479616" d="950400" r="58"/>
          </SegmentTimeline>
        </SegmentTemplate>
      </Representation>
      <Representation id="2" bandwidth="1696409" codecs="avc1.4d001e" mimeType="video/mp4" sar="64:45" width="640" height="512">
        <SegmentTemplate timescale="90000" initialization="edash-video-512.mp4" media="edash-video-512-$Number$.mp4" startNumber="1">
          <SegmentTimeline>
            <S t="6000631616" d="950400" r="184"/>
          </SegmentTimeline>
        </SegmentTemplate>
      </Representation>
      <Representation id="3" bandwidth="897907" codecs="avc1.4d0015" mimeType="video/mp4" sar="64:45" width="480" height="384">
        <SegmentTemplate timescale="90000" initialization="edash-video-384.mp4" media="edash-video-384-$Number$.mp4" startNumber="1">
          <SegmentTimeline>
            <S t="6000718016" d="950400" r="184"/>
          </SegmentTimeline>
        </SegmentTemplate>
      </Representation>
      <Representation id="4" bandwidth="1996114" codecs="avc1.4d001e" mimeType="video/mp4" sar="64:45" width="720" height="576">
        <SegmentTemplate timescale="90000" initialization="edash-video-576.mp4" media="edash-video-576-$Number$.mp4" startNumber="1">
          <SegmentTimeline>
            <S t="6000549056" d="950400" r="184"/>
          </SegmentTimeline>
        </SegmentTemplate>
      </Representation>
    </AdaptationSet>
  </Period>
</MPD>

GDB shows:

(gdb) thread apply all bt

Thread 8 (Thread 0x7f371ba33700 (LWP 5484)):
#0  0x00007f371e2036d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006d9795 in base::ConditionVariable::Wait (this=0x7f371ba320d8) at ../../packager/base/synchronization/condition_variable_posix.cc:54
#2  0x00000000006db18e in base::WaitableEvent::TimedWait (this=0x1137948, max_time=...) at ../../packager/base/synchronization/waitable_event_posix.cc:214
#3  0x00000000006dadf6 in base::WaitableEvent::Wait (this=0x1137948) at ../../packager/base/synchronization/waitable_event_posix.cc:154
#4  0x0000000000435a8e in edash_packager::media::IoCache::Write (this=0x1137910, buffer=0x7f371ba34010, size=1316) at ../../packager/media/file/io_cache.cc:76
#5  0x0000000000432778 in edash_packager::media::ThreadedIoFile::RunInInputMode (this=0x11378f0) at ../../packager/media/file/threaded_io_file.cc:175
#6  0x0000000000431597 in edash_packager::media::ThreadedIoFile::TaskHandler (this=0x11378f0) at ../../packager/media/file/threaded_io_file.cc:156
#7  0x0000000000433589 in base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>::Run (this=0x7f371ba32c90, object=0x11378f0)
    at ../../packager/base/bind_internal.h:176
#8  0x00000000004334cc in base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >::MakeItSo (runnable=..., args=0x11378f0) at ../../packager/base/bind_internal.h:293
#9  0x0000000000433498 in base::internal::Invoker<base::IndexSequence<0ul>, base::internal::BindState<base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, void (edash_packager::media::ThreadedIoFile*), base::internal::TypeList<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::TypeList<base::internal::UnwrapTraits<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >, void ()>::Run(base::internal::BindStateBase*) (base=0x1137140) at ../../packager/base/bind_internal.h:343
#10 0x000000000068509e in base::Callback<void ()>::Run() const (this=0x7f371ba32e08) at ../../packager/base/callback.h:396
#11 0x00000000006fbb49 in base::(anonymous namespace)::WorkerThread::ThreadMain (this=0x1138390) at ../../packager/base/threading/worker_pool_posix.cc:98
#12 0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7ffd0f895e80) at ../../packager/base/threading/platform_thread_posix.cc:74
#13 0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x7f3718e2f700 (LWP 5485)):
#0  0x00007f371e2036d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006d9795 in base::ConditionVariable::Wait (this=0x7f3718e2e0d8) at ../../packager/base/synchronization/condition_variable_posix.cc:54
#2  0x00000000006db18e in base::WaitableEvent::TimedWait (this=0x11545f8, max_time=...) at ../../packager/base/synchronization/waitable_event_posix.cc:214
#3  0x00000000006dadf6 in base::WaitableEvent::Wait (this=0x11545f8) at ../../packager/base/synchronization/waitable_event_posix.cc:154
#4  0x0000000000435a8e in edash_packager::media::IoCache::Write (this=0x11545c0, buffer=0x7f3718e30010, size=1316) at ../../packager/media/file/io_cache.cc:76
#5  0x0000000000432778 in edash_packager::media::ThreadedIoFile::RunInInputMode (this=0x11545a0) at ../../packager/media/file/threaded_io_file.cc:175
#6  0x0000000000431597 in edash_packager::media::ThreadedIoFile::TaskHandler (this=0x11545a0) at ../../packager/media/file/threaded_io_file.cc:156
#7  0x0000000000433589 in base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>::Run (this=0x7f3718e2ec90, object=0x11545a0)
    at ../../packager/base/bind_internal.h:176
#8  0x00000000004334cc in base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >::MakeItSo (runnable=..., args=0x11545a0) at ../../packager/base/bind_internal.h:293
#9  0x0000000000433498 in base::internal::Invoker<base::IndexSequence<0ul>, base::internal::BindState<base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, void (edash_packager::media::ThreadedIoFile*), base::internal::TypeList<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::TypeList<base::internal::UnwrapTraits<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >, void ()>::Run(base::internal::BindStateBase*) (base=0x1154890) at ../../packager/base/bind_internal.h:343
#10 0x000000000068509e in base::Callback<void ()>::Run() const (this=0x7f3718e2ee08) at ../../packager/base/callback.h:396
#11 0x00000000006fbb49 in base::(anonymous namespace)::WorkerThread::ThreadMain (this=0x1138b20) at ../../packager/base/threading/worker_pool_posix.cc:98
#12 0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7ffd0f895e80) at ../../packager/base/threading/platform_thread_posix.cc:74
#13 0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x7f3711ffe700 (LWP 5486)):
#0  0x00007f371e2036d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006d9795 in base::ConditionVariable::Wait (this=0x7f3711ffd0d8) at ../../packager/base/synchronization/condition_variable_posix.cc:54
#2  0x00000000006db18e in base::WaitableEvent::TimedWait (this=0x114a518, max_time=...) at ../../packager/base/synchronization/waitable_event_posix.cc:214
#3  0x00000000006dadf6 in base::WaitableEvent::Wait (this=0x114a518) at ../../packager/base/synchronization/waitable_event_posix.cc:154
#4  0x0000000000435a8e in edash_packager::media::IoCache::Write (this=0x114a4e0, buffer=0x7f371822d010, size=1316) at ../../packager/media/file/io_cache.cc:76
#5  0x0000000000432778 in edash_packager::media::ThreadedIoFile::RunInInputMode (this=0x114a4c0) at ../../packager/media/file/threaded_io_file.cc:175
---Type <return> to continue, or q <return> to quit---  
#6  0x0000000000431597 in edash_packager::media::ThreadedIoFile::TaskHandler (this=0x114a4c0) at ../../packager/media/file/threaded_io_file.cc:156
#7  0x0000000000433589 in base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>::Run (this=0x7f3711ffdc90, object=0x114a4c0)
    at ../../packager/base/bind_internal.h:176
#8  0x00000000004334cc in base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >::MakeItSo (runnable=..., args=0x114a4c0) at ../../packager/base/bind_internal.h:293
#9  0x0000000000433498 in base::internal::Invoker<base::IndexSequence<0ul>, base::internal::BindState<base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, void (edash_packager::media::ThreadedIoFile*), base::internal::TypeList<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::TypeList<base::internal::UnwrapTraits<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >, void ()>::Run(base::internal::BindStateBase*) (base=0x11438e0) at ../../packager/base/bind_internal.h:343
#10 0x000000000068509e in base::Callback<void ()>::Run() const (this=0x7f3711ffde08) at ../../packager/base/callback.h:396
#11 0x00000000006fbb49 in base::(anonymous namespace)::WorkerThread::ThreadMain (this=0x1143660) at ../../packager/base/threading/worker_pool_posix.cc:98
#12 0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7ffd0f895e80) at ../../packager/base/threading/platform_thread_posix.cc:74
#13 0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7f37115fc700 (LWP 5490)):
#0  0x00007f371e206623 in recvfrom () from /lib64/libpthread.so.0
#1  0x00000000004339da in edash_packager::media::UdpFile::Read (this=0x1144e90, buffer=0x7f37115fd010, length=2097152) at ../../packager/media/file/udp_file_posix.cc:109
#2  0x00000000004326c5 in edash_packager::media::ThreadedIoFile::RunInInputMode (this=0x1145d00) at ../../packager/media/file/threaded_io_file.cc:167
#3  0x0000000000431597 in edash_packager::media::ThreadedIoFile::TaskHandler (this=0x1145d00) at ../../packager/media/file/threaded_io_file.cc:156
#4  0x0000000000433589 in base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>::Run (this=0x7f37115fbc90, object=0x1145d00)
    at ../../packager/base/bind_internal.h:176
#5  0x00000000004334cc in base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >::MakeItSo (runnable=..., args=0x1145d00) at ../../packager/base/bind_internal.h:293
#6  0x0000000000433498 in base::internal::Invoker<base::IndexSequence<0ul>, base::internal::BindState<base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, void (edash_packager::media::ThreadedIoFile*), base::internal::TypeList<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::TypeList<base::internal::UnwrapTraits<base::internal::UnretainedWrapper<edash_packager::media::ThreadedIoFile> > >, base::internal::InvokeHelper<false, void, base::internal::RunnableAdapter<void (edash_packager::media::ThreadedIoFile::*)()>, base::internal::TypeList<edash_packager::media::ThreadedIoFile*> >, void ()>::Run(base::internal::BindStateBase*) (base=0x1144e40) at ../../packager/base/bind_internal.h:343
#7  0x000000000068509e in base::Callback<void ()>::Run() const (this=0x7f37115fbe08) at ../../packager/base/callback.h:396
#8  0x00000000006fbb49 in base::(anonymous namespace)::WorkerThread::ThreadMain (this=0x11459d0) at ../../packager/base/threading/worker_pool_posix.cc:98
#9  0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7ffd0f895e80) at ../../packager/base/threading/platform_thread_posix.cc:74
#10 0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#11 0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7f3704ffc700 (LWP 5494)):
#0  0x00007f371e2036d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006d9795 in base::ConditionVariable::Wait (this=0x7f3704ffa8f8) at ../../packager/base/synchronization/condition_variable_posix.cc:54
#2  0x00000000006db18e in base::WaitableEvent::TimedWait (this=0x1145d60, max_time=...) at ../../packager/base/synchronization/waitable_event_posix.cc:214
#3  0x00000000006dadf6 in base::WaitableEvent::Wait (this=0x1145d60) at ../../packager/base/synchronization/waitable_event_posix.cc:154
#4  0x0000000000435554 in edash_packager::media::IoCache::Read (this=0x1145d20, buffer=0x7f371802c010, size=2097152) at ../../packager/media/file/io_cache.cc:45
#5  0x00000000004319f3 in edash_packager::media::ThreadedIoFile::Read (this=0x1145d00, buffer=0x7f371802c010, length=2097152) at ../../packager/media/file/threaded_io_file.cc:81
#6  0x00000000006606df in edash_packager::media::Demuxer::Parse (this=0x11459f0) at ../../packager/media/base/demuxer.cc:214
#7  0x0000000000660e94 in edash_packager::media::Demuxer::Run (this=0x11459f0) at ../../packager/media/base/demuxer.cc:184
#8  0x0000000000412404 in edash_packager::media::RemuxJob::Run (this=0x11e29c0) at ../../packager/app/packager_main.cc:140
#9  0x00000000006eb811 in base::SimpleThread::ThreadMain (this=0x11e29c0) at ../../packager/base/threading/simple_thread.cc:66
#10 0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7ffd0f8976d0) at ../../packager/base/threading/platform_thread_posix.cc:74
#11 0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#12 0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x7f36e7ffb700 (LWP 5495)):
#0  0x00007f371e203a82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006d99ff in base::ConditionVariable::TimedWait (this=0x11371c8, max_time=...) at ../../packager/base/synchronization/condition_variable_posix.cc:102
---Type <return> to continue, or q <return> to quit---
#2  0x00000000006faddc in base::PosixDynamicThreadPool::WaitForTask (this=0x1137180) at ../../packager/base/threading/worker_pool_posix.cc:192
#3  0x00000000006fb986 in base::(anonymous namespace)::WorkerThread::ThreadMain (this=0x7f36f8003110) at ../../packager/base/threading/worker_pool_posix.cc:89
#4  0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7f3710df8380) at ../../packager/base/threading/platform_thread_posix.cc:74
#5  0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7f36effff700 (LWP 5496)):
#0  0x00007f371e203a82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000006d99ff in base::ConditionVariable::TimedWait (this=0x11371c8, max_time=...) at ../../packager/base/synchronization/condition_variable_posix.cc:102
#2  0x00000000006faddc in base::PosixDynamicThreadPool::WaitForTask (this=0x1137180) at ../../packager/base/threading/worker_pool_posix.cc:192
#3  0x00000000006fb986 in base::(anonymous namespace)::WorkerThread::ThreadMain (this=0x7f36fc203000) at ../../packager/base/threading/worker_pool_posix.cc:89
#4  0x00000000006eac2a in base::(anonymous namespace)::ThreadFunc (params=0x7f3705ffb380) at ../../packager/base/threading/platform_thread_posix.cc:74
#5  0x00007f371e1ffdc5 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f371df2d28d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f371f255740 (LWP 5483)):
#0  0x00007f371e200ef7 in pthread_join () from /lib64/libpthread.so.0
#1  0x00000000006ea727 in base::PlatformThread::Join (thread_handle=...) at ../../packager/base/threading/platform_thread_posix.cc:221
#2  0x00000000006eb74b in base::SimpleThread::Join (this=0x11e29c0) at ../../packager/base/threading/simple_thread.cc:47
#3  0x000000000040f11e in edash_packager::media::RunRemuxJobs (remux_jobs=std::__debug::vector of length 4, capacity 4 = {...}) at ../../packager/app/packager_main.cc:358
Python Exception <type 'exceptions.IndexError'> list index out of range: 
#4  0x000000000040f7cf in edash_packager::media::RunPackager (stream_descriptors=std::__debug::multiset with 5 elements) at ../../packager/app/packager_main.cc:427
#5  0x000000000040fca4 in edash_packager::media::PackagerMain (argc=6, argv=0x7ffd0f898bb8) at ../../packager/app/packager_main.cc:463
#6  0x000000000040fd42 in main (argc=16, argv=0x7ffd0f898b68) at ../../packager/app/packager_main.cc:470

Please tell me how I can help to detect what the issue is.

BRS

The text was updated successfully, but these errors were encountered:

tinskip · 2016-02-29T18:22:48Z

The issue is likely to be a networking issue. One of the multicast-aware routers between the packager host and the UDP stream source may be discontinuing the stream after a predetermined amount of time.

Does failure occur after roughly the same amount of time each time?
Any errors or other potentially useful info output by the packager? You may want to try running a debug build, which ought to be chattier.

peyoh · 2016-03-01T07:24:15Z

Hi,
On the network interface I'm still able to see incoming streams from all needed sources. To see them I'm using tcpdump.
The time when the stream stops to be packetized is completely random. This is not IGMP timeout issue.

peyoh · 2016-03-01T12:33:45Z

Hi,
in addition.
Here is the list from files recorded by the packager. MPD file is still generated (publishTime="2016-03-01T12:25:49Z" - is actual) , even the row data files was not. Take a look

Feb 29 15:48 edash-video-288-1.mp4
Feb 29 13:43 edash-video-384-408.mp4
Feb 29 13:43 edash-video-512-408.mp4
Feb 29 13:43 edash-video-576-408.mp4
Feb 29 13:43 edash-audio-431.mp4
Mar  1 14:24 662.mpd

This instance command line is:
Debug/packager --udp_interface_address=10.0.8.33 input=udp://239.204.6.121:7000,stream=audio,init_segment=/storage/web/dash/662/edash-audio.mp4,segment_template=/storage/web/dash/662/edash-audio-$Number$.mp4 input=udp://239.204.6.121:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-576.mp4,segment_template=/storage/web/dash/662/edash-video-576-$Number$.mp4 input=udp://239.204.6.122:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-512.mp4,segment_template=/storage/web/dash/662/edash-video-512-$Number$.mp4 input=udp://239.204.6.123:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-384.mp4,segment_template=/storage/web/dash/662/edash-video-384-$Number$.mp4 input=udp://239.204.6.124:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-288.mp4,segment_template=/storage/web/dash/662/edash-video-288-$Number$.mp4 --profile live --mpd_output /storage/web/dash/662/662.mpd -time_shift_buffer_depth 86400 -dump_stream_info -availability_time_offset 10

Meanwhile, tcpdump on this interface shows:

[root@boron dash]# tcpdump -i vlan8 host 239.204.6.124 -q 
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:02.610227 IP 10.0.8.31.60892 > 239.204.6.124.afs3-fileserver: UDP, length 1316

^C
34 packets captured
333 packets received by filter
233 packets dropped by kernel
[root@boron dash]# tcpdump -i vlan8 host 239.204.6.123 -q 
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:27.279552 IP 10.0.8.31.53678 > 239.204.6.123.afs3-fileserver: UDP, length 1316

^C
13 packets captured
160 packets received by filter
69 packets dropped by kernel
[root@boron dash]# tcpdump -i vlan8 host 239.204.6.122 -q 
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:30.567387 IP 10.0.8.31.35004 > 239.204.6.122.afs3-fileserver: UDP, length 1316

^C
31 packets captured
166 packets received by filter
104 packets dropped by kernel
[root@boron dash]# tcpdump -i vlan8 host 239.204.6.121 -q 
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:33.059965 IP 10.0.8.31.50208 > 239.204.6.121.afs3-fileserver: UDP, length 1316

netstat -tupan shows, that the sockets receive queue of 3 from 4 input streams is full.. hm. Nobody reads from them:

udp        0      0 239.204.6.124:7000      0.0.0.0:*                           5483/packager
udp   213248      0 239.204.6.123:7000      0.0.0.0:*                           5483/packager       
udp   213248      0 239.204.6.122:7000      0.0.0.0:*                           5483/packager       
udp   213248      0 239.204.6.121:7000      0.0.0.0:*                           5483/packager

tinskip · 2016-03-01T16:49:51Z

You mean that the MPD keeps getting updated, including references to mp4
files which are not being generated?

I am at a loss to think of an internal state which might cause that
behavior to occur.

On Tue, Mar 1, 2016 at 4:33 AM, peyoh notifications@github.com wrote:

Hi,
in addition.

Here is the list from files recorded by the packager. MPD file is still
generated (publishTime="2016-03-01T12:25:49Z" - is actual) , even the row
data files was not. Take a look

Feb 29 15:48 edash-video-288-1.mp4
Feb 29 13:43 edash-video-384-408.mp4
Feb 29 13:43 edash-video-512-408.mp4
Feb 29 13:43 edash-video-576-408.mp4
Feb 29 13:43 edash-audio-431.mp4
Mar 1 14:24 662.mpd

This instance command line is:
Debug/packager --udp_interface_address=10.0.8.33 input=udp://
239.204.6.121:7000,stream=audio,init_segment=/storage/web/dash/662/edash-audio.mp4,segment_template=/storage/web/dash/662/edash-audio-$Number$.mp4
input=udp://239.204.6.121:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-576.mp4,segment_template=/storage/web/dash/662/edash-video-576-$Number$.mp4
input=udp://239.204.6.122:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-512.mp4,segment_template=/storage/web/dash/662/edash-video-512-$Number$.mp4
input=udp://239.204.6.123:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-384.mp4,segment_template=/storage/web/dash/662/edash-video-384-$Number$.mp4
input=udp://239.204.6.124:7000,stream=video,init_segment=/storage/web/dash/662/edash-video-288.mp4,segment_template=/storage/web/dash/662/edash-video-288-$Number$.mp4
--profile live --mpd_output /storage/web/dash/662/662.mpd
-time_shift_buffer_depth 86400 -dump_stream_info -availabi lity_time_offset
10

Meanwhile, tcpdump on this interface shows:

[root@boron dash]# tcpdump -i vlan8 host 239.204.6.124 -q
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:02.610227 IP 10.0.8.31.60892 > 239.204.6.124.afs3-fileserver: UDP, length 1316

^C
34 packets captured
333 packets received by filter
233 packets dropped by kernel
[root@boron dash]# tcpdump -i vlan8 host 239.204.6.123 -q
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:27.279552 IP 10.0.8.31.53678 > 239.204.6.123.afs3-fileserver: UDP, length 1316

^C
13 packets captured
160 packets received by filter
69 packets dropped by kernel
[root@boron dash]# tcpdump -i vlan8 host 239.204.6.122 -q
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:30.567387 IP 10.0.8.31.35004 > 239.204.6.122.afs3-fileserver: UDP, length 1316

^C
31 packets captured
166 packets received by filter
104 packets dropped by kernel
[root@boron dash]# tcpdump -i vlan8 host 239.204.6.121 -q
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vlan8, link-type EN10MB (Ethernet), capture size 65535 bytes
14:31:33.059965 IP 10.0.8.31.50208 > 239.204.6.121.afs3-fileserver: UDP, length 1316

—
Reply to this email directly or view it on GitHub
#93 (comment)
.

Thomás Inskip | Software Engineer | tinskip@google.com | +1 650 241 9697

kqyang · 2016-03-01T18:15:15Z

That is indeed weird. Just to confirm, is the mpd file actually being updated, other than the publishTime? Do you see any error messages on the console?

peyoh · 2016-03-02T07:47:03Z

Hello,
it's quite strange.
Only one representation is updated together with it's files:

  <Representation id="3" bandwidth="498519" codecs="avc1.4d0015" mimeType="video/mp4" sar="64:45" width="360" height="288">
        <SegmentTemplate timescale="90000" initialization="edash-video-288.mp4" media="edash-video-288-$Number$.mp4" startNumber="1">
          <SegmentTimeline>
            <S t="322514032" d="950400" r="2161"/>
          </SegmentTimeline>
        </SegmentTemplate>
      </Representation>

About warning messages, I've redirected them to /dev/null. Will restart the services with logging enabled.

BTW,
I can give ssh access to the test machine with CentOS if you think this can help.

peyoh · 2016-03-03T06:00:35Z

Hello,
here are the logs. Nothing unexpected.


[0302/095358:INFO:demuxer.cc(60)] Initialize Demuxer for file 'udp://239.204.6.121:7000'.
[0302/095358:INFO:demuxer.cc(60)] Initialize Demuxer for file 'udp://239.204.6.122:7000'.
[0302/095359:INFO:demuxer.cc(60)] Initialize Demuxer for file 'udp://239.204.6.123:7000'.
[0302/095400:INFO:demuxer.cc(60)] Initialize Demuxer for file 'udp://239.204.6.124:7000'.
[0302/095401:INFO:demuxer.cc(173)] Demuxer::Run() on file 'udp://239.204.6.121:7000'.
[0302/095401:INFO:demuxer.cc(173)] Demuxer::Run() on file 'udp://239.204.6.122:7000'.
[0302/095401:INFO:demuxer.cc(173)] Demuxer::Run() on file 'udp://239.204.6.123:7000'.
[0302/095401:INFO:demuxer.cc(173)] Demuxer::Run() on file 'udp://239.204.6.124:7000'.
[0302/095401:WARNING:mpd_builder.cc(232)] Video info does not contain frame duration required for calculating framerate. @frameRate is required for DASH IOP.
[0302/095401:WARNING:mpd_builder.cc(232)] Video info does not contain frame duration required for calculating framerate. @frameRate is required for DASH IOP.
[0302/095401:WARNING:mpd_builder.cc(232)] Video info does not contain frame duration required for calculating framerate. @frameRate is required for DASH IOP.
[0302/095401:WARNING:mpd_builder.cc(232)] Video info does not contain frame duration required for calculating framerate. @frameRate is required for DASH IOP.
[0302/102230:WARNING:mpd_builder.cc(1259)] Found a gap of size 55680 > kRoundingErrorGrace (5). The new segment starts at 2613932752 but the previous segment ends at 2613877072.
[0302/103230:WARNING:mpd_builder.cc(1259)] Found a gap of size 15360 > kRoundingErrorGrace (5). The new segment starts at 2667976912 but the previous segment ends at 2667961552.
[0302/103851:WARNING:mpd_builder.cc(1259)] Found a gap of size 26880 > kRoundingErrorGrace (5). The new segment starts at 2702222032 but the previous segment ends at 2702195152.
[0302/114153:WARNING:mpd_builder.cc(1259)] Found a gap of size 28800 > kRoundingErrorGrace (5). The new segment starts at 3042632272 but the previous segment ends at 3042603472.
[0302/121534:WARNING:mpd_builder.cc(1259)] Found a gap of size 15360 > kRoundingErrorGrace (5). The new segment starts at 3224544592 but the previous segment ends at 3224529232.
[0302/152950:WARNING:mpd_builder.cc(1259)] Found a gap of size 4320 > kRoundingErrorGrace (5). The new segment starts at 4273608112 but the previous segment ends at 4273603792.
[0302/190327:WARNING:mpd_builder.cc(1259)] Found a gap of size 13440 > kRoundingErrorGrace (5). The new segment starts at 5427136432 but the previous segment ends at 5427122992.

kqyang · 2016-03-07T22:05:42Z

Yes, it can definitely help if you give us ssh access. Btw, just to rule out, do you have any cron job running that removes out-dated segments periodically?

peyoh · 2016-03-08T05:08:58Z

No.I have no cronjob for removing segments.

kqyang · 2016-03-09T06:33:53Z

Hi peyoh,

From the thread info,

(gdb) info threads
  Id   Target Id         Frame
  8    Thread 0x7f0287711700 (LWP 1771) "WorkerPool/1771" 0x00007f0289ee16d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  7    Thread 0x7f0284b0d700 (LWP 1777) "WorkerPool/1777" 0x00007f0289ee4623 in recvfrom () from /lib64/libpthread.so.0
  6    Thread 0x7f027ddfd700 (LWP 1783) "WorkerPool/1783" 0x00007f0289ee16d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  5    Thread 0x7f027d1fa700 (LWP 1798) "WorkerPool/1798" 0x00007f0289ee16d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  4    Thread 0x7f0271ffe700 (LWP 1818) "RemuxJob/1818" 0x00007f0289ee16d5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  3    Thread 0x7f025dffc700 (LWP 1822) "WorkerPool/1822" 0x00007f0289ee1a82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  2    Thread 0x7f025d7fb700 (LWP 2214) "WorkerPool/2214" 0x00007f0289ee1a82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1    Thread 0x7f028af33740 (LWP 1770) "packager" 0x00007f0289edeef7 in pthread_join () from /lib64/libpthread.so.0

There is only one RemuxJob exist. Looks like the other packaging threads have exited. It is unknown yet what was causing these threads to exit. Likely some media parsing error.

Can you run with debug code at https://github.com/kqyang/edash-packager, which contains slightly more debug messages? Then capture all logs. Let's analyze the logs later to see if we can figure out what is causing those threads to exit.

peyoh · 2016-03-09T10:40:37Z

Hi kqyang,
What verbose level to place? v=1 has too many messages.

kqyang · 2016-03-09T18:16:07Z

Just use default if v=1 is too much. (no verbose level)

peyoh · 2016-03-10T07:51:25Z

Hi kquang,
this is one "frozen" profile. Maybe this can explain what's up.


[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=3948
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=1316
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=2632
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=1316
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=1316
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=2632
[0310/092737:VERBOSE1:h264_parser.cc(1027)] Error in stream: invalid value while trying to read &shdr->idr_pic_id
[0310/092737:VERBOSE1:mp2t_media_parser.cc(114)] Parsing failed for pid = 256
[0310/092737:VERBOSE1:es_parser_h264.cc(101)] EsParserH264::Reset
[0310/092737:ERROR:packager_main.cc(143)] [udp://239.204.0.32:7000] Demuxer failed 8 (PARSER_FAILURE): Cannot parse media file udp://239.204.0.32:7000
[0310/092737:VERBOSE1:ts_section_psi.cc(103)] Trailing bytes after a PSI section: 16 vs 183
[0310/092737:VERBOSE1:ts_section_psi.cc(103)] Trailing bytes after a PSI section: 21 vs 183
[0310/092737:VERBOSE1:mp2t_media_parser.cc(285)] RegisterPes: pes_pid=256 stream_type=1b
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=1316
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=1316
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=1316
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=15792
[0310/092737:VERBOSE1:mp2t_media_parser.cc(189)] Mp2tMediaParser::Parse size=2632

This profile is definitely not processed:

[root@boron 503]# netstat -tupan| grep 239.204.0.3
udp        0      0 239.204.0.34:7000       0.0.0.0:*                           17218/packager      
udp        0      0 239.204.0.33:7000       0.0.0.0:*                           17218/packager      
udp   213248      0 239.204.0.32:7000       0.0.0.0:*                           17218/packager      
udp        0      0 239.204.0.31:7000       0.0.0.0:*                           17218/packager

kqyang · 2016-03-11T06:13:45Z

Thanks for the new log, so there is a parsing failure. It seems like some problem in the content.

Can you apply the below patch and run again:

diff --git c/packager/media/formats/mp2t/es_parser_h264.cc w/packager/media/formats/mp2t/es_parser_h264.cc
index fabe114..8f1e8f2 100644
--- c/packager/media/formats/mp2t/es_parser_h264.cc
+++ w/packager/media/formats/mp2t/es_parser_h264.cc
@@ -23,6 +23,14 @@ namespace mp2t {

 namespace {

+void HexDump(const std::string& label, const uint8* data, size_t data_size) {
+  LOG(INFO) << label << " size " << data_size;
+  for (size_t i = 0; i < data_size; ++i) {
+    if ((i % 16) == 0) printf("\n");
+    printf("%02X ", data[i]);
+  }
+}
+
 // An AUD NALU is at least 4 bytes:
 // 3 bytes for the start code + 1 byte for the NALU type.
 const int kMinAUDSize = 4;
@@ -233,8 +241,21 @@ bool EsParserH264::ParseInternal() {
         if (h264_parser_->ParseSliceHeader(nalu, &shdr) != H264Parser::kOk) {
           // Only accept an invalid SPS/PPS at the beginning when the stream
           // does not necessarily start with an SPS/PPS/IDR.
-          if (last_video_decoder_config_)
+          if (last_video_decoder_config_) {
+            LOG(ERROR) << "Parse slice header failed.";
+            HexDump("Nalu", nalu.data(), nalu.header_size() + nalu.payload_size());
+            HexDump("Access Unit", es, access_unit_size);
+
+            std::vector<uint8_t> decoder_config_record;
+            if (!stream_converter_->GetAVCDecoderConfigurationRecord(
+                    &decoder_config_record)) {
+              DLOG(ERROR) << "Failure to construct an AVCDecoderConfigurationRecord";
+              return false;
+            }
+            HexDump("Decoder config", decoder_config_record.data(), decoder_config_record.size());
+
             return false;
+          }
         } else {
           pps_id_for_access_unit = shdr.pic_parameter_set_id;
         }

You may also just sync and use the code at https://github.com/kqyang/edash-packager.

This will collect additional debug message to help confirm what is wrong.

peyoh · 2016-03-14T08:18:56Z

Hi,
attached files are 3 failed streams logs,

failures.zip

kqyang · 2016-03-14T19:00:48Z

I believe this is content problem. Here is the data from failure_1.txt:

This is an IDR Slice NAL unit. Apparently it is incomplete, which caused the parsing failure.

25 88 80 00 01

The NAL unit is extracted from the below stream:

00 00 00 01 
// AUD NAL unit
09 10 
00 00 00 01 
// SPS NAL unit
27 4D 00 15 96 98 3C 18 DF F8 02 00 01 68 80 00 00 03 00 80 00 00 19 4E D0 E1 69 C0
00 00 00 01
// PPS NAL unit
28 EE 3C 80 
00 00 00 01
// SEI Message NAL unit
06 00 01 C0 01 01 04 80
00 00 01
// IDR slice NAL unit, which failed to be parsed due to incompleteness.
25 88 80 00 01
// It seems that it should be part of the IDR slice NAL unit from the context. 000001 is
// reserved sequence which indicates the start of a new NAL unit. Start code emulation
// prevention should have been applied to escape this sequence inside NAL units.
00 00 01
// This is not a valid NAL unit. It seems that it should be part of IDR slice NAL unit,
// but there is a start code before that.
7F EC 4B 1C C0 53 F3 43 6D E6 A3 ...

I think the problem is that start code emulation prevention was not applied properly to the source content causing NAL unit parsing problem.

It might be possible to workaround it in edash-packager, but it will be better to solve the root cause. How is the content transcoded? Can you look into why the start code emulation prevention was not applied properly?

peyoh · 2016-03-15T05:27:34Z

Hm,
That's a live source received by DVB-S. Nobody can guarantee what transcode hardware was used before go to the satellite. The more interesting is, that all h264 video streams (I have) from different content providers and satellites causes this issue.

kqyang · 2016-03-16T18:39:00Z

Ok, that is a good argument to have more robust handling of NAL unit and start codes in edash-packager - which is difficult though. We'll think about how to tackle it.

kqyang · 2016-03-25T22:48:50Z

@peyoh As mentioned in a separate email, the improvement in #96 seems to be working well to handle the problem discovered in this issue.

I'll close it for now. Feel free to re-open it if there are still problems.

This was referenced Mar 18, 2016

Widevine encrypted content fails in Chrome #95

Closed

Robust handling of unescaped NAL units in byte stream #96

Closed

kqyang added the type: question A question from the community label Mar 25, 2016

kqyang closed this as completed Mar 25, 2016

kqyang mentioned this issue Apr 22, 2016

DTS issues question #50

Closed

shaka-bot added the status: archived Archived and locked; will not be updated label Apr 19, 2018

shaka-project locked and limited conversation to collaborators Apr 19, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Packager stops packetizing from live sources in live profile #93

Packager stops packetizing from live sources in live profile #93

peyoh commented Feb 29, 2016

tinskip commented Feb 29, 2016

peyoh commented Mar 1, 2016

peyoh commented Mar 1, 2016

tinskip commented Mar 1, 2016

kqyang commented Mar 1, 2016

peyoh commented Mar 2, 2016

peyoh commented Mar 3, 2016

kqyang commented Mar 7, 2016

peyoh commented Mar 8, 2016

kqyang commented Mar 9, 2016

peyoh commented Mar 9, 2016

kqyang commented Mar 9, 2016

peyoh commented Mar 10, 2016

kqyang commented Mar 11, 2016

peyoh commented Mar 14, 2016

kqyang commented Mar 14, 2016

peyoh commented Mar 15, 2016

kqyang commented Mar 16, 2016

kqyang commented Mar 25, 2016

Packager stops packetizing from live sources in live profile #93

Packager stops packetizing from live sources in live profile #93

Comments

peyoh commented Feb 29, 2016

tinskip commented Feb 29, 2016

peyoh commented Mar 1, 2016

peyoh commented Mar 1, 2016

tinskip commented Mar 1, 2016

kqyang commented Mar 1, 2016

peyoh commented Mar 2, 2016

peyoh commented Mar 3, 2016

kqyang commented Mar 7, 2016

peyoh commented Mar 8, 2016

kqyang commented Mar 9, 2016

peyoh commented Mar 9, 2016

kqyang commented Mar 9, 2016

peyoh commented Mar 10, 2016

kqyang commented Mar 11, 2016

peyoh commented Mar 14, 2016

kqyang commented Mar 14, 2016

peyoh commented Mar 15, 2016

kqyang commented Mar 16, 2016

kqyang commented Mar 25, 2016