Schedules Direct Token Issue

[TheKenR]

Did I mention that I hate snippets.  Sub did put in code to request a new token and I want to confirm a few things.

Martin

LOL yeah you did! I'll PM you the full log.

K

[mvallevand]

I got the log but I don't like supporting by PM, because now you have to post them for sub. There are so many things goes wrong that it doesn't make sense for NextPVR to keep requesting them

If it fails with you VPN off then you might need to have SD look again since there is no guarantee that your ISP is providing a fixed IP either especially if you use T-Mobile or Verizon.

If you are running, multiple NextPVR servers, EPG123 or Jellyfin with SD at the same time you could also be creating a deadly embrace too.

Martin

[TheKenR]

I got the log but I don't like supporting by PM, because now you have to post them for sub.  There are so  many things goes wrong that it doesn't make sense for NextPVR to keep requesting them

If it fails with you VPN off then you might need to have SD look again since there is no guarantee that your ISP is providing a fixed IP either especially if you use T-Mobile or Verizon.

If you are running, multiple NextPVR servers,  EPG123 or Jellyfin with SD at the same time you could also be creating a deadly embrace too.

Martin

Hi Martin,

I'll send the log to sub as well.

My ISP is pretty good at keeping a fixed IP for an extended period. I'm not with T-Mobile or Verizon. I don't have multiple instances running of NextPVR and only use EPG123 for troubleshooting. Thanks for the Jellyfin reminder because I do have that running but I'm using the NextPVR plugin. I see in the log it appears to be pulling the EPG data from NextPVR. 

So last night's scheduled task was the first time it executed UpdateEPG.sh to disconnect my VPN and use my ISP assigned IP address. I got the same error. NextPVR gets the 403 error but continues to use the same token it received the day before. I would expect a 403 on the first request since my IP changed but then NextPVR "should" be requesting a token and all should be good.

Sorry but here's another snip.  No change from the log I sent you.

2023-02-18 06:06:20.511 [DEBUG][52] Doing EPG update from Schedules Direct JSON
2023-02-18 06:06:20.511 [DEBUG][52] SD using existing token
2023-02-18 06:06:20.532 [DEBUG][52] SD using existing token
2023-02-18 06:06:20.575 [DEBUG][52] Requesting /schedules
2023-02-18 06:06:20.575 [DEBUG][52] SD(https://json.schedulesdirect.org/20141201/schedules)
2023-02-18 06:06:20.575 [DEBUG][52] token header: 34dcd524a29eda09e29d23926af9bbed
2023-02-18 06:06:21.055 [ERROR][52] System.Net.WebException: The remote server returned an error: (403) Forbidden.
  at System.Net.HttpWebRequest.GetResponse()
  at NShared.SchedulesDirectJSONEPGSource.DoPOSTRequest(String url, String token, String body, Boolean retry)
2023-02-18 06:06:21.056 [ERROR][52] SD http code: Forbidden
2023-02-18 06:06:21.056 [ERROR][52] {"response":"TOKEN_EXPIRED","code":4006,"serverID":"20141201.web","message":"Token has expired. Request new token.","datetime":"2023-02-18T10:06:21Z"}
2023-02-18 06:06:21.058 [DEBUG][52] Got /schedules:
2023-02-18 06:06:21.062 [ERROR][52] Unexpected error processing chunk: Newtonsoft.Json.JsonReaderException: Error reading JArray from JsonReader. Current JsonReader item is not an array: StartObject. Path '', line 1, position 1.
  at Newtonsoft.Json.Linq.JArray.Load(JsonReader reader, JsonLoadSettings settings)
  at Newtonsoft.Json.Linq.JArray.Parse(String json, JsonLoadSettings settings)
  at NShared.SchedulesDirectJSONEPGSource.ProcessChunk(List`1 channelsChunk, IEPGUpdateCallback callback)
  at NShared.SchedulesDirectJSONEPGSource.UpdateEPG(IEPGUpdateCallback callback, Boolean manuallyInitiated)
2023-02-18 06:06:21.062 [DEBUG][52] SD using existing token
2023-02-18 06:06:21.070 [DEBUG][52] Requesting /schedules
2023-02-18 06:06:21.070 [DEBUG][52] SD(https://json.schedulesdirect.org/20141201/schedules)
2023-02-18 06:06:21.070 [DEBUG][52] token header: 34dcd524a29eda09e29d23926af9bbed

[mvallevand]

That's a snippet again so useless, there is an area of the code that sub needs to fix which is why he needs the logs but by the time it happens I expect his has happened earlier.

It is not the IPv4 you are assigned, they can still NAT it so you still need to follow up with SD to see what they are seeing.

If you send PM me your credentials I can test it here my bet is it will work.

Martin

[TheKenR]

That's a snippet again so useless, there is an area of the code that sub needs to fix which is why he needs the logs but by the time it happens I expect his has happened earlier.

It is not the IPv4 you are assigned, they can still NAT it so you still need to follow up with SD to see what they are seeing. 

If you send PM me your credentials I can test it here my bet is it will work.

Martin

What I'm showing in the snip in bold is clearly the issue. There are no missing lines. The full log I sent you and Sub shows that NextPVR requests a new token when it starts up but never when it gets a 403 error. That's the issue so what I'm giving you is not useless.

Let's see what Sub thinks.

[mvallevand]

No all the failures earlier with SD are the issue, it should not be failing on every request. Unfortuanely you didn't send the logs.


Martin

[sub]

2023-02-17 19:38:32.919 [ERROR][37] SD http code: Forbidden
2023-02-17 19:38:32.920 [ERROR][37] {"response":"TOKEN_EXPIRED","code":4006,"serverID":"20141201.web","message":"Token has expired. Request new token.","datetime":"2023-02-17T23:38:32Z"}

When we'd looked at this in the past, it'd been a code:4003 that prompted us to request a new token. This is 4006 instead.

I've added logic for the next build to also request it on 4006.

[TheKenR]

2023-02-17 19:38:32.919 [ERROR][37] SD http code: Forbidden
2023-02-17 19:38:32.920 [ERROR][37] {"response":"TOKEN_EXPIRED","code":4006,"serverID":"20141201.web","message":"Token has expired. Request new token.","datetime":"2023-02-17T23:38:32Z"}

When we'd looked at this in the past, it'd been a code:4003 that prompted us to request a new token. This is 4006 instead.

I've added logic for the next build to also request it on 4006.

Thanks Sub. 

For now I've implemented a work around by using XMLTV to download my channel lineups from SD and then import them as XML. This method works with my VPN connected as well.

K

[mvallevand]

Yes testing for both 4003 and 4006 will not solve the root cause, you will still spam the server and could be blocked anyway. Afterall NextPVR did handle 50 failed requests for the 4003 before it finally worked and then the 4003 and 4006 started again, so just retrying on the 4006 won't guarantee success.

I saw a forum post on the SD forum https://forums.schedulesdirect.org/viewt...752#p10752 but did you open the support ticket that I asked you to do? https://www.schedulesdirect.org/lineupsupport That is what Robert from the SDJSON suport told us to do and I think he does need to diagnose things with the VPN disabled.

Martin

[TheKenR]

I think handling the 4006 will resolve it. If SD is returning a code that is defined as "token expired" I would think the client should request a new token.

Yes, Robert contacted me via PM and helped me troubleshoot.

For now I've got XMLTV downloading my lineups, although I'm not using JSON.

Thanks
K