"stream@2 got zero bytes" --

[MarkyMark]

Hello! I have a fairly straightforward setup that randomly (but regularly) drops a live stream with the following log message typically preceding the stream failure:

stream@2 got zero bytes

Connecting directly to the tuner does not appear to have the same issue. My Tuner is hardwired directly to my nextPVR linux box. Here's the basic setup:

Tuner: HDHR5-2US (Firmware: 20231214)
PVR: NextPVR (Version: 7.0.0.241105, docker container on a Linux host)
TV: Amazon Firestick (latest) Kodi (21.0) - NextPVR Addon (21.2.0)

The same behavior happens on two different clients. Both are the exact same(firestick -> kodi -> PVR) but one is hardwired, one is connected over WiFi. The channels that get dropped are very strong signals. For example:

Local CBS affiliate:

Virtual Channel
4.1 KCNC-TV
Frequency
599.000 MHz
Program Number
1

Modulation Lock
8vsb
Signal Strength
100%
Signal Quality
100%
Symbol Quality
100%

Local NBC affiliate:

Virtual Channel
9.1 KUSA-HD
Frequency
189.000 MHz
Program Number
1

Modulation Lock
8vsb
Signal Strength
100%
Signal Quality
91%
Symbol Quality
100%

Here are the logs that I pulled from NextPVR for what I believe is the whole request -- opening the stream to it failing:

Code:

024-12-02 02:02:34.397    [DEBUG][251]    Got request [192.168.1.117]: /service (channel.transcode.lease)
2024-12-02 02:02:34.397    [DEBUG][251]    method=channel.transcode.lease
2024-12-02 02:02:34.397    [DEBUG][251]    parameters:
2024-12-02 02:02:34.398    [DEBUG][251]       method: channel.transcode.lease
2024-12-02 02:02:34.398    [DEBUG][251]       sid: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:34.398    [DEBUG][251]       client_ip: 192.168.1.117
2024-12-02 02:02:34.398    [DEBUG][251]       user_agent: Kodi/21.1 (Linux; Android 7.1.2; AFTMM Build/NS6708) Android TV/7.1.2 Sys_CPU/armv7l App_Bitness/32 Version/21.1-(21.1.0)-Git:20240817-183eb85f10
2024-12-02 02:02:34.398    [DEBUG][251]       host_callback: ...
2024-12-02 02:02:34.398    [DEBUG][251]    Renew lease ok (0x19001D)
2024-12-02 02:02:34.398    [DEBUG][251]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
</rsp>

2024-12-02 02:02:41.405    [DEBUG][305]    Got request [192.168.1.117]: /service (channel.transcode.lease)
2024-12-02 02:02:41.405    [DEBUG][305]    method=channel.transcode.lease
2024-12-02 02:02:41.405    [DEBUG][305]    parameters:
2024-12-02 02:02:41.405    [DEBUG][305]       method: channel.transcode.lease
2024-12-02 02:02:41.405    [DEBUG][305]       sid: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:41.406    [DEBUG][305]       client_ip: 192.168.1.117
2024-12-02 02:02:41.406    [DEBUG][305]       user_agent: Kodi/21.1 (Linux; Android 7.1.2; AFTMM Build/NS6708) Android TV/7.1.2 Sys_CPU/armv7l App_Bitness/32 Version/21.1-(21.1.0)-Git:20240817-183eb85f10
2024-12-02 02:02:41.406    [DEBUG][305]       host_callback: ...
2024-12-02 02:02:41.406    [DEBUG][305]    Renew lease ok (0x19001D)
2024-12-02 02:02:41.406    [DEBUG][305]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
</rsp>

2024-12-02 02:02:41.411    [DEBUG][305]    Got request [192.168.1.117]: /service (channel.stream.info)
2024-12-02 02:02:41.411    [DEBUG][305]    method=channel.stream.info
2024-12-02 02:02:41.411    [DEBUG][305]    parameters:
2024-12-02 02:02:41.411    [DEBUG][305]       method: channel.stream.info
2024-12-02 02:02:41.411    [DEBUG][305]       sid: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:41.411    [DEBUG][305]       client_ip: 192.168.1.117
2024-12-02 02:02:41.411    [DEBUG][305]       user_agent: Kodi/21.1 (Linux; Android 7.1.2; AFTMM Build/NS6708) Android TV/7.1.2 Sys_CPU/armv7l App_Bitness/32 Version/21.1-(21.1.0)-Git:20240817-183eb85f10
2024-12-02 02:02:41.411    [DEBUG][305]       host_callback: ...
2024-12-02 02:02:41.411    [DEBUG][305]    <map>
  <stream_length>372520636</stream_length>
  <stream_duration>260701</stream_duration>
  <live>true</live>
  <complete>false</complete>
  <files>
    <file>
      <filename>/buffer/live-KUSA-HD-14.ts</filename>
      <offset>0</offset>
      <start_ms>0</start_ms>
      <end_ms>0</end_ms>
    </file>
  </files>
</map>

2024-12-02 02:02:41.411    [DEBUG][305]    <map>
  <stream_length>372520636</stream_length>
  <stream_duration>260701</stream_duration>
  <live>true</live>
  <complete>false</complete>
  <files>
    <file>
      <filename>/buffer/live-KUSA-HD-14.ts</filename>
      <offset>0</offset>
      <start_ms>0</start_ms>
      <end_ms>0</end_ms>
    </file>
  </files>
</map>

2024-12-02 02:02:44.881    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:45.884    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:46.888    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:47.892    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:48.895    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:49.899    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:50.903    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:51.907    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:52.911    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:53.915    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:54.918    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:55.208    [DEBUG][251]    Got request [192.168.1.117]: /service (channel.transcode.lease)
2024-12-02 02:02:55.208    [DEBUG][251]    method=channel.transcode.lease
2024-12-02 02:02:55.208    [DEBUG][251]    parameters:
2024-12-02 02:02:55.208    [DEBUG][251]       method: channel.transcode.lease
2024-12-02 02:02:55.208    [DEBUG][251]       sid: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:55.208    [DEBUG][251]       client_ip: 192.168.1.117
2024-12-02 02:02:55.208    [DEBUG][251]       user_agent: Kodi/21.1 (Linux; Android 7.1.2; AFTMM Build/NS6708) Android TV/7.1.2 Sys_CPU/armv7l App_Bitness/32 Version/21.1-(21.1.0)-Git:20240817-183eb85f10
2024-12-02 02:02:55.208    [DEBUG][251]       host_callback: ...
2024-12-02 02:02:55.208    [DEBUG][251]    Renew lease ok (0x19001D)
2024-12-02 02:02:55.208    [DEBUG][251]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
</rsp>

2024-12-02 02:02:55.922    [DEBUG][467]    stream@2 got zero bytes
2024-12-02 02:02:55.928    [DEBUG][305]    Got request [192.168.1.117]: /live
2024-12-02 02:02:55.928    [DEBUG][305]    /live?channeloid=7358&client=b4d1479cdd1f445fb02f0ff450fd5d6d&sid=b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:55.928    [DEBUG][305]     - channeloid: 7358
2024-12-02 02:02:55.928    [DEBUG][305]     - client: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:55.928    [DEBUG][305]     - sid: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:55.928    [DEBUG][305]    range: bytes=374394104-
2024-12-02 02:02:55.928    [DEBUG][305]    RollingFile.Open(/buffer/live-KUSA-HD-14.ts) ..
2024-12-02 02:02:55.929    [DEBUG][305]    File is in live mode
2024-12-02 02:02:55.929    [DEBUG][305]    Range: 374394104-
2024-12-02 02:02:55.929    [DEBUG][305]    Start location: 374394104 (file-size: 374428868)
2024-12-02 02:02:55.929    [DEBUG][305]    About to continue streaming until stream stops
2024-12-02 02:02:56.123    [DEBUG][467]    Connection abandoned...
2024-12-02 02:02:56.123    [DEBUG][467]    Done. Sent 374427328 bytes
2024-12-02 02:02:56.129    [DEBUG][305]    client disconnected
2024-12-02 02:02:56.129    [DEBUG][305]    Done. Sent 31584 bytes
2024-12-02 02:02:56.235    [DEBUG][48]    Got request [192.168.1.117]: /service (channel.stream.stop)
2024-12-02 02:02:56.236    [DEBUG][48]    method=channel.stream.stop
2024-12-02 02:02:56.236    [DEBUG][48]    parameters:
2024-12-02 02:02:56.236    [DEBUG][48]       method: channel.stream.stop
2024-12-02 02:02:56.236    [DEBUG][48]       sid: b4d1479cdd1f445fb02f0ff450fd5d6d
2024-12-02 02:02:56.236    [DEBUG][48]       client_ip: 192.168.1.117
2024-12-02 02:02:56.236    [DEBUG][48]       user_agent: Kodi/21.1 (Linux; Android 7.1.2; AFTMM Build/NS6708) Android TV/7.1.2 Sys_CPU/armv7l App_Bitness/32 Version/21.1-(21.1.0)-Git:20240817-183eb85f10
2024-12-02 02:02:56.236    [DEBUG][48]       host_callback: ...
2024-12-02 02:02:56.236    [DEBUG][48]    RollingFile.Open(/buffer/live-KUSA-HD-14.ts) ..
2024-12-02 02:02:56.236    [DEBUG][48]    File is in live mode
2024-12-02 02:02:56.236    [DEBUG][48]    StopStream(29)
2024-12-02 02:02:56.236    [DEBUG][48]    StopStream handle: 29
2024-12-02 02:02:56.236    [DEBUG][48]    Closing TSWriter....: LIVE&/buffer/live-KUSA-HD-14.ts
2024-12-02 02:02:56.236    [ERROR][48]    writer.Close() did not complete in a timely fashion
2024-12-02 02:02:56.236    [DEBUG][48]    Close@2
2024-12-02 02:02:56.236    [DEBUG][48]    Closing mapAccessor
2024-12-02 02:02:56.237    [DEBUG][48]    Closing mapMMF
2024-12-02 02:02:56.237    [DEBUG][48]    Closing mapFileStream
2024-12-02 02:02:56.237    [DEBUG][48]    deleting /buffer/live-KUSA-HD-14.ts.map
2024-12-02 02:02:56.237    [DEBUG][48]    Close@exit
2024-12-02 02:02:56.237    [DEBUG][48]    StopStream@exit
2024-12-02 02:02:56.247    [DEBUG][48]    stopping graph
2024-12-02 02:02:56.247    [DEBUG][48]    destroying graph
2024-12-02 02:02:56.247    [INFO][48]    Stopped
2024-12-02 02:02:56.247    [DEBUG][48]    stopped live stream for timeshift
2024-12-02 02:02:56.307    [DEBUG][48]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
</rsp>

I'm stumped.

[sub]

Can you supply a sample recording for me to check? You'd need to put it somewhere like onedrive/googledrive and supply a download link.

[MarkyMark]

Can you supply a sample recording for me to check? You'd need to put it somewhere like onedrive/googledrive and supply a download link.

Sorry to be obtuse, but do you mean the live TV buffer file? I suspect I can do that, but it might take a little futzing with watching live TV and grabbing the corresponding buffer file before it's cleaned up.

[sub]

A recording or a live tv buffer file. If you want to use a live tv buffer file, you can just copy the file while you're still trying to watch live tv.

I'd ideally like 10 minutes or so of content though, so a recording might be better.

[MarkyMark]

A recording or a live tv buffer file. If you want to use a live tv buffer file, you can just copy the file while you're still trying to watch live tv.

I'd ideally like 10 minutes or so of content though, so a recording might be better.

Not sure if this is a relevant datapoint in this discussion, but interestingly I've never noticed an issue on my recordings, this appears to impact live streams only from what I can tell. I'll flip on the TV and see what I can come up with.

[sub]

Ok, try grabbing a live tv buffer file then.

[mvallevand]

Here are the logs that I pulled from NextPVR for what I believe is the whole request -- opening the stream to it failing:

Not even close.  I have stopped supporting users who don't send the zipped logs, since they tell the whole picture.

Martin

[MarkyMark]

Here are the logs that I pulled from NextPVR for what I believe is the whole request -- opening the stream to it failing:

Not even close.  I have stopped supporting users who don't send the zipped logs, since they tell the whole picture.

Martin

Since you asked so kindly, find them attached.  

You can see in the most recent log an event that JUST happened. Getting a recording buffer is going to be impossible as far as I can tell -- the buffer file is removed as soon as the stream fails and I can't transfer or move it fast enough.

[mvallevand]

You're right I shouldn't have to ask. Probably best to test from Kodi to avoid any transcoding that is spamming the logs.

Now we know you have an HDHR do you see anything in the logs at

http://192.168.1.15

Also the time on your server looks way off.

Martin

[MarkyMark]

You're right I shouldn't have to ask.  Probably best to test from Kodi to avoid any transcoding that is spamming the logs.

Now we know you have an HDHR do you see anything in the logs at

http://192.168.1.15

Also the time on your server looks way off. 

Martin

The most recent log entries with the "stream got zero bytes" messages using our local CBS affiliate (KCNC) were testing using Kodi.


My HDHR doesn't log a whole lot (that I can see), unfortunately. Here's a sample of the logs:

20241202-18:57:10 Tuner: tuner0 tuning 6.1 KRMADT1 (8vsb:587MHz-1)
20241202-18:57:10 Tuner: tuner0 streaming http to 192.168.1.199:52536
20241202-18:58:23 Tuner: tuner0 http stream ended (remote closed)
20241202-18:58:27 Tuner: tuner0 tuning 4.4 MeTV (8vsb:599MHz-4)
20241202-18:58:28 Tuner: tuner0 streaming http to 192.168.1.199:40232
20241202-18:58:44 Tuner: tuner0 http stream ended (remote closed)
20241202-18:58:44 Tuner: tuner0 tuning 31.1 KDVR-DT (8vsb:605MHz-3)
20241202-18:58:45 Tuner: tuner0 streaming http to 192.168.1.199:42470
20241202-18:58:52 Tuner: tuner0 http stream ended (remote closed)
20241202-18:59:03 Tuner: tuner0 tuning 4.1 KCNC-TV (8vsb:599MHz-1)
20241202-18:59:04 Tuner: tuner0 streaming http to 192.168.1.199:49988
20241202-19:01:01 Tuner: tuner0 http stream ended (remote closed)
20241202-19:01:08 Tuner: tuner0 tuning 4.1 KCNC-TV (8vsb:599MHz-1)
20241202-19:01:08 Tuner: tuner0 streaming http to 192.168.1.199:59748
20241202-19:01:51 Tuner: tuner0 http stream ended (remote closed)
20241202-19:02:22 Tuner: tuner0 tuning 4.1 KCNC-TV (8vsb:599MHz-1)
20241202-19:02:22 Tuner: tuner0 streaming http to 192.168.1.199:41756
20241202-19:04:00 Tuner: tuner0 http stream ended (remote closed)
20241202-20:05:58 Tuner: tuner0 tuning 4.1 KCNC-TV (8vsb:599MHz-1)
20241202-20:05:58 Tuner: tuner0 streaming http to 192.168.1.199:47234
20241202-20:14:35 Tuner: tuner0 http stream ended (remote closed)
20241202-20:17:03 Tuner: tuner0 tuning 4.1 KCNC-TV (8vsb:599MHz-1)
20241202-20:17:03 Tuner: tuner0 streaming http to 192.168.1.199:50176
20241202-20:28:42 Tuner: tuner0 http stream ended (remote closed)
20241202-20:29:00 Tuner: tuner1 tuning 6.3 Create (8vsb:587MHz-3)
20241202-20:29:01 Tuner: tuner1 streaming http to 192.168.1.199:49450

Docker uses UTC unless you specify otherwise, I'll fix that at next time I spin my docker stack up/down.