New install: Intermittent Recording Service Not Running, long delays

[sub]

Live TV is just a type of recording, so if one works, the other usually would too.

Differences typically are:
- recording directory: ie make sure it is set to a location it'll be able to write to.
- multiple tuners: live tv makes it's way *up* the tuner list looking for a tuner with the requested channel. recordings make their way *down* the tuner. So, if you have multiple tuners, and channels setup on each, you may be seeing the tuner that is being used for live tv is not functioning. I suspect temporarily deleting all tuners but one that has channels, so that live tv and recordings are trying the same tuner, so that you're testing the same thing.

[mvallevand]

Sub what does this mean? It is new to me and I don't see them followed with a start recording or a call to devicehost

Code:

2021-11-24 14:38:29.891    [DEBUG][66]    Waiting for immediate recording to start...
2021-11-24 14:38:29.891    [DEBUG][66]    immediate recording status=STATUS_PENDING
2021-11-24 14:38:29.891    [DEBUG][66]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
</rsp>

Martin

[sub]

I think it's when they've pushed the record button in kodi while watching live tv? (alternatively could just be pressing record in guide on show that is already happening)

It's basically just scheduling a recording, and waiting up to a few seconds to confirm it has started recording, before returning an 'ok' response.

[mvallevand]

But there are no recordings started after that. I see it only as pending and then it fails

2021-11-24 14:44:39.545 [DEBUG][19] CaptureSource.LoadAll()
2021-11-24 14:44:39.554 [DEBUG][19] Waiting for immediate recording to start...
2021-11-24 14:44:39.554 [DEBUG][19] immediate recording status=STATUS_PENDING
2021-11-24 14:44:39.554 [DEBUG][19] <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
</rsp>

2021-11-24 14:44:39.833 [DEBUG][9] Requesting wake up for 'RecordingOID869' [That '70s Show] at 11/24/2021 12:28 PM
2021-11-24 14:44:39.841 [DEBUG][9] Marking recording (869) as 'Recording service not running at recording time'

Martin

[mvallevand]

When I test an immediate recording mine doesn't go to status pending it goes right to recording

Code:

2021-11-24 21:10:35.703    [DEBUG][49]    Waiting for immediate recording to start...
2021-11-24 21:10:35.773    [DEBUG][9]    Reloading recording schedule
2021-11-24 21:10:35.774    [DEBUG][9]    PowerManagement CancelRecordingWakeupRequests (needs implementation)
2021-11-24 21:10:35.774    [DEBUG][9]    [Tough as Nails] at 2021-11-24 9:00 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    Requesting wake up for 'RecordingOID25070' [Tough as Nails] at 2021-11-24 8:57 p.m.
2021-11-24 21:10:35.703    [DEBUG][49]    Waiting for immediate recording to start...
2021-11-24 21:10:35.773    [DEBUG][9]    Reloading recording schedule
2021-11-24 21:10:35.774    [DEBUG][9]    PowerManagement CancelRecordingWakeupRequests (needs implementation)
2021-11-24 21:10:35.774    [DEBUG][9]    [Tough as Nails] at 2021-11-24 9:00 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    Requesting wake up for 'RecordingOID25070' [Tough as Nails] at 2021-11-24 8:57 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    PowerManagement ScheduleWakeup (needs implementation)
2021-11-24 21:10:35.774    [DEBUG][9]    [Star Trek: Discovery] at 2021-11-25 9:00 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    Requesting wake up for 'RecordingOID25068' [Star Trek: Discovery] at 2021-11-25 8:57 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    PowerManagement ScheduleWakeup (needs implementation)
2021-11-24 21:10:35.774    [DEBUG][9]    [La Brea] at 2021-11-30 9:00 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    Requesting wake up for 'RecordingOID25067' [La Brea] at 2021-11-30 8:57 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    PowerManagement ScheduleWakeup (needs implementation)
2021-11-24 21:10:35.774    [DEBUG][9]    [Star Trek: Discovery] at 2021-12-02 9:00 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    Requesting wake up for 'RecordingOID25069' [Star Trek: Discovery] at 2021-12-02 8:57 p.m.
2021-11-24 21:10:35.774    [DEBUG][9]    PowerManagement ScheduleWakeup (needs implementation)
2021-11-24 21:10:35.799    [DEBUG][9]    Looking for recording directory with most space available
2021-11-24 21:10:35.800    [DEBUG][9]    /home/martin/recordings/ has 302512877568 available
2021-11-24 21:10:35.802    [DEBUG][9]    /media/recordings has 1000908341248 available
2021-11-24 21:10:35.802    [DEBUG][9]    will record to /media/recordings/
2021-11-24 21:10:35.805    [DEBUG][9]    Preferred filename is 'Tough as Nails.S03E08.Battle Lines'
2021-11-24 21:10:35.855    [DEBUG][9]    allocating recording target filename: /media/recordings/Tough as Nails/Season 03/Tough as Nails.S03E08.Battle Lines.ts
2021-11-24 21:10:35.856    [DEBUG][9]    About to start recording (25070 on 1558): /media/recordings/Tough as Nails/Season 03/Tough as Nails.S03E08.Battle Lines.ts...
2021-11-24 21:10:35.856    [DEBUG][9]    (Recording is due to be stopped at 2021-11-24 10:00 p.m.)2021-11-24 21:10:35.800    [DEBUG][9]    /home/martin/recordings/ has 302512877568 available
2021-11-24 21:10:35.802    [DEBUG][9]    /media/recordings has 1000908341248 available
2021-11-24 21:10:35.802    [DEBUG][9]    will record to /media/recordings/
2021-11-24 21:10:35.805    [DEBUG][9]    Preferred filename is 'Tough as Nails.S03E08.Battle Lines'
2021-11-24 21:10:35.855    [DEBUG][9]    allocating recording target filename: /media/recordings/Tough as Nails/Season 03/Tough as Nails.S03E08.Battle Lines.ts
2021-11-24 21:10:35.856    [DEBUG][9]    About to start recording (25070 on 1558): /media/recordings/Tough as Nails/Season 03/Tough as Nails.S03E08.Battle Lines.ts...
2021-11-24 21:10:35.856    [DEBUG][9]    (Recording is due to be stopped at 2021-11-24 10:00 p.m.)

[sub]

When I test an immediate recording mine doesn't go to status pending it goes right to recording

It does go via pending->recording. It can happen pretty quickly though, and it'll be 'recording' by the time the call returns. (it waits for it to switch to 'recording' status before returning

[sub]

GnatGoSplat, while we're trying to debug your recording issue, it's probably best to stay away from more complicate scenarios like starting a recording while live tv is active.

Maybe restart everything (to reset the logs), then just schedule a recording, let it happen, then post the logs. (along with confirmation that failed or succeeded to whatever)

[GnatGoSplat]

Unfortunately, still not working even for scheduling future recordings and with Live TV not going.

I've attached screenshot of the failed recordings.  The first 3 at the bottom were just pressing record of live TV already in progress to make sure nothing had changed on its own for this boot.
Next 2 are future recordings from the guide, but I did have Live TV going.
Last one at the top, nothing going at all, and pressed Record from the Guide on a future airing.
Just adding a future recording causes it to fail immediately, they don't wait till the time occurs to fail.

One thing I noticed, the recording times shown are 2-hours earlier than current time, but the system clock is correct and the time shows correct in the actual Guide on Kodi.  When I log in remotely, the recording times are correct so it's only on localhost that they're off in the browser.

I was wrong about 0-byte files, there are 5KB .map files that I'm not even sure are of the recordings.  I've attached a screenshot of that.

I've attached a new copy of the logs.  I've restarted the computer, but there still seems to be old stuff in there from my earlier tests.

[mvallevand]

How do the shows on your web guide look? I suspect the timezone on your server is not correct. I looked on zap2it and those display start and stop times look by 2 hours.

Martin

[GnatGoSplat]

How do the shows on your web guide look?  I suspect the timezone on your server is not correct.  I looked on zap2it and those display start and stop times look by 2 hours. 

Martin

Ah hah, I think that was the problem entirely.  When I unchecked auto time zone, it was set to Pacific and I'm on Central time zone.  The auto time set and auto time zone in Windows apparently isn't working.  I turned off the auto, set them manually, then turned the auto back on, but "last sync" shows it's never been able to sync to time.windows.com for some reason.

I rebooted it to make sure the recording working wasn't just another one-time thing, and it was still working after a reboot.  Hopefully all is well!

The original slow response when skipping ahead doesn't seem to be there any more, so maybe it was somehow related.

Thanks everyone, for the help!