U4 - change in scheduled programs produces multiple timers for same event,

Discuss the IceTV EPG and Recording Apps here

Moderators: Gully, peteru

Post Reply
IanL-S
Master
Posts: 322
Joined: Mon Jun 27, 2016 15:11

U4 - change in scheduled programs produces multiple timers for same event,

Post by IanL-S » Fri Feb 09, 2018 15:50

On Saturday 7flix Melbourne has replaced 3 episodes of Bones with a movie - it the update process I have 3 recordings scheduled for the movie. Early on Saturday morning I have three timers scheduled for "Ricky Gervais Live: Politics", which as far as I am aware I have never scheduled.

I have checked on the U4 and those programs are not scheduled; the prior programs are scheduled (Bones in the first instance and 30 Rock and Parks and Recreation (which I have series recording set). Not sure if it is an IceTV or Beyonwiz issue. The U4 has the latest firmware (not on beta feed).

Ian
Attachments
Ashampoo_Snap_2018.02.09_16h37m20s_001_.jpg
Ashampoo_Snap_2018.02.09_16h37m42s_002_.jpg
Enjoying an active retirement "playing" with my Toppys and now Beyonwiz.
T2, U4 and V2 controlled by IceTV
Various Toppys including TRF-2400, TRF-5300 and TF7100HDPVRt Plus
For help with your Toppy checkout the oztoppy forum and the oztoppy wiki.

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Sat Feb 10, 2018 11:18

Daniel Hall at IceTV has contacted me about this, but I haven't been able to be any more helpful to him than this post is likely to be to you.

Similar problems have also been reported T series boxes on the IceTV forum (here and here, as well as your report there). Those reports are from T series boxes, so it looks as though it's not a U4-specific problem (which I would have thought unlikely, anyway).

The screenshots from the IceTV Web page are of limited use. What would be more useful in addition would be screenshots of the programs in the Beyonwiz's timer list (or the timers.xml file) and screenshots that show the history of modification of the timers (IceTV logs). The last one is hard to capture, because that log is cleared on GUI restart (or full system restart).
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Sat Feb 10, 2018 11:57

prl wrote:
Sat Feb 10, 2018 11:18
... The screenshots from the IceTV Web page are of limited use. What would be more useful in addition would be screenshots of the programs in the Beyonwiz's timer list (or the timers.xml file) and screenshots that show the history of modification of the timers (IceTV logs). The last one is hard to capture, because that log is cleared on GUI restart (or full system restart).

I've been meaning to ask you, is it possible to have a special permanent-debug version of the IceTV plugin that I could swap in/out as required? Or perhaps a mod to the existing plugin so that it could take its debug state from a "settings" file config entry (even if I had to hand-edit it), or perhaps use the presence/absence of an "IceTV.debug" file in the home directory?
Currently, you have to be very quick to enable debugging upon boot from deep standby. If you miss it, or if the T/U-series boots automatically, then the first fetch could very well gather in the changes without a chance for debugging.

In my case that I listed on the Ice forum, the Blue Blood timers had different 'ice_timer_id' values. I believe that should have required the IceTV server to issue a 'forget' for the original ice_timer_id and a 'record' for the replacement. Without the debugging on the 'Wiz, we've no way of knowing if the delete got sent or accepted.

IanL-S
Master
Posts: 322
Joined: Mon Jun 27, 2016 15:11

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by IanL-S » Sat Feb 10, 2018 16:01

prl wrote:
Sat Feb 10, 2018 11:18
The screenshots from the IceTV Web page are of limited use. What would be more useful in addition would be screenshots of the programs in the Beyonwiz's timer list (or the timers.xml file) and screenshots that show the history of modification of the timers (IceTV logs). The last one is hard to capture, because that log is cleared on GUI restart (or full system restart).
If it happens again I will get a screenshot. I use the U4 all the time, T2 are primarily for backup.

Ian
Enjoying an active retirement "playing" with my Toppys and now Beyonwiz.
T2, U4 and V2 controlled by IceTV
Various Toppys including TRF-2400, TRF-5300 and TF7100HDPVRt Plus
For help with your Toppy checkout the oztoppy forum and the oztoppy wiki.

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Sat Feb 10, 2018 16:42

Thanks, Ian.
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Sun Feb 11, 2018 11:17

IanL-S wrote:
Sat Feb 10, 2018 16:01
prl wrote:
Sat Feb 10, 2018 11:18
The screenshots from the IceTV Web page are of limited use. What would be more useful in addition would be screenshots of the programs in the Beyonwiz's timer list (or the timers.xml file) and screenshots that show the history of modification of the timers (IceTV logs). The last one is hard to capture, because that log is cleared on GUI restart (or full system restart).
If it happens again I will get a screenshot. I use the U4 all the time, T2 are primarily for backup.
...

A copy of the timers.xml file (or at least the repeated entries in it) would be very useful, too, since the timer entries have some details that aren't shown in the UI and also contain some logging information (that can be seen by pressing INFO for the timer when in the timer list)..
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Sun Feb 11, 2018 12:12

prl wrote:
Sun Feb 11, 2018 11:17
A copy of the timers.xml file (or at least the repeated entries in it) would be very useful, too, since the timer entries have some details that aren't shown in the UI and also contain some logging information (that can be seen by pressing INFO for the timer when in the timer list)..

Are you referring to the 'record time changed, start prepare is now {new time}' logging entries? I've not seen those entries in timers.xml for any timers set from IceTV. I've always assumed they only appear for AutoTimer adjustments.
Perhaps all of the IceTV changes I've observed have been forget/record changes and that's why I've not seen them.

In my case of the Blue Bloods timers, there is no extra logging info as to when the timers were set/changed -

Code: Select all

<timer begin="1518097800" end="1518103500" serviceref="1:0:19:684:607:1014:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Blue Bloods" description="Cutting Losses" afterevent="deepstandby" eit=
"48786" tags="" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="0" ice_timer_id="16369476556848109774">
<log code="5" time="1518097780">activating state 1</log>
<log code="0" time="1518097780">Found enough free space to record</log>
<log code="0" time="1518097780">Filename calculated as: &apos;/media/hdd/movie/20180208 2150 - TEN HD - Blue Bloods&apos;</log>
<log code="6" time="1518097780">prepare ok, waiting for begin</log>
<log code="5" time="1518097800">activating state 2</log>
<log code="11" time="1518097800">start recording</log>
<log code="5" time="1518103500">activating state 3</log>
<log code="12" time="1518103500">stop recording</log>
</timer>

<timer begin="1518098400" end="1518103800" serviceref="1:0:19:684:607:1014:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Blue Bloods" description="Cutting Losses" afterevent="deepstandby" eit=
"48786" tags="" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="0" ice_timer_id="16369494230873449226">
<log code="5" time="1518098380">activating state 1</log>
<log code="0" time="1518098380">Found enough free space to record</log>
<log code="0" time="1518098380">Filename calculated as: &apos;/media/hdd/movie/20180208 2200 - TEN HD - Blue Bloods&apos;</log>
<log code="6" time="1518098380">prepare ok, waiting for begin</log>
<log code="5" time="1518098400">activating state 2</log>
<log code="11" time="1518098400">start recording</log>
<log code="5" time="1518103800">activating state 3</log>
<log code="12" time="1518103800">stop recording</log>
</timer>

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Sun Feb 11, 2018 13:31

Grumpy_Geoff wrote:
Sun Feb 11, 2018 12:12
prl wrote:
Sun Feb 11, 2018 11:17
A copy of the timers.xml file (or at least the repeated entries in it) would be very useful, too, since the timer entries have some details that aren't shown in the UI and also contain some logging information (that can be seen by pressing INFO for the timer when in the timer list)..

Are you referring to the 'record time changed, start prepare is now {new time}' logging entries? I've not seen those entries in timers.xml for any timers set from IceTV. I've always assumed they only appear for AutoTimer adjustments.
...

I just want to get as much information about the timers as I can get. I didn't say that I didn't want the other information I asked for earlier.

The problem seems hard to provoke or plan for ahead of time. I am completely reliant on what information I can glean from users after the fact (and Daniel Hall, is too, I expect).
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Sun Feb 11, 2018 14:22

prl wrote:
Sun Feb 11, 2018 13:31
I just want to get as much information about the timers as I can get. I didn't say that I didn't want the other information I asked for earlier.

I just don't think there's anything in the timers.xml file that would show anything, apart from differing 'ice_timer_id' values (and they can be gleaned from the debug log).

prl wrote: The problem seems hard to provoke or plan for ahead of time. I am completely reliant on what information I can glean from users after the fact (and Daniel Hall, is too, I expect).

I agree, that's why I suggested an 'always debug on' IceTV plugin (with 'debug level = 4'), as then we can see if the IceTV server sent a 'forget' for the original timer.
The on-screen IceTV plugin log only shows the last 40 entries, very easy for the 'duplicate' to slip of the screen before it's actually noticed that it has occurred.
I'm surprised IceTV doesn't have some rudimentary logging of timers sent to a PVR (apart from conflicts).

IanL-S
Master
Posts: 322
Joined: Mon Jun 27, 2016 15:11

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by IanL-S » Sun Feb 11, 2018 14:48

Just checked something I missed in my previous post, my TRF-2400 had a similar issue, it did not delete the old timer task; Bones appeared to record but the content was (part) of the movie. The manifestation with the Toppy is slightly different but suggests that IceTV is not send a message to delete the timer to either the Beyonwiz or the 2400.

Ian
Enjoying an active retirement "playing" with my Toppys and now Beyonwiz.
T2, U4 and V2 controlled by IceTV
Various Toppys including TRF-2400, TRF-5300 and TF7100HDPVRt Plus
For help with your Toppy checkout the oztoppy forum and the oztoppy wiki.

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Sun Feb 11, 2018 16:16

Grumpy_Geoff wrote:
Sun Feb 11, 2018 14:22
prl wrote:
Sun Feb 11, 2018 13:31
I just want to get as much information about the timers as I can get. I didn't say that I didn't want the other information I asked for earlier.

I just don't think there's anything in the timers.xml file that would show anything, apart from differing 'ice_timer_id' values (and they can be gleaned from the debug log).

The timers in timers.xml have the start/end times accurate to the second. Most other displays of them are to the minute. I know that IceTV timers are supposed to be set on even 5 minutes (and that's true for your Blue Bloods example), but I am investigating behaviour that's not supposed to happen.

In IanL-S's examples, I've only seen the display on the IceTV Web page, and that shows all the duplicated timers with the same times, but only with a 1-minute resolution. Knowing whether they're actually the same times would also be useful.

Also, in all cases so far, there has been no debug logging available, and so the timer_ids in the timers.xml file are the only way for me to see whether the differing timer ids are a common element or not.
Grumpy_Geoff wrote:
Sun Feb 11, 2018 14:22
...
The on-screen IceTV plugin log only shows the last 40 entries, very easy for the 'duplicate' to slip of the screen before it's actually noticed that it has occurred.
I'm surprised IceTV doesn't have some rudimentary logging of timers sent to a PVR (apart from conflicts).

Yes, I'd like to see some less volatile, and more easily sharable and searchable logging from the IceTV plugin without going to the log of the HTML query/response data. The HDML logging is useful sometimes, but it's very bulky and difficult to read (no whitespace that's not part of strings or necessary for JSON or HTML syntax). The other logging tells a lot more about what's done with the data.
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

User avatar
peteru
Uber Wizard
Posts: 9730
Joined: Tue Jun 12, 2007 23:06
Location: Sydney, Australia
Contact:

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by peteru » Mon Feb 12, 2018 01:46

Code: Select all

_debug_level = 0  # 1 = request/reply, 2 = 1+headers, 3 = 2+partial body, 4 = 2+full body
Where partial body is up to 2000 characters from the start and end of the message.

Controlled with CH+/- and goes to normal enigma2 debug output location.

You could always add the following to addLog() to have everything in one place.

Code: Select all

if ice._debug_level > 0:
    print "[IceTV]", msg
If you want to go as far as making the debug level a persistent config option (and I would discourage that), please ensure that you never save a setting value larger than 2 (or maybe 1). The flood of log messages will negatively impact on performance and it is way too easy for users to leave the setting at a high value and then wonder why their box is as slow as a wet week.

"Beauty lies in the hands of the beer holder."
Blog.

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Mon Feb 12, 2018 11:44

Yes, I'm already using CH+ to set the IceTV debug level. The main problem is quickly setting the logging level before that first IceTV fetch after a boot or GUI restart. Of course, if the boot is unattended, no logging.
The other day I managed to get the logging level set only 1.8 secs before the first fetch was logged (more likely, I managed to set it whilst it was waiting on a response from the Ice server). That was on a T4, I'm guessing a U4 would initiate the call to IceTV even quicker.

I think I only need the '"timers":' part of the payload, no need for '"channels":' nor '"shows":', and therefore I can use debug level = 3 since the timers are listed last.
I currently use level 4 because I didn't know what the other levels logged, the payload message is large at the initial IceTV fetch, but not so big at other times.

User avatar
peteru
Uber Wizard
Posts: 9730
Joined: Tue Jun 12, 2007 23:06
Location: Sydney, Australia
Contact:

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by peteru » Mon Feb 12, 2018 13:06

For a temporary hack, you could always install the source package for IceTV plugin and then manually change the file to initialise the _debug_level variable to something else.

It'll be enough to debug a particular issue. When you are done, simply uninstall both IceTV plugin packages, then re-install the binary version only.

"Beauty lies in the hands of the beer holder."
Blog.

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Mon Feb 12, 2018 16:53

peteru wrote:
Mon Feb 12, 2018 13:06
For a temporary hack, you could always install the source package for IceTV plugin and then manually change the file to initialise the _debug_level variable to something else.

It'll be enough to debug a particular issue. When you are done, simply uninstall both IceTV plugin packages, then re-install the binary version only.

I'd be happy to give that a go, but I'd need my hand held on how to get a copy of the plugin source file, and where to place it (in /usr/lib/enigma2/python/Plugins/SystemPlugins/IceTV/ as plugin.py by any chance?)
Would I rename "plugin.pyo" to something else?
I'd have to undo this before each online update, right?

User avatar
peteru
Uber Wizard
Posts: 9730
Joined: Tue Jun 12, 2007 23:06
Location: Sydney, Australia
Contact:

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by peteru » Mon Feb 12, 2018 21:10

To install source

Code: Select all

opkg install enigma2-plugin-systemplugins-icetv-src
To remove both

Code: Select all

opkg remove enigma2-plugin-systemplugins-icetv enigma2-plugin-systemplugins-icetv-src
To install binary only

Code: Select all

opkg install enigma2-plugin-systemplugins-icetv

"Beauty lies in the hands of the beer holder."
Blog.

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Mon Feb 12, 2018 21:21

Seems easy-peasy. A job for tomorrow.
Thanks.

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Tue Feb 13, 2018 12:35

Grumpy_Geoff wrote:
Sun Feb 11, 2018 12:12
Are you referring to the 'record time changed, start prepare is now {new time}' logging entries? I've not seen those entries in timers.xml for any timers set from IceTV. I've always assumed they only appear for AutoTimer adjustments.
Perhaps all of the IceTV changes I've observed have been forget/record changes and that's why I've not seen them.

Time to eat my words :oops: :) Here's two IceTV timers with log code 15 entries.

Existing timer details -
Adventure Time, ice_timer_id=16369462276048328528, begin=14-Feb 04:30, end=04:50
Power Rangers, ice_timer_id=16369462273246533449, begin=14-Feb 04:50, end=05:10

IceTV sent an "Updated by Scheduler SERIES" message for the existing timers. The update had new start times and new durations -
Adventure Time, id: 16369462276048328528, start_time: 2018-02-13T20:00:00+00:00, duration_minutes:30, action:record (so, a 14-Feb 04:00 start)
Power Rangers, id:16369462273246533449, start_time:2018-02-13T20:30:00+00:00, duration_minutes:30, action:record (so, a 14-Feb 04:30 start)

The IceTV plugin deleted the original timers (perhaps due to the duration change), and created two new timers with the new details (pre/post-padding is 10/25). The plugin then sent the details to the IceTV server which responded with two new Ice timer IDs -

Code: Select all

<timer begin="1518551400" end="1518555300" serviceref="1:0:1:463:460:1012:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Adventure Time With Finn And Jake" description="Walnuts &amp; Rain / Chi
ps &amp; Ice Cream" afterevent="auto" eit="48669" tags="" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="0" ice_timer_id="16370903530858612238">
<log code="15" time="1518473209">record time changed, start prepare is now: Wed Feb 14 03:49:40 2018</log>
</timer>
<timer begin="1518553200" end="1518557100" serviceref="1:0:1:463:460:1012:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Power Rangers Dino Charge" description="No Matter How You Slice It" afte
revent="auto" eit="48670" tags="" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="0" ice_timer_id="16370903530858612239">
<log code="15" time="1518473209">record time changed, start prepare is now: Wed Feb 14 04:19:40 2018</log>
</timer>


I'm a bit puzzled by this debug log entry though -
There is not /etc/enigma2/timers.xml file !!! Why ??
It was listed after the two new timers were sent (POST) to IceTV

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Wed Feb 14, 2018 16:31

Did these two timer updates (delete/re-creates) work correctly or not? By the look of what you posted, it worked correctly, but I just wanted to be sure.
Grumpy_Geoff wrote:
Tue Feb 13, 2018 12:35
...
I'm a bit puzzled by this debug log entry though -
There is not /etc/enigma2/timers.xml file !!! Why ??
It was listed after the two new timers were sent (POST) to IceTV

Now that's a strange one (apart from the twisted syntax).

The code that writes that to the logs is in RecordTimer.saveTimer(). It happens if there's an exception in the code that writes a list containing the contents of timers.xml to the file, first by opening /etc/enigma2/timers.xml.writing, writing the new contents to that and then renaming /etc/enigma2/timers.xml.writing to /etc/enigma2/timers.xml.

Unfortunately, the exception's message isn't part of what's written to the debug log:

Code: Select all

		try:
			f = open(self.Filename + ".writing", "w")
			for x in list:
				f.write(x)
			f.flush()

			os.fsync(f.fileno())
			f.close()
			os.rename(self.Filename + ".writing", self.Filename)
		except:
			print "There is not /etc/enigma2/timers.xml file !!! Why ?? "
Note that the message is actually rather misleading. The problem isn't that timers.xml (or timers.xml.writing) doesn't exist, but rather that timers.xml.writing couldn't be created, had write errors while writing it, or couldn't be renamed to timers.xml. It also prints what self.Filename should be, rather than what it actually is :(

I'm also a bit puzzled by the "make a list and the write the list" aspect of the code rather than just writing the text to the file as I'd probably have written it, but there's nothing actually incorrect about doing it that way.

Could you check that the flash drive isn't full (or nearly full)?
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Wed Feb 14, 2018 17:35

Yep, those timer re-creations were correct.

Both new timers had their 'ice_timer_id' attributes updated in response to the POST to IceTV, so they were updated successfully too.

T2 Flash is 309MB free (461MB total).

There wasn't a clash between AutoTimers and IceTV plugin as the previous AutoTimer poll finished 52 secs before the message and the next one started 104 secs later.

The POSTs to Ice were at <156676.032> and <156676.305>, and the error was listed at <156677.247> - so almost a second before the error was listed. Nothing else in the log around those times.


I've just checked logs for the T2 and T4 -- both units have reported this over a number of days.
Last T2 occurrence was yesterday, last T4 occurrence was 7-Feb. My U4 isn't using IceTV yet.
It's possible whatever caused this has been fixed in recent updates, as my T2 is lagging behind on revision 20180129 whilst the T4 is on revision 20180207.

One week ago on the T2 -

Code: Select all

{624}< 19153.627> [SCREENNAME]  StandbySummary
{624}< 19153.639> [SCREENNAME]  Standby
{8926}< 19181.276> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27280}< 19181.433> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27276}< 19181.943> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27274}< 19184.833> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27272}< 19184.941> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27279}< 19198.034> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27276}< 19198.366> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{8926}< 19198.547> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27272}< 19198.672> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27274}< 19198.784> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27275}< 19199.881> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{749}< 19199.885> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27276}< 19210.628> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27276}< 19221.487> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27272}< 19236.541> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27280}< 19236.918> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27277}< 19237.016> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27278}< 19244.737> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27274}< 19244.832> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{749}< 19250.426> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27277}< 19250.432> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27276}< 19250.636> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{8926}< 19258.061> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{749}< 19263.850> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27272}< 19263.978> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27280}< 19264.088> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27274}< 19264.216> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27278}< 19270.192> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27279}< 19270.416> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27279}< 19282.655> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27274}< 19282.844> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27272}< 19282.856> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{8926}< 19283.013> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{749}< 19283.094> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27280}< 19283.107> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27277}< 19283.334> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27276}< 19283.342> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27275}< 19283.348> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27274}< 19286.576> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{27278}< 19286.585> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{624}< 19636.117> KEY: 116 make KEY_POWER ('POWER',)
{624}< 19636.118> [ActionMap] StandbyActions power
{624}< 19636.119> [Standby] leave standby
{624}< 19636.355> [SCREENNAME]  MovieSelectionSummary
{624}< 19636.362> KEY: 116 break KEY_POWER ('POWER',)
{624}< 19636.378> [SCREENNAME]  MovieSelection
{624}< 19643.713> KEY: 174 make KEY_EXIT ('EXIT',)

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Wed Feb 14, 2018 18:44

Strange. I'll turn logging on on our in-use T4 and see if i can reproduce the error. If I can, I'll improve the logging and see what's going on.
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Tue Feb 20, 2018 21:06

Grumpy_Geoff wrote:
Wed Feb 14, 2018 17:35
... It's possible whatever caused this has been fixed in recent updates, as my T2 is lagging behind on revision 20180129 whilst the T4 is on revision 20180207.

Nup, not fixed by any recent updates as I'm still occasionally getting There is not /etc/enigma2/timers.xml file !!! Why ?? on our T2, e.g. today @ time interval 6400:

Code: Select all

{623}<  6325.899> [eDVBServiceRecord] now running: Paper Port (767 seconds)
{623}<  6325.900> [eDVBDemux] open demux /dev/dvb/adapter0/demux0
{623}<  6325.900> [eDVBSectionReader] DMX_SET_FILTER pid=18
{789}<  6396.669> [RecordTimer] record time changed, start prepare is now: Tue Feb 20 06:01:30 2018
{789}<  6397.448> [RecordTimer] record time changed, start prepare is now: Wed Feb 21 02:09:40 2018
{789}<  6397.662> [RecordTimer] record time changed, start prepare is now: Wed Feb 21 03:59:40 2018
{789}<  6397.845> [RecordTimer] record time changed, start prepare is now: Wed Feb 21 04:24:40 2018
{789}<  6398.045> [RecordTimer] ignore double timer
{6407}<  6400.499> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{6413}<  6400.506> There is not /etc/enigma2/timers.xml file !!! Why ?? 
{623}<  7055.806> [eDVBServiceRecord] pcr of eit change for event 7220: 54f27e5e
The T2 is on 20180216. T4 also is on 20180216 but hasn't listed this 'error' since the 7th.

IanL-S
Master
Posts: 322
Joined: Mon Jun 27, 2016 15:11

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by IanL-S » Wed Mar 07, 2018 08:42

It has happened again - sehttp://www.beyonwiz.com.au/forum/download/file ... w&id=3287e attachments.
Attachments
IcveTV listing.jpg
U4 listing 1.jpg
U4 Listing 2.jpg
Enjoying an active retirement "playing" with my Toppys and now Beyonwiz.
T2, U4 and V2 controlled by IceTV
Various Toppys including TRF-2400, TRF-5300 and TF7100HDPVRt Plus
For help with your Toppy checkout the oztoppy forum and the oztoppy wiki.

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Wed Mar 07, 2018 12:58

My guess is that IceTV is sending out the new timer with a different IceTV timer id on it than the original. Unfortunately, that's hard to check, because the timer id isn't logged. Probably only server-side logging would be able to say. In the discussion in U4 schedule change produces multiple timers for same program on the IceTV forum, Daniel Hall says that he's enabled logging on your account. It might be useful to see whether you still have logging on and whether that shows anything "interesting" on their end.

Your IceTV Web page screenshot shows 3 timers for Cold Case "It's Raining Men", but the Beyonwiz Open Webif screenshots only show two. Were there two or three timers on the Beyonwiz side? Also, strangely, the IceTV screenshot shows all 3 timers starting at 23:50, but the Open Webif screen shots shows those two both starting at 23:45, but with different end times

The start times are odd for the two Madam Secretary recordings, too: IceTV shows them both at 21:40, and the two timers in the OpenWebif screenshot show them both at 21:25 (but again with different end times). The end times aren't shown on the IceTV Web screenshot.
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

IanL-S
Master
Posts: 322
Joined: Mon Jun 27, 2016 15:11

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by IanL-S » Thu Mar 08, 2018 15:26

Peter I posted on the IceTV Forum as suggested. One thing I noticed on my quick check on the U4 was than the times fro none of the timers corresponded to times shown in the EPG. It took a chance on which timer was most accurate and deleted the others for the same program. There were no duplicate recordings.

The issue did not carry over to my T2's which had both Cold Case and Madam Secretary scheduled.

I noticed a comment in an earlier post about the possibility of a clash between an locally set auto timer update and icetv download. I think there may be a auto timer set for one program on the U4. Will see if deleting it solves the problem.

Ian
Enjoying an active retirement "playing" with my Toppys and now Beyonwiz.
T2, U4 and V2 controlled by IceTV
Various Toppys including TRF-2400, TRF-5300 and TF7100HDPVRt Plus
For help with your Toppy checkout the oztoppy forum and the oztoppy wiki.

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Thu Mar 08, 2018 16:57

IanL-S wrote:
Thu Mar 08, 2018 15:26
...
I noticed a comment in an earlier post about the possibility of a clash between an locally set auto timer update and icetv download. I think there may be a auto timer set for one program on the U4. Will see if deleting it solves the problem.
...

AutoTimer-generated timers should be ignored by IceTV altogether. Likewise, AutoTimer should ignore IceTV timers.

If you have an IceTV series recording and an AutoTimer set for the same series, you'll get duplicate recordings. But the timers generated by the AutoTimer shouldn't appear on the IceTV Web page.
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Grumpy_Geoff
Uber Wizard
Posts: 6490
Joined: Thu Mar 05, 2009 22:54
Location: Perth

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by Grumpy_Geoff » Sun Mar 18, 2018 14:36

prl wrote:
Wed Mar 07, 2018 12:58
My guess is that IceTV is sending out the new timer with a different IceTV timer id on it than the original. ...

Yep, I think you're correct in that this is an IceTV server issue.

I've just seen an example of something that may be related.
IceTV changed the program start times for 'Blindspot', from 23:30 to 22:30 and then back to 23:30.
EITs appeared to have changed.
It was in the last change that IceTV appeared to forget about the previous timer and created a new one instead.

Original timer -
Start 23:30, ice_timer_id 16379874719882831239

First change -
Program start now 22:30
Timer changed to 22:30 start ("Updated by Scheduler SERIES")
IceTV plugin on T4:
changes the existing timer -
sends delete to IceTV for timer 16379874719882831239
posts new timer notice to IceTV for start 22:30, Ice responds with new timer id 16380156062520837002

Second change -
Program start now back to 23:30
New timer created for start 23:30, new Ice timer 16380190280525328195 ("Created by Scheduler SERIES" -- note Created by, not Updated by)

Resulting in Ice timer id 16380156062520837002 from first change left on IceTV server and on PVR


In slightly more detail -

(i) Original timer -
Start of 23:30, ice_timer_id 16379874719882831239

(ii) First change (on Sat 09:27) -
EPG change, program start now 22:30, EIT 15510 (unknown if changed)
Timer changed to 22:30 start, EIT 15510 ("Updated by Scheduler SERIES")

Code: Select all

,"timers":[{"id":"16379874719882831239","device_id":"176230","channel_id":"2659","name":"Blindspot","show_id":"137702879","eit_id":"15510","start_time":"2018-03-18T14:30:00+00:00","duration_minutes":"60","action":"record","state":"waiting","message":"Updated by Scheduler SERIES","series_recording_id":"10973946","keyword_id":"0"}]}
IceTV plugin on T4:
changes the existing timer -

Code: Select all

{841}<  1873.089> [RecordTimer] record time changed, start prepare is now: Sun Mar 18 22:19:40 2018
sends delete to IceTV for timer 16379874719882831239
posts new timer notice to IceTV for start 22:30, Ice responds with new timer id 16380156062520837002
EIT value is 15510

Code: Select all

{815}<  1873.377> [IceTV] DELETE http://api.icetv.com.au/shows/timers/16379874719882831239?{snipped}
{815}<  1873.378> [IceTV] headers {snipped}
{815}<  1873.378> [IceTV] {}
{815}<  1873.379> [IceTV] 200 OK
{815}<  1873.380> [IceTV] headers {snipped}
{815}<  1873.381> [IceTV] 
{762}<  1873.719> [IceTV] POST http://api.icetv.com.au/shows/timers?{snipped}
{762}<  1873.720> [IceTV] headers {snipped}
{762}<  1873.720> [IceTV] {"name": "Blindspot", "eit_id": 15510, "start_time": "2018-03-18T14:30:00+00:00", "duration_minutes": 60, "channel_id": 2659, "state": "pending", "action": "record", "message": "Created by Beyonwiz T4", "device_id": 176230}
{762}<  1873.721> [IceTV] 201 Created
{762}<  1873.722> [IceTV] headers {snipped}
{762}<  1873.723> [IceTV] {"timers":[{"id":"16380156062520837002","device_id":"176230","channel_id":"2659","name":"Blindspot","show_id":"137702879","eit_id":"15510","start_time":"2018-03-18T14:30:00+00:00","duration_minutes":"60","action":"record","state":"pending","message":"Created by Beyonwiz T4","series_recording_id":"0","keyword_id":"0"}]}
{762}<  1873.723> 
(iii) Second change (on Sun 04:57) -
EPG change, program start now back to 23:30, EIT has changed to 16761
New timer created for start 23:30, EIT 16761, new Ice timer 16380190280525328195 ("Created by Scheduler SERIES" -- note Created by, not Updated by)

Code: Select all

,"timers":[{"id":"16380190280525328195","device_id":"176230","channel_id":"2659","name":"Blindspot","show_id":"137728788","eit_id":"16761","start_time":"2018-03-18T15:30:00+00:00","duration_minutes":"60","action":"record","state":"waiting","message":"Created by Scheduler SERIES","series_recording_id":"10973946","keyword_id":"0"}]}
IceTV plugin on T4:
creates the new timer 16380190280525328195 as requested, and informs Ice it's done -

Code: Select all

{762}< 72072.946> [RecordTimer] Record RecordTimerEntry(name=Blindspot, begin=Sun Mar 18 23:20:00 2018, end=Mon Mar 19 00:55:00 2018, serviceref=1:0:19:564:506:1013:EEEE0000:0:0:0:, justplay=False, isAutoTimer=False, ice_timer_id=16380190280525328195)
{841}< 72073.280> [IceTV] PUT http://api.icetv.com.au/shows/timers/16380190280525328195?{snipped}&application_version=20171208
{841}< 72073.281> [IceTV] headers {'Content-Length': '189', 'Accept-Encoding': 'gzip, deflate', 'Accept': 'application/json', 'User-Agent': 'SystemPlugins.IceTV/20171208 (Beyonwiz; T4)', 'Connection': 'keep-alive', 'Content-Type': 'application/json'}
{841}< 72073.281> [IceTV] {"timers": [{"eit_id": 16761, "start_time": "2018-03-18T15:30:00+00:00", "state": "pending", "duration_minutes": 60, "message": "Will record on Beyonwiz T4", "id": "16380190280525328195"}]}
{841}< 72073.282> [IceTV] 200 OK
{841}< 72073.283> [IceTV] headers {'Content-Length': '332', 'Access-Control-Allow-Headers': 'origin, content-type, accept', 'X-Powered-By': 'CppCMS/1.0.3', 'Set-Cookie': 'AWSELB=FF9FA59B0AA9FAB4E737D9FE7A7C22F11253580EC0D24ADC55CEE08267D3C43F5DA893040553F9688133D842341C470880B88B6909104AFA162DF6462193C0491CE12D1991;PATH=/;MAX-AGE=3600', 'Access-Control-Allow-Credentials': 'true', 'Server': 'nginx/1.10.2', 'Connection': 'keep-alive', 'Cache-control': 'no-cache="set-cookie"', 'Date': 'Sat, 17 Mar 2018 20:57:29 GMT', 'Access-Control-Allow-Origin': '*', 'Access-Control-Allow-Methods': 'GET, POST, PUT, DELETE', 'Content-Type': 'application/json; charset=utf-8'}
{841}< 72073.283> [IceTV] {"timers":[{"id":"16380190280525328195","device_id":"176230","channel_id":"2659","name":"Blindspot","show_id":"137728788","eit_id":"16761","start_time":"2018-03-18T15:30:00+00:00","duration_minutes":"60","action":"record","state":"pending","message":"Will record on Beyonwiz T4","series_recording_id":"10973946","keyword_id":"0"}]}
{841}< 72073.283>
It appears the IceTV server did nothing with ICE timer ID 16380156062520837002 from the first change.
This timer is left both on the PVR (named as 'Blindspot' with episode title 'Steve Jobs' [from replacement event 'Autopsy']), and on the IceTV server (named as 'Autopsy', episode title 'Steve Jobs').

The timers -

Code: Select all

<timer begin="1521382800" end="1521388500" serviceref="1:0:19:564:506:1013:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Blindspot" description="Steve Jobs" afterevent="auto" eit="16760" tags=
"" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="0" ice_timer_id="16380156062520837002">
<log code="15" time="1521250049">record time changed, start prepare is now: Sun Mar 18 22:19:40 2018</log>
</timer>
<timer begin="1521386400" end="1521392100" serviceref="1:0:19:564:506:1013:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Blindspot" description="Upside Down Craft" afterevent="auto" eit="16761
" tags="" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="0" ice_timer_id="16380190280525328195">
</timer>

Cheers,
Geoff
Last edited by Grumpy_Geoff on Mon May 14, 2018 09:06, edited 1 time in total.

prl
Wizard God
Posts: 32697
Joined: Tue Sep 04, 2007 13:49
Location: Canberra; Black Mountain Tower transmitters

Re: U4 - change in scheduled programs produces multiple timers for same event,

Post by prl » Sun Mar 18, 2018 14:44

I agree that it looks like a server-end issue, though it might still be something that the plugin isn't telling the server.

I suggest you try to get Daniel Hall @ IceTV to have a look at what you've dug out (if you haven't already).
Peter
T4 HDMI
U4, T4, T3, T2, V2 test/development machines
Sony BDV-9200W HT system
LG OLED55C9PTA 55" OLED TV

Post Reply

Return to “Ice TV”