TV-Server does'nt stop scheduled recordings (1 Viewer)

[uxDesign]

Hi, I have a sometimes problems with recording that won't stop. Today at 8:22 started the recording of 'Der Mondbär' and should stop at 8:57h

[2013-11-05 08:57:01,519] [Log ] [scheduler thread] [INFO ] - diskmanagement: recording Der Mondbär ended. type:Once max episodes:2147483647

[2013-11-05 08:57:13,755] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record KiKA HD 05.11.2013 08:22:24-05.11.2013 08:50:00 Der Mondbär

[2013-11-05 08:57:13,793] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record did not succeed (trying again in 1 min.) KiKA HD 05.11.2013 08:22:24-05.11.2013 08:50:00 Der Mondbär

[2013-11-05 08:57:28,855] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record did not succeed (trying again in 1 min.) KiKA HD 05.11.2013 08:22:24-05.11.2013 08:50:00 Der Mondbär

and so on...

The recording however was stopped but I have the file twice with timestamp 8:57h:

Der Mondbär - 2013-11-05 - Einladung an alle; Der schreckliche Riese.ts
Der Mondbär - 2013-11-05 - Einladung an alle; Der schreckliche Riese_1.ts

[2013-11-05 11:57:46,563] [Log ] [scheduler thread] [DEBUG] - ThumbProcessor.OnTvServerEvent: Enqueue recording D:\Media\Filme\Aufnahmen\KiKA HD\Der Mondbär\Der Mondbär - 2013-11-05 - Einladung an alle; Der schreckliche Riese_1.ts

The next recording started at 11:57:31 just before Mondbär ended really. But this recording didn't stop until evening when I came home. This should have been 3 parts of a docu being broadcasted on after the other.

[2013-11-05 11:57:31,202] [Log ] [scheduler thread] [INFO ] - Scheduler : record to D:\Media\Filme\Aufnahmen\Unterwegs in der Urzeit - ZDFinfo HD - 2013-11-05_1.ts

I stopped TVServer and ended up with several files, the largest 40GB!

It is not the first time that I have this problem, but I didn't keep the logs because I thought this would be a singular event. It never happened before switching to MP 1.5.

Regards,
uxDesign

 

[mm1352000]

Hello uxDesign

For some reason your first schedule (Der Mondbär) seems to have been recorded twice. Both recordings were stopped successfully at 08:57:01:

[2013-11-05 08:57:01,328] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record KiKA HD 05.11.2013 08:22:12-05.11.2013 08:50:00 Der Mondbär
[2013-11-05 08:57:01,333] [Log ] [scheduler thread] [INFO ] - card: StopRecording card=2, user=scheduler1138
[2013-11-05 08:57:01,336] [Log ] [scheduler thread] [INFO ] - basesubchannel.StopRecording 1
[2013-11-05 08:57:01,338] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch=1, subch index=1
[2013-11-05 08:57:01,341] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch:1-1 tswriter StopRecording...
[2013-11-05 08:57:01,362] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 2 subch#1
[2013-11-05 08:57:01,365] [Log ] [scheduler thread] [INFO ] - DVB subch:1 Decompose()
[2013-11-05 08:57:01,399] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 1
[2013-11-05 08:57:01,402] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : subchannels STILL present 1, continuing graph
[2013-11-05 08:57:01,405] [Log ] [scheduler thread] [DEBUG] - usermanagement.RemoveUser: scheduler1138, subch: 1 of 1, card: 2
[2013-11-05 08:57:01,407] [Log ] [scheduler thread] [INFO ] - user:scheduler1138 remove
[2013-11-05 08:57:01,410] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2013-11-05 08:57:01,412] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2013-11-05 08:57:01,415] [Log ] [scheduler thread] [INFO ] - DVB subch:0 Decompose()
[2013-11-05 08:57:01,417] [Log ] [scheduler thread] [INFO ] - basesubchannel.StopRecording 0
[2013-11-05 08:57:01,420] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch=0, subch index=0
[2013-11-05 08:57:01,422] [Log ] [scheduler thread] [INFO ] - tvdvbchannel.OnStopRecording subch:0-0 tswriter StopRecording...
[2013-11-05 08:57:01,479] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2013-11-05 08:57:01,482] [Log ] [scheduler thread] [INFO ] - dvbtopGraph

...but probably the way the second recording was stopped confused the scheduler, and hence you see the "failed to stop" messages.
@gibman this seems like a bug. If the scheduler detects that a subchannel is null I think it should give up trying to stop the recording.

[2013-11-05 08:57:43,874] [Log ] [scheduler thread] [INFO ] - Scheduler: stop record KiKA HD 05.11.2013 08:22:24-05.11.2013 08:50:00 Der Mondbär
[2013-11-05 08:57:43,881] [Log ] [scheduler thread] [INFO ] - card: StopRecording card=2, user=scheduler1138
[2013-11-05 08:57:43,889] [Log ] [scheduler thread] [INFO ] - card: StopRecording subchannel null, skipping

Same with "Unterwegs in der Urzeit". It seems like the service started 2 recordings...

[2013-11-05 11:57:05,951] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record ZDFinfo HD 11:57-12:45 Unterwegs in der Urzeit
[2013-11-05 11:57:30,734] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record ZDFinfo HD 11:57-12:45 Unterwegs in der Urzeit

...but the second recording was stopped immediately because of the outstanding request to stop the "Der Mondbär" recording.

This is really not normal!
Did you import your schedules somehow?
Could you please export your schedules (use the import/export section of TV Server configuration) and post the XML file for us.

mm

 

[uxDesign]

Hi mm,

here the export file, I only deleted the descriptions of TV-Wishlist plugin. This plugin is new since I switched to MP 1.5. Can this cause the problem? In TV-Wishlist I use only email notifications and no automatic recordings. 'Möndbär' is a daily scheduled series and 'Unterwegs in der Urzeit' was scheduled in the program guide. Today (Nov 6.) 'Möndbär' was ok, but on Nov 4. it was also recorded twice.

Thanks
uxDesign

PS: I didn't import my schedules, I even wasn't aware of that feature

 

[TheEngineer0815]

Hallo,

I have made a clean Install to win 8.1 Pro three Weeks ago and Installed MP 1.5
I've got the same Problem that recording is not stopping anymore.

We are also discussing this in the german Forum: https://forum.team-mediaportal.com/threads/aufnahme-wird-nicht-beendet.121532/

 

[mm1352000]

I've got the same Problem that recording is not stopping anymore.

Maybe same symptom (recording not stopping)... but almost certainly not the same problem.

Please provide full log files.
I note that abrandt's log files are insufficient to identify the cause.

 

[mm1352000]

Thanks for the schedule export uxDesign

I don't see duplicate schedules in there so I'm at a loss to explain why schedules would be recorded twice.

This plugin is new since I switched to MP 1.5. Can this cause the problem?

Only one way to find out. You could temporarily disable the plugin and see if the problem goes away.

 

[abrandt]

I'm not sure what log-files your are need, but that files are all I have.
The logfiles may be insufficient, because I'm killing the tvservice process - thats the only way to stop a recording.

In my system, I didn't recognized duplicated schedules.

When I disable all tvservice-plugins (only xmltv for epg) and plugins for MP (Skin, TVseries, TVMovie) - the service has the same Problem - the recordings didn't stop.

 

[mm1352000]

I'm not sure what log-files your are need, but that files are all I have.

I am interested in the event logs. Those logs are only included when you use the watchdog.
In your first set of logs it looks like you didn't wait until the end of the recording... so although the event logs are present, I can't see anything interesting.

The logfiles may be insufficient, because I'm killing the tvservice process - thats the only way to stop a recording.

No - they're insufficient because you only included the TVService.log.

In my system, I didn't recognized duplicated schedules.

I agree - that's why I said to TheEngineer0815 that you probably are experiencing a different problem... even though the symptom is the same.

When I disable all tvservice-plugins (only xmltv for epg) and plugins for MP (Skin, TVseries, TVMovie) - the service has the same Problem - the recordings didn't stop.

Okay.

 

[abrandt]

so i'm upload a new diag-logs
i'm programmed "Die Simpsons - 2013-11-09_12_45" Start: today 12:45pm End: today 01:15pm (with 10min before and 15min after) - the recording is still aktive

In your first set of logs it looks like you didn't wait until the end of the recording... so although the event logs are present, I can't see anything interesting.

No - schedules starts at 08:15 pm and i'm killing the tvservice in the moring next day - and the recordings are 20GB and above

 

[mm1352000]

Thanks
Unfortunately I don't understand German but it looks like some kind of error occurred:

12:45:22";"ESENT";"Allgemein";"Information";"svchost (10096) Instance: Das Datenbankmodul hat die Instanz (0) beendet. Fehlerhaftes Herunterfahren: 0 Interne Zeitsteuerungsabfolge: [1] 0.000, [2] 0.000, [3] 0.000, [4] 0.000, [5] 0.000, [6] 0.000, [7] 0.000, [8] 0.000, [9] 0.000, [10] 0.000, [11] 0.000, [12] 0.000, [13] 0.000, [14] 0.000, [15] 0.000.";"103"

Google translate is translating "das datenbankmodul" to "the database". I'm not sure if that is your MySQL database or some other database...

There is nothing else to see, so it looks like the scheduler threads might have silently died or deadlocked after starting the first recording, but I don't see why.

mm