Post Processing and moving files

[ballfam]

I'm using a post processing script to move files after the recording is done, and it was working well for some time (at least a few years), but I just noticed that the NextPVR database no longer seems to be updated with the new loaction. The last line of the script is:

Code:

  # tell NextPVR where it went
  /opt/dotnet/dotnet /opt/nextpvr/system/NScriptHelper.dll  -rename "$1" "$plex_file"

It's supposed to tell the NextPVR database that the file moved from the input filename (in $1) to my new location (in $plex_file)

For a very long time it was working fine, but now it doesn't seem to update the database. I did upgrade recently; has this command changed, or should this still work as-is?

[mvallevand]

I personally don't suppport NScriptHelper because I don't use it and sub doesn't test it enough. I think I found that you had to change to the folder the and run it like this the last time I checked

cd /opt/nextpvr/system/
/opt/dotnet/dotnet NScriptHelper.dll ....

Sub probably needs to update the json files.

Martin

[ballfam]

OK, thanks, I'll give that a try, and I'll add some extra tracing to the script while I'm there to see if I can track it down. 

It's not a major issue since I never play or manipulate the recordings from NextPVR (as you may have spotted from the script, I use Plex for that), so if they "disappear" from the database, it's kind of OK; but it is nice to at least get the status from NextPVR as a sanity check (e.g recorded fine, or failed because error 404, or something else).

[ballfam]

That change didn't seem to help; the debugging tells me everything else is correct in the script, so the only conclusion I can come to is that NScriptHelper isn't working properly.

One thing that did occur to me was that the action is non-atomic, and there may be some kind of timing window. I move the file first and then tell NextPVR it was moved; if NextPVR notices that the file is no longer there, it may remove it from the database before I get a chance to tell it that the file moved. There is only one line of script between moving it and running NScriptHelper, so the change is petty much instant, but it is a possibility. If I run NScriptHelper first, then I probably still have the same issue since the file will not be at the target location yet. I could copy the file instead, and then delete at the old location after running NScriptHelper, but these files can be petty big, a move to the same drive is instant (simple inode change), but a copy could be much longer running.

Maybe I'll play with it if I get time, but right now, this functionality seems to be broken, unless there are some requirements I don't know about.

[mvallevand]

NScripthelper is often broken. The only way I test it is with this in my PostStartup.sh comand and restart the service

Code:

cd /opt/nextpvr/system
/opt/dotnet/dotnet NScriptHelper.dll -isrecording

Perhaps that will help you. There would also be scripthelper logs if it running correctly.

Martin

[ballfam]

Thanks for the hint on the logs. looks like it does run the rename, but my timing window theory might be correct, error is:

Code:

2022-12-28 04:05:07.015 [ERROR][37]    Unable to find existing recording with filename: /media/server_jj/ToRecode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts

Yeah...that makes sense, I just moved that file to some other location.

The strange thing is that I'm sure this worked at some time in the past; I guess something changed in the newer releases somewhere.

Full logs attached for this one record cycle in case you can spot anything else of use.

[ballfam]

Logs didn't upload. I'm getting:

Code:

Your allocated attachment usage quota is [b]NaN MB[/b]. You are currently using [b]848.35 KB[/b]. [url=https://forums.nextpvr.com/usercp.php?action=attachments][View My Attachments][/url]

One more try.

[ballfam]

Deleted old attachments. Last try

[ballfam]

OK, in text form:

Code:

2022-12-28 04:05:00.015 [DEBUG][12]    Stopping recording (118691 on 21). Past end time of recording. 94
2022-12-28 04:05:00.243 [DEBUG][12]    StopStream@1
2022-12-28 04:05:00.244 [DEBUG][12]    Stopping m3u8 stream (https://i.mjh.nz/.../sbs.m3u8?....  [ZvcQzG/X/cvbBhtZP0MkTqWCoH3HT91b6DOaf1IORsDlCrCnctTiMCrLLOGVMCPCQl5EL1WeNOlL8mnqR9WS+mFxjpeq0Rnx3BKu4vCTSyNN1grc+w6OrtbKoTIEtiYE/Wkyt69DnfSPgMtday3KUN3WvUQ+3x6Zm5xtHiK7qkEVMA9gDGYL7RjNakWeHyE6pGt0jgG7YLDi6D4EYN/Up9SZdw9AqCV65duCxugWPSlgfu92whvrFbD16IBgoQyzFKMbKGlQszXLpu7z7T96FKWOK4WpZoawoNE8ZPYAomkb7wDFO/eYq2vUkI5z1TFLuax7fyrhr9K2tnVhb8Ym0TwmdX7EaJuN5uXzMxwUOxZilnhwl0HAWjnIm188WrnBfO+NXoz5/l8j7XfYaWKnZg==])
2022-12-28 04:05:00.244 [DEBUG][12]    Cancelling pending requests
2022-12-28 04:05:00.244 [DEBUG][12]    StopStream@2
2022-12-28 04:05:00.244 [DEBUG][12]    StopStream@3
2022-12-28 04:05:00.244 [DEBUG][12]    StopStream handle: 94
2022-12-28 04:05:00.244 [DEBUG][12]    Closing TSWriter....: /media/server_jj/ToRecode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts
2022-12-28 04:05:00.244 [ERROR][12]    writer.Close() did not complete in a timely fashion
2022-12-28 04:05:00.244 [DEBUG][12]    Close@2
2022-12-28 04:05:00.244 [DEBUG][12]    Closing mapAccessor
2022-12-28 04:05:00.245 [DEBUG][12]    Closing mapMMF
2022-12-28 04:05:00.245 [DEBUG][12]    Closing mapFileStream
2022-12-28 04:05:00.245 [DEBUG][12]    deleting /media/server_jj/ToRecode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts.map
2022-12-28 04:05:00.246 [DEBUG][12]    Close@exit
2022-12-28 04:05:00.246 [DEBUG][12]    StopStream@exit
2022-12-28 04:05:00.246 [DEBUG][12]    StopStream@exit
2022-12-28 04:05:00.249 [DEBUG][12]    StoreMetaData@exit
2022-12-28 04:05:00.250 [DEBUG][12]    Starting: bash -c "'/var/opt/nextpvr/scripts/PostProcessing.sh' '/media/server_jj/ToRecode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts' 3 118691 21 'SBS World News Late'"
2022-12-28 04:05:00.559 [DEBUG][37]    > chmod: changing permissions of '/media/server_jj/Recode/SBS World News Late/Season 2022/Plex Versions': Operation not permitted
2022-12-28 04:05:01.162 [DEBUG][56]    Got request [127.0.0.1]: /service (session.initiate)
2022-12-28 04:05:01.163 [DEBUG][56]    method=session.initiate
2022-12-28 04:05:01.163 [DEBUG][56]    parameters:
2022-12-28 04:05:01.163 [DEBUG][56]        method: session.initiate
2022-12-28 04:05:01.163 [DEBUG][56]        ver: 1.0
2022-12-28 04:05:01.163 [DEBUG][56]        device: scripthelper
2022-12-28 04:05:01.163 [DEBUG][56]        client_ip: 127.0.0.1
2022-12-28 04:05:01.163 [DEBUG][56]        host_callback: ...
2022-12-28 04:05:01.163 [DEBUG][56]        sid: default
2022-12-28 04:05:01.163 [INFO][56]      InitiateSession (device=scripthelper)
2022-12-28 04:05:01.163 [DEBUG][56]    SetSessionObject(60bea8ef1a7d42328b6aea12b90e6681, 'child', NON-null)
2022-12-28 04:05:01.163 [DEBUG][56]    Device: scripthelper
2022-12-28 04:05:01.163 [DEBUG][56]    SetSessionObject(60bea8ef1a7d42328b6aea12b90e6681, 'child', NON-null)
2022-12-28 04:05:01.163 [DEBUG][56]    <?xml version="1.0" encoding="utf-8" ?>^M
<rsp stat="ok">^M
  <sid>60bea8ef1a7d42328b6aea12b90e6681</sid>^M
  <salt>befbfd60-396e-41b0-967f-ffc3c99b1681</salt>^M
</rsp>^M

[ballfam]

Code:

2022-12-28 04:05:01.176 [DEBUG][37]    Got request [127.0.0.1]: /service (session.login)
2022-12-28 04:05:01.176 [DEBUG][37]    method=session.login
2022-12-28 04:05:01.176 [DEBUG][37]    parameters:
2022-12-28 04:05:01.176 [DEBUG][37]        method: session.login
2022-12-28 04:05:01.176 [DEBUG][37]        sid: 60bea8ef1a7d42328b6aea12b90e6681
2022-12-28 04:05:01.176 [DEBUG][37]        md5: 025B45B25F4A0436DFFE74D716F11C26
2022-12-28 04:05:01.176 [DEBUG][37]        client_ip: 127.0.0.1
2022-12-28 04:05:01.176 [DEBUG][37]        host_callback: ...
2022-12-28 04:05:01.176 [INFO][37]      LoginSession(sid = 60bea8ef1a7d42328b6aea12b90e6681)
2022-12-28 04:05:01.176 [DEBUG][37]    [imU1oNbN/STVuXG4qCTJq9FEzW4HKvfGMoqSJyehOH7cwyyCaiq1Eogqz9K5PytxkH+7RBenv7p7TLDdbK4c+t3gRLxxdkcZrrso6PVz9EmnGU/j66B99prjxHaN9ewiE6edC++s51eSWb2cADM9Hm4lSw8wrf0QyKL1FbTB1OX5qNVa04yy8qLjYg7eyPle18ClMIdYNpwv3T2ymQqeCJJNnzew+WVFMb0BnSHm6jFBnuG1tuJDeniAN/CeZ+f7r1EUEGrQI9aedM3LvSc3FPt6+Nd6v8BDIIExu9Hrffx6pA14Q1c0tmqG+PZDx6g+YFAydAPsHVvvspfUNiVZfw+x5NuXkpxWRQd7JIuqH9DLeHBELgRHM6wftQgiqsli61g0TtpyWz6pnzLg8VigAP54adNUE+iMUWCGR1/PFQhbn2GPU8Hm5qWgAKr5DLXbFeF7xGtdSJQFtQrFBTW0Vg==]
2022-12-28 04:05:01.176 [DEBUG][37]    [CeUugE1g9U0eKYa0SkT6TyLW5AfsJ3PVcF3fiiV4ChcBBB81M+pj9p2SACZ44TAfRC4D3kY18V96VXnGI3p/AxFS1mclozPvlFKI6LJ0twDpL/DSouGEqHEqBaJJs1/MvcTHGqk4ycZCNgVr/zCMCrcAIPbQYj7isbhvfpr1iKdnWHiioW4mN75MPTvYJ2DRQIq0zPBsTMDkOidbzHdZJGJj5+fZ36P+Qtu1JTToqH8wqVmy6ccOnqZvnM50+Uxi8gJnD+SD8fgvdrPPnz02KI3YQlJg9MxzLBr6Z//BstzEgbj73pFFT7mW983BwUbSwEB2N1BF79rrjLahJbbB+k3vBmIwE9V+Ri4+7MUdjs647tMKoO4VPJFLkXEoGMNwOQpV3RrnPIzFyC7dLIzBXf4rkzMEasamkjsD264vYxo=]
2022-12-28 04:05:01.176 [DEBUG][37]    [mrsXfAFXgVfS93s40KNFCAWjhqp3cJu0rf2lmAo3N9HThu7E2ah5BVBn+QO5es19ICuWj0I+wGo9WKR0Pgk0XaGRiSd6ZI62/7btt3j3k7beZfYqWLqLBGRChrRxLm1viUXkfYozTKJlaR5My4VQ2w36xGBx8l8wmcXY11wn4J6APU4rloxJgWy+ZNpLrnRBSdvQVRYyxEe87tCU2E4NJNsrHXgVPBnyQmSlaXJIXb7hjZDqlfORx2XPsP/Lmuddonuw/n22XTHfc2Elu2G38JBT90HALILRZoIMzeABT1EOX+VqU1WlrDhbRAOS1CejWcz1+8UpbQeddel3jTYLpHGo7j1a3BkxDJMVf/434baXjcKnCSVQfoE2YiQ+w1mNlhB4RJIcp1DZ1b4clV8tbjL0LM1rCIomBt9Wvj5D+Jc=]
2022-12-28 04:05:01.176 [DEBUG][37]    <?xml version="1.0" encoding="utf-8" ?>^M
<rsp stat="ok">^M
  <sid>60bea8ef1a7d42328b6aea12b90e6681</sid>^M
  <allow_settings>false</allow_settings>^M
  <allow_watch>true</allow_watch>^M
  <allow_schedule>true</allow_schedule>^M
  <allow_delete>true</allow_delete>^M
</rsp>^M

2022-12-28 04:05:01.177 [DEBUG][37]    Got request [127.0.0.1]: /services/service (recording.rename)
2022-12-28 04:05:01.178 [DEBUG][37]    method=recording.rename
2022-12-28 04:05:01.178 [DEBUG][37]    parameters:
2022-12-28 04:05:01.178 [DEBUG][37]        method: recording.rename
2022-12-28 04:05:01.178 [DEBUG][37]        from: /media/server_jj/ToRecode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts
2022-12-28 04:05:01.178 [DEBUG][37]        to: /media/server_jj/Recode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts
2022-12-28 04:05:01.178 [DEBUG][37]        sid: 60bea8ef1a7d42328b6aea12b90e6681
2022-12-28 04:05:01.178 [DEBUG][37]        client_ip: 127.0.0.1
2022-12-28 04:05:01.178 [DEBUG][37]        host_callback: ...
2022-12-28 04:05:01.178 [DEBUG][37]    Rename
2022-12-28 04:05:07.015 [ERROR][37]    Unable to find existing recording with filename: /media/server_jj/ToRecode/SBS World News Late/Season 2022/SBS.World.News.Late.S2022E258.ts
2022-12-28 04:05:07.015 [DEBUG][37]    <?xml version="1.0" encoding="utf-8" ?>^M
<rsp stat="fail">^M
  <err code="2" msg="Invalid Args" />^M
</rsp>^M