"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.