(Some) Satellite channels not working : Writer failed to get PMT pid

[cheeseborough]

I have a machine running Ubuntu Server 20.04 with a TBS 5521 connected to a Sky satellite dish. Actually most TV channels are working fine - I have a good signal, clear pictures and reliable streams. However, some channels fail to work. Looking at the logs, the main difference between a working channel and one that doesn't is this message: [ERROR] Writer failed to get PMT pid

The device-adapter log is here:

Code:

2022-04-10 12:42:50:757 [DEBUG] got request:
POST /stream/start?slipseconds=1200&target=LIVE%26%2Fvideo%2Fnextpvr%2Flive-Film4-37188-2.ts HTTP/1.1
Host: localhost:41393
Connection: Keep-Alive
Content-Type: application/x-www-form-urlencoded
Content-Length: 197

<tuning>
  <type>DVB-S</type>
  <name>Film4</name>
  <locator>
    <conf>11307000HORIZONTAL</conf>
  </locator>
  <service_id>8385</service_id>
  <service_type>27</service_type>
</tuning>

2022-04-10 12:42:50:757 [DEBUG] starting stream: LIVE&/video/nextpvr/live-Film4-37188-2.ts
2022-04-10 12:42:50:757 [DEBUG] slip seconds: 1200
2022-04-10 12:42:50:757 [DEBUG]
Film4
2022-04-10 12:42:50:771 [INFO] Tuning: 10936000 Hz
2022-04-10 12:42:50:771 [INFO] Changing frequencies
2022-04-10 12:42:51:019 [INFO] Tuning: 10936000 Hz
2022-04-10 12:42:51:129 [INFO] using demux 'dvb0.demux0'
2022-04-10 12:42:51:129 [INFO] using dvr 'dvb0.dvr0'
2022-04-10 12:42:51:129 [DEBUG] waiting for signal lock
2022-04-10 12:42:51:206 [DEBUG] status 00 | quality 00 | signal ffff67a8 | snr 0000 | ber 00000000 | unc 00000000 | pre_ber 00000000 | per 00000000 |
2022-04-10 12:42:51:235 [DEBUG] status 00 | quality 00 | signal ffff67a8 | snr 0000 | ber 00000000 | unc 00000000 | pre_ber 00000000 | per 00000000 |
2022-04-10 12:42:51:263 [DEBUG] status 1f | quality 00 | signal ffff67a8 | snr 416e | ber 00000000 | unc 00000000 | pre_ber 00000000 | per 00000000 |
2022-04-10 12:42:51:263 [DEBUG] FE_HAS_LOCK
2022-04-10 12:42:51:263 [INFO] Creating writer for: LIVE&/video/nextpvr/live-Film4-37188-2.ts (live mode)
2022-04-10 12:42:51:263 [DEBUG] mutex would be: Global\NPVR-mutex-4b5783f53a08fd3a6538e1d494174e83
2022-04-10 12:42:51:263 [DEBUG] Created shared memory
2022-04-10 12:42:51:405 [ERROR] Writer failed to get PMT pid
2022-04-10 12:42:51:405 [INFO] Stopped recording (/video/nextpvr/live-Film4-37188-2.ts)
2022-04-10 12:42:51:456 [INFO] received request
2022-04-10 12:42:51:456 [DEBUG] got request:
GET /stream/stop?handle=1 HTTP/1.1
Host: localhost:41393
Connection: Keep-Alive


2022-04-10 12:42:51:456 [DEBUG] stopped stream 1
2022-04-10 12:42:51:456 [DEBUG] No more streams active.
2022-04-10 12:42:51:456 [DEBUG] Stopping device...
2022-04-10 12:42:51:456 [DEBUG] Stopped

The nrecord log:

Code:

2022-04-10 12:42:50.244    [DEBUG][41]    Checking XBMC sid: ea7d6908a6d247859d9c46f9aeb2f6dd
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@1..
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@2
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@3
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@4
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@5
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@6
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@7...
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@previous-handle = 1507329
2022-04-10 12:42:50.244    [DEBUG][41]    StreamNative@8 (/video/nextpvr/live-Film4-37188-2.ts)
2022-04-10 12:42:50.244    [DEBUG][41]    about to start stream...
2022-04-10 12:42:50.244    [DEBUG][41]    StartStream(7941:Film4)
2022-04-10 12:42:50.244    [DEBUG][41]    checking if previous capture source can be reused
2022-04-10 12:42:50.244    [DEBUG][41]    checking if previous capture source can be reused
2022-04-10 12:42:50.245    [DEBUG][41]    About to change frequencies...will stop existing handles
2022-04-10 12:42:50.245    [DEBUG][41]    http://localhost:41393/stream/start?slipseconds=1200&target=LIVE%26%2Fvideo%2Fnextpvr%2Flive-Film4-37188-2.ts
2022-04-10 12:42:50.245    [DEBUG][41]    body:
<tuning>
  <type>DVB-S</type>
  <name>Film4</name>
  <locator>
    <conf>11307000HORIZONTAL</conf>
  </locator>
  <service_id>8385</service_id>
  <service_type>27</service_type>
</tuning>

2022-04-10 12:42:50.608    [ERROR][41]    Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The remote server returned an error: (500) OK.
   at System.Net.HttpWebRequest.GetResponse()
   at System.Net.WebClient.GetWebResponse(WebRequest request)
   at System.Net.WebClient.DownloadBits(WebRequest request, Stream writeStream)
   at System.Net.WebClient.UploadBits(WebRequest request, Stream readStream, Byte[] buffer, Int32 chunkSize, Byte[] header, Byte[] footer)
   at System.Net.WebClient.UploadDataInternal(Uri address, String method, Byte[] data, WebRequest& request)
   at System.Net.WebClient.UploadString(Uri address, String method, String data)
   at NShared.LocalRecorder.StartStream(ChannelMapping channelMapping, String target, String& reason)
2022-04-10 12:42:50.608    [DEBUG][41]    Stopping handles from last frequency
2022-04-10 12:42:50.609    [DEBUG][41]    http://localhost:41393/stream/stop?handle=1
2022-04-10 12:42:50.657    [ERROR][41]    Unable to SwitchStream. Reason: The remote server returned an error: (500) OK.
2022-04-10 12:42:50.657    [DEBUG][41]    SwitchStream not possible
2022-04-10 12:42:50.657    [DEBUG][41]    stopping previous handle
2022-04-10 12:42:50.657    [DEBUG][41]    http://localhost:41393/stream/stop?handle=1
2022-04-10 12:42:50.708    [DEBUG][41]    looking for capture source (in reverse priority order)
2022-04-10 12:42:50.708    [DEBUG][41]    checking: IPTV (http://...)
2022-04-10 12:42:50.708    [DEBUG][41]    checking: adapter0/frontend0 (TurboSight TBS 5520SE DVB-T/T2/C/C2/ISDB-T)
2022-04-10 12:42:50.708    [DEBUG][41]    checking: adapter0/frontend0 (TurboSight TBS 5520SE DVB-T/T2/C/C2/ISDB-T)
2022-04-10 12:42:50.708    [DEBUG][41]    enabled and present
2022-04-10 12:42:50.708    [DEBUG][41]    does not have channel
2022-04-10 12:42:50.708    [DEBUG][41]    checking: adapter0/frontend1 (TurboSight TBS 5520SE DVB-S/S2/S2X)
2022-04-10 12:42:50.708    [DEBUG][41]    enabled and present
2022-04-10 12:42:50.708    [DEBUG][41]    has channel
2022-04-10 12:42:50.709    [DEBUG][41]    live tv is possible
2022-04-10 12:42:50.709    [DEBUG][41]    http://localhost:41393/stream/start?slipseconds=1200&target=LIVE%26%2Fvideo%2Fnextpvr%2Flive-Film4-37188-2.ts
2022-04-10 12:42:50.709    [DEBUG][41]    body:
<tuning>
  <type>DVB-S</type>
  <name>Film4</name>
  <locator>
    <conf>11307000HORIZONTAL</conf>
  </locator>
  <service_id>8385</service_id>
  <service_type>27</service_type>
</tuning>

2022-04-10 12:42:51.407    [ERROR][41]    Unexpected error on LocalRecorder.StartStream(): System.Net.WebException: The remote server returned an error: (500) OK.
   at System.Net.HttpWebRequest.GetResponse()
   at System.Net.WebClient.GetWebResponse(WebRequest request)
   at System.Net.WebClient.DownloadBits(WebRequest request, Stream writeStream)
   at System.Net.WebClient.UploadBits(WebRequest request, Stream readStream, Byte[] buffer, Int32 chunkSize, Byte[] header, Byte[] footer)
   at System.Net.WebClient.UploadDataInternal(Uri address, String method, Byte[] data, WebRequest& request)
   at System.Net.WebClient.UploadString(Uri address, String method, String data)
   at NShared.LocalRecorder.StartStream(ChannelMapping channelMapping, String target, String& reason)
2022-04-10 12:42:51.407    [ERROR][41]    Unable to StartStream(): The remote server returned an error: (500) OK.
2022-04-10 12:42:51.407    [DEBUG][41]    StartStream(7941:Film4, LIVE&/video/nextpvr/live-Film4-37188-2.ts) allocated handle: 0
2022-04-10 12:42:51.407    [DEBUG][41]    Handle: 0
2022-04-10 12:42:51.407    [DEBUG][41]    Failed to start stream. Handle 0.
2022-04-10 12:42:51.407    [DEBUG][37]    StopStream(1507329)...
2022-04-10 12:42:51.407    [DEBUG][37]    clientHandle[XBMC-ea7d6908a6d247859d9c46f9aeb2f6dd] = 1507329
2022-04-10 12:42:51.407    [DEBUG][37]    Calling StopStream()
2022-04-10 12:42:51.409    [DEBUG][37]    http://localhost:41393/stream/stop?handle=1
2022-04-10 12:42:51.457    [DEBUG][37]    StopStream() done

My understanding is that the system is getting a lock on the signal, its failing to set up the transcoding part of the pipeline.
Does anyone have any advice as to where to look next in tracking down this fault?

[mvallevand]

Because it is both tuners, I don't think nothing can do anything to help. Can you create a recording on this channel manually using dvbv5 tools?

dvbv5-zap -c /var/opt/nextpvr/adapter1-ATSC-channels.conf Film4 -r

and from another session

cp /dev/dvb/adapter0/dvr0 film4.ts

Note: you probably will need to stop or restart the NextPVR service to free up the tuner.

Martin