Missing audio streams when not available at initial HTSP subscription

[spdfrk]

Hi,

I'm running into an issue where sometimes the audio streams are not available yet on subscription (HTSP). This seams to be specifically HTSP as HTTP mode works but not really an option. The issue can happen randomly for any stream, restarting the stream most of the time fixes it. The streams are DASH streams piped through ffmpeg.

On Tvheadend side I can see below warnings when the audio is missing:
tsfix: The timediff for AC3 is big (.....), using current dts
tsfix: The timediff for AAC is big (.....), using current dts

Alternatively sometimes only AC3 is missing.

Kodi log when working ok:

2024-11-02 15:55:45.262 T:160885   debug <general>: AddOnLog: pvr.hts: demux subscription start
2024-11-02 15:55:45.262 T:160885   debug <general>: AddOnLog: pvr.hts:   id: 1001, type H264, codec: 27
2024-11-02 15:55:45.262 T:160885   debug <general>: AddOnLog: pvr.hts:   id: 1002, type AAC, codec: 86018
2024-11-02 15:55:45.262 T:160885   debug <general>: AddOnLog: pvr.hts:   id: 1003, type AC3, codec: 86019
2024-11-02 15:55:45.262 T:160885   debug <general>: AddOnLog: pvr.hts: demux stream change
2024-11-02 15:55:45.262 T:163081   debug <general>: CDVDDemuxClient::RequestStream(): added/updated stream 1001 with codec_id 27
2024-11-02 15:55:45.262 T:163081   debug <general>: CDVDDemuxClient::RequestStream(): added/updated stream 1002 with codec_id 86018
2024-11-02 15:55:45.262 T:163081   debug <general>: CDVDDemuxClient::RequestStream(): added/updated stream 1003 with codec_id 86019
2024-11-02 15:55:45.262 T:163081    info <general>: Opening stream: 1001 source: 256
2024-11-02 15:55:45.262 T:163081   error <general>: OpenStream: Codec id 27 require extradata.
2024-11-02 15:55:45.262 T:163081 warning <general>: OpenStream - Unsupported stream 1001. Stream disabled.
2024-11-02 15:55:45.262 T:163081    info <general>: Opening stream: 1003 source: 256
2024-11-02 15:55:45.262 T:163081    info <general>: Finding audio codec for: 86019
2024-11-02 15:55:45.263 T:163081    info <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder ac3

Not ok:

2024-11-02 15:57:47.036 T:160885   debug <general>: AddOnLog: pvr.hts: demux subscription start
2024-11-02 15:57:47.036 T:160885   debug <general>: AddOnLog: pvr.hts:   id: 1001, type H264, codec: 27
2024-11-02 15:57:47.037 T:160885   debug <general>: AddOnLog: pvr.hts: demux stream change
2024-11-02 15:57:47.037 T:163081   debug <general>: CDVDDemuxClient::RequestStream(): added/updated stream 1001 with codec_id 27
2024-11-02 15:57:47.037 T:163081    info <general>: Opening stream: 1001 source: 256
2024-11-02 15:57:47.037 T:163081   error <general>: OpenStream: Codec id 27 require extradata.
2024-11-02 15:57:47.037 T:163081 warning <general>: OpenStream - Unsupported stream 1001. Stream disabled.
2024-11-02 15:57:47.040 T:163081   debug <general>: GetPacketExtradata: fetching extradata, extradata_size(49)
2024-11-02 15:57:47.040 T:163081   debug <general>: CDVDDemuxClient::ParsePacket - split extradata

Now the log spam from Kodi starts with:

AddOnLog: pvr.hts: Dropped packet with unknown stream index 1002
AddOnLog: pvr.hts: Dropped packet with unknown stream index 1003

As a quick fix I just reset the stream like this. Although I think somehow adding the streams would be a lot better.
https://github.com/kodi-pvr/pvr.hts/blob/Piers/src/tvheadend/HTSPDemuxer.cpp#L547

Logger::Log(LogLevel::LEVEL_DEBUG, "Dropped packet with unknown stream index %i", idx);
m_lastPkt = 0;
m_conn.Disconnect();
m_demuxPktHdl.AllocateDemuxPacket(0);
return;

Do you think this is something that can be fixed on the plugin side? Thanks!

[spdfrk]

Well the above works pretty well but small adjustment needed to prevent the stream from resetting when it's closing down.

  /* Drop packets for unknown streams */
  if (m_streamStat.find(idx) == m_streamStat.end())
  {
    if(m_streamStat.size() > 0) {
      Logger::Log(LogLevel::LEVEL_DEBUG, "Dropped packet with unknown stream index %i", idx);
      m_conn.Disconnect();
    }

Tried also this as a test but somehow I end up with a 5 second delay on the video side which Kodi does not resync. Opening a second video player in parallel with the same stream shows the stream itself is actually ok. Or I think, not really sure how Tvheadend handles a second client on the same channel.

    if(idx == 1003) {
      m_streamStat[idx] = 0;
      kodi::addon::PVRCodec codec = m_demuxPktHdl.GetCodecByName("AC3");
      kodi::addon::PVRStreamProperties stream;
      stream.SetCodecType(codec.GetCodecType());
      stream.SetCodecId(codec.GetCodecId());
      stream.SetPID(idx);
      stream.SetChannels(6);
      stream.SetSampleRate(48000);
      m_streams.emplace_back(std::move(stream));
      DEMUX_PACKET* pkt = m_demuxPktHdl.AllocateDemuxPacket(0);
      pkt->iStreamId = DEMUX_SPECIALID_STREAMCHANGE;
      m_pktBuffer.Push(pkt);
    }

Anyway, not really sure yet how to proceed. Some input would be welcome!