[ViX_Misc] TimerSanityCheck can report a failure when it should be OK

[ccs]

If I try with 4 tuners enabled.....

timer1, timer2, and timer3 all set to 14:00->18:00
timer4 set to 15:00->16:00
timer5 set to 17:00->17:30, I get sanity error conflicts on timer1/timer2/timer3, (all 3 are flagged as conflicts).

Not sure it this proves anything, but if timer3 is set to 15:00->16:00 it works ok....

timer1 and timer2 both set to 14:00->18:00
timer3 and timer4 both set to 15:00->16:00
timer5 set to 17:00->17:30, works ok.

 

[birdman]

if you run the build process again it will just update e2

It didn't when I tried it - hence the question.

See #12 in this thread.

 

[birdman]

Not sure it this proves anything, but if timer3 is set to 15:00->16:00 it works ok....

timer1 and timer2 both set to 14:00->18:00
timer3 and timer4 both set to 15:00->16:00
timer5 set to 17:00->17:30, works ok.

Sort of fits with what is in my mind.

If a timer starts and takes the last tuner, then it stops and another recording comes along to take that last tuner (as the others are still occupied with what was there for the first timer) then a conflict is signalled.

Mind you, this is all in the "simulate" code. Not sure what happens if you let the timers actually run in this state (and I can get them into "all active, but conflict reported" by changing the start time of one to allow them all, then changing it back).
But now is not the time for me to test it (lots of real timers coming up).

 

[rossi2000]

It didn't when I tried it - hence the question.

See #12 in this thread.

then you will have to explain to me how your attempting to do it.
as always on a rebuild if e2 has been updated, it gets updated, you must be doing something wrong.

 

[birdman]

you must be doing something wrong.

That's what I suspect..

I use a script which does:

git clone git://github.com/oe-alliance/build-enviroment.git oe-alliance
git clone git://github.com/OpenViX/enigma2.git ssh-enigma2

It then runs (for my config)

cd oe-alliance
MACHINE=mbtwin DISTRO=openvix make update
cd -
cd ssh-enigma2
git pull --ff-only || git pull --rebase

to populate things and finally

cd oe-alliance
MACHINE=mbtwin DISTRO=openvix make image

to create a full OpenVix image. Along the way it has built the enigma2 executable, which is all I'm actually interested in.

But if I then edit servicedvbrecord.cpp (which is in oe-alliance/builds/openvix/release/inihdx/tmp/work/mbtwin-oe-linux/enigma2/enigma2-5.1+gitAUTOINC+a33e2d4525-r2/package/usr/src/debug/enigma2/enigma2-5.1+gitAUTOINC+a33e2d4525-r2/git/lib/service/) and run the make image again, it doesn't rebuild enigma2.
It doesn't rebuild it if I edit the servicedvbrecord.cpp in ssh-enigma2/lib/service either.

 

[ccs]

I've set the conditions up again and added code to see what fakeRecService.start(True) is actually returning.

The answer is -6.

I've had a look at the code in eDVBServiceRecord::start() and can't see anything that would do that (only -1, -2, -3 and -4 are defined in the enums). Hmmmm......

I've found another reference to the -6 result code on OpenPLi......

http://forums.openpli.org/topic/23062-timer-bug/?view=findpost&p=500533

 

[birdman]

I've figured out where to make the changes so that all new timers (anything added to the timer_list) get added sorted by a primary key of the start time and a secondary one of the end time.
It replaces insort() calls with an append and keyed sort (of the start and stop times).

Patches are available under the Timers-EndSort at:

http://birdman.dynalias.org/OpenVix/

Which have resulted in a few unexpected failures.

I've had two crashes, with

Traceback (most recent call last):
  File "/usr/lib/enigma2/python/timer.py", line 250, in calcNextActivation
    self.processActivation()
  File "/usr/lib/enigma2/python/timer.py", line 323, in processActivation
    self.doActivate(self.timer_list[0])
  File "/usr/lib/enigma2/python/RecordTimer.py", line 848, in doActivate
    if w.activate():
  File "/usr/lib/enigma2/python/RecordTimer.py", line 545, in activate
    if (abs(NavigationInstance.instance.RecordTimer.getNextRecordingTime() - time()) <= 900 or abs(NavigationInstance.instance.RecordTimer.getNextZapTime() - time()) <= 900) or NavigationInstance.instance.RecordTimer.getStillRecording():
  File "/usr/lib/enigma2/python/RecordTimer.py", line 1011, in getStillRecording
    if timer.isStillRecording:
AttributeError: 'RecordTimerEntry' object has no attribute 'isStillRecording'
<  2596.449457> [ePyObject] (CallObject(<bound method RecordTimer.calcNextActivation of <RecordTimer.RecordTimer instance at 0x724900f8>>,()) failed)
]]>

Both were for timers that woke the box up, ran in Standby and tried to go to Deep Standby.

I also had two recordings consecutive recordings on the same channel which, instead of running on two tuners with an overlap (there were no other timers at the time) ran consecutively on one tuner - the second starting up as soon as the first completed.
So I've reverted my code....

Still trying to figure out how to build a version of enigma2 I can use for debugging.....

 

[ccs]

I also had two recordings consecutive recordings on the same channel which, instead of running on two tuners with an overlap (there were no other timers at the time) ran consecutively on one tuner - the second starting up as soon as the first completed.

Wouldn't it normally record the 2 programmes using the same tuner (and with overlap)?

What you saw should only happen if only one tuner is available to record consecutive programmes and they are on different channels (mux's).

.... and aren't there issues doing this anyway?

I must say that this does surprise me.

Does this mean that a box with a single tuner can't record consecutive programmes (one ends when the other one starts, no padding) on different mux's (or whatever the terminology is), without a clash being generated?

Yes, that is what it means.

 

[birdman]

Wouldn't it normally record the 2 programmes using the same tuner (and with overlap)?

What you saw should only happen if only one tuner is available to record consecutive programmes and they are on different channels (mux's).

.... and aren't there issues doing this anyway?

Precisely. Which in itself is odd (it really did switch on the second recording ~2s after stopping the first). All my added code did was to sort the programmes based on end time iff the start time was the same. So it shouldn't have affected this anyway. Perhaps it didn't and the oddity would have happened anyway, but since the problem the code was added for isn't specific to timers with equal starting times anyway, I decided I might as well remove it.

 

[birdman]

Well, I appear to have found a way to rebuild enigma2 quickly.

The front-end script to bitbake I have builds everything in the entire OpenVix image. It ends up with the image and a complete set of *.ipk files, but deletes all intermediate files. So not much use for debugging.

I do have a Debian mips system running (as a qemu chroot environment on a x64 VirtualBox VM system) so tried building it on that. Eventually I found the right files under the bitbake build to figure out what options to give to configure, and also installed of the *.ipk files for missing/iupdated packages c.f. the Debian mips setup (just copied all of the package files into place by hand - I have a copy of the original chroot environment to go back to at the end).
Running with those configure options (I'd tried some others while searching, but couldn't get the resulting image to run) results in an image which, although a little larger than the standard enigma2 image (after stripping), does actually run.

So it looks as though I have a a working (albeit unconventional) debugging environment.

Just noticed a new version of OpenVix (034) is out, so I'm going to upgrade to that, then recreate my debug environment from scratch using that, and make tidier notes along the way.

 

[abu baniaz]

......Just noticed a new version of OpenVix (034) is out.

035 is being built.

 

[birdman]

035 is being built.

So I now notice - and this is what I'd downloaded before updating to 034. I'm now on 035 and the build has just been started - I'm off to the gym while it runs....

 

[birdman]

I can now run debugging versions of enigma2.

In the process of checking that an eDebug statement got to the log file I noticed this:

[TimerSanityCheck] Possible Bug: unknown Conflict!

and it turns out I've been getting this for 5 days. The first entry is in the last log before the [TimerSanityCheck] tag was added to that text.

 

[birdman]

At least I now know what the -6 error is:

errAllSourcesBusy

returned by allocateFrontend in dvb.cpp.
Now I "just" need to know why it's losing track of things, so need to find out how it de-allocates channels (done it once, but didn't make notes...). It seems to reckon it has a slot in use when there are no recordings taking place (1 in use - add another, remove 2, still reckons 1 in use, but no active recordings at that point...).

 

[birdman]

I haven't found the cause, but I'm getting information.
I've also found a bug/mis-feature in the process.

At the moment, when the box starts up each timer, as it gets added to the timer list, gets run through the TimerSanityCheck, where it gets checked against all timers currently on the list for unhandleable tuner conflicts.
Nothing wrong with that, apart from the fact that all completed timers are run though the same code, as when they first get added at boot time all timers have a state of StateWaiting (0).
So all completed timers (which come at the end of the list) get checked against all waiting timers.

I've added code to TimerSanityCheck.py (~line 75) to ignore timers whose end time has already passed.
It might make more sense to set their state to StateEnded as they are read in, but that is all done in resetState(), which does other things and it wasn't clear to me whether this would affect other parts of the code (such as discarding them completely when read in rather than after the configured time).

##################################################################################
# process the new timer
                self.rep_eventlist = []
                self.nrep_eventlist = []
                if ext_timer != 1:
                        self.newtimer = ext_timer

[COLOR=#ff0000]#GML - A timer which has already ended (happens during start-up check) can't clash!!
                from time import time
                if (self.newtimer is not None) and (self.newtimer.end < time()):
                        return True[/COLOR]

 

[birdman]

As for the actual bug.

For some reason my box decided this evening to start reporting a clash on Saturday evening (again) for timers that have been in place, untouched, all week without any such reporting.
I can see that it has 1 of 2 tuners in use, and adds a (simulated) timer.
It then removes two recordings, but neither of these ends up calling dec_use() (which it should) .

However, while checking that, I noticed that I'd forgotten to add the current (simulated) recording count as they were removed. So I added that line and the problem has gone away (dec_use() is now being called)!

Commenting out that line (it's in python code) doesn't make it come back either!?

However, the dec_use() call is in a destructor, so I'm wondering whether there is an issue with when an object gets destroyed, involving how different thread run?

 

[birdman]

However, the dec_use() call is in a destructor, so I'm wondering whether there is an issue with when an object gets destroyed, involving how different thread run?

Slow "progress".

It's definitely to do with when the destructor gets run. I can't find any evidence of threads being involved, but if I add a 1s delay after removing each check timer from the list (it then takes several minutes to get the box to start) I still end up with the same clash.
(And without this I can get a recording this evening and one next morning to "share" a channel, because the destructor is late so the channel is still marked as in use...)

The services added to the list do keep their own reference count (of something) using AddRef and Remove. Hmmm.....more work yet.

 

[Huevos]

Is this an INI driver bug?

 

[birdman]

Is this an INI driver bug?

I doubt it. It's a generic problem. See http://www.world-of-satellite.com/s...t-should-be-OK&p=388678&viewfull=1#post388678

I can't see the code getting near any drivers, as it isn't doing anything real to any hardware when it goes wrong - it's simulating everything.

 

[birdman]

I *might* have solved it!!!!

It's sufficiently obscure to be the actual problem, and fixing it does end up with a "missing" destructor running at the same time that it should run (based on adding timers in a way that doesn't produce clashes).

Just need to do some more testing - and at the moment I've have imminent recordings.

Although the issue is about reference counts, the bug (and hence fix) is in the TimerSanityCheck.py code....