interesting issue - box hangs during stand-by

[mateoosh]

Hi,

Since upgrade to 2.3 kernel 3.11 I'm experiencing following issue: every 3-4 days box hangs (with spinner rotating) during stand-by. I'm able to revive the box by restarting enigma2 process. Interesting is, that everytime when box is "frozen" the time at display shows Sun May 15 04:18:11

Because it happened several times already, I turned on the debug logs, and it seems, that 'hanging' is potentially caused by the "time warp" mentioned above.

Temporarily I changed time sync from transponder time to NTP and I'll see if it helps.

I have 2 other receivers, genuine Dreambox 500HD running latest iCVS image with GP3 (kernel 2.6.18) and Globo 9500 running IPbox9500 Linux/enigma port. Both are connected to same dish (quad monoblock LNB), time sync is set to transponder time. No issues there.

Here's small part of the log (whole log have over 1.4 GB!!!)


eHdmiCEC: received message
[EPGC] 4552023 bytes for cache used
eHdmiCEC: received message
eHdmiCEC: received message
[EPGC] 4552023 bytes for cache used
It's now Sat Jan 21 01:54:14 2012
[timer.py] next activation: Sat Jan 21 01:55:54 2012 (in 99998 ms)
It's now Sat Jan 21 01:54:22 2012
next real activation is Sat Jan 21 01:56:40 2012
[timer.py] next activation: Sat Jan 21 01:56:02 2012 (in 99997 ms)
eHdmiCEC: received message
eHdmiCEC: received message
[EPGC] 4546585 bytes for cache used
eHdmiCEC: received message
It's now Sat Jan 21 01:55:54 2012
[timer.py] next activation: Sat Jan 21 01:57:34 2012 (in 99997 ms)
It's now Sat Jan 21 01:56:02 2012
[timer.py] next activation: Sat Jan 21 01:56:40 2012 (in 37997 ms)
eHdmiCEC: received message
[EPGC] 4546585 bytes for cache used
eHdmiCEC: received message
It's now Sat Jan 21 01:56:40 2012
[TIMER] activating state 1
begin_date: 20120121 0157
service_name: SCI FI
name: Gwiezdne wrota: Atlantyda - odc. 17.
description: tytuł odcinka: Letters from PegasusTo najnowszy serial bazujący na tematyce znanego cyklu "Gwiezdne Wrota" SG-1. Opowiada doświadczeniach o całkiem nowych bohaterów w świecie Gwiezdnych Wrót. Akcja toczy się już po przygodach grupy SG-1 w odległej galaktyce
[TIMER] Filename calculated as: '/hdd/movie/20120121 0157 - SCI FI - Gwiezdne wrota_ Atlantyda - odc_ 17_'
[TIMER] Found enough free space to record
recording service: <enigma.eServiceReference; proxy of <Swig Object of type 'eServiceReference *' at 0x6a91a460> >
[add callback]
allocate channel.. 1fa4:013e
opening frontend 0
FE_ENABLE_HIGH_LNB_VOLTAGE: Operation not supported
(0)tune
RotorCmd ffffffff, lastRotorCmd ffffffff
prepare_sat System 0 Freq 12322000 Pol 0 SR 27500000 INV 2 FEC 3 orbpos 130 system 0 modulation 1 pilot 2, rolloff 0
tuning to 1722 mhz
OURSTATE: tuning
allocate Channel: res 0
[eDVBCIInterfaces] addPMTHandler 1:0:1:3A36:1FA4:13E:820000:0:0:0:
allocate demux
query epg event id 10017
[EPGC] event 2721 not found in epgcache
query stime 1:57:0, etime 3:5:0, qtime 2:31:0
found event.. store to disc
[TIMER] prepare ok, waiting for begin
[timer.py] next activation: Sat Jan 21 01:57:00 2012 (in 19949 ms)
[SEC] set static current limiting
set sequence pos 3
set sequence pos 4
[SEC] setVoltage 2
FE_ENABLE_HIGH_LNB_VOLTAGE: Operation not supported
[SEC] sleep 200ms
[SEC] invalidate current switch params
[SEC] sendDiseqc: e00000(DiSEqC reset)
[SEC] sleep 50ms
[SEC] sendDiseqc: e00003(DiSEqC peripherial power on)
[SEC] sleep 150ms
[SEC] sendDiseqc: e01038f3
[SEC] sleep 50ms
set sequence pos 3
[SEC] setTone 1
[SEC] sleep 10ms
[SEC] update current switch params
[SEC] startTuneTimeout 5000
[SEC] setFrontend 1
setting frontend 0
[SEC] sleep 500ms
(0)fe event: status 0, inversion off, m_tuning 1
(0)fe event: status 1f, inversion off, m_tuning 2
OURSTATE: ok
[eDVBLocalTimerHandler] channel 0x73aacf90 running
no version filtering
0014: 70 00 00 00 00 00
mask: fc 00 00 00 00 00
mode: 00 00 00 00 00 00
[eEPGCache] channel 0x73aacf90 running
stop release channel timer
[EPGC] next update in 2 sec
RECORD service event 6
tuned..
no version filtering
0012: 4e 3a 36 00 00 00
mask: ff ff ff 00 00 00
mode: 00 00 00 00 00 00
[Trashcan] gotRecordEvent <enigma.iRecordableServicePtr; proxy of <Swig Object of type 'ePtr< iRecordableService > *' at 0x6a91aa80> > 2
[TIMER] record event 2
ok ... now we start!!
no version filtering
0000: 00 00 00 00 00 00
mask: ff 00 00 00 00 00
mode: 00 00 00 00 00 00
RECORD service event 5
[Trashcan] gotRecordEvent <enigma.iRecordableServicePtr; proxy of <Swig Object of type 'ePtr< iRecordableService > *' at 0x6a91a2e0> > 6
[TIMER] record event 6
+ 1/1 TID 00
done!
PATready
use pmtpid 0141 for service_id 3a36
no version filtering
0141: 02 3a 36 00 00 00
mask: ff ff ff 00 00 00
mode: 00 00 00 00 00 00
doing version filtering
0000: 00 00 00 1b 00 00
mask: ff 00 00 3f 00 00
mode: 00 00 00 3e 00 00
+ 1/1 TID 02
done!
RECORD service event 5
[Trashcan] gotRecordEvent <enigma.iRecordableServicePtr; proxy of <Swig Object of type 'ePtr< iRecordableService > *' at 0x6a91ac20> > 6
[TIMER] record event 6
[eDVBCAService] new service 1:0:1:3A36:1FA4:13E:820000:0:0:0:
[eDVBCAService] add demux 0 to slot 0 service 1:0:1:3A36:1FA4:13E:820000:0:0:0:
[eDVBCIInterfaces] gotPMT
demux 0 mask 01 prevhash 00000000
doing version filtering
0141: 02 3a 36 03 00 00
mask: ff ff ff 3f 00 00
mode: 00 00 00 3e 00 00
sdt update done!
[SEC] set dynamic current limiting
[EPGC] start caching events(1327107402)
timeout 0012!
[EPGC] abort non avail netmed schedule reading
[EPGC] abort non avail netmed schedule other reading
[EPGC] abort non avail FreeSat schedule_other reading
[EPGC] abort non avail viasat reading
[EPGC] nownext finished(1327107411)
[EPGC] schedule finished(1327107412)
[eDVBLocalTimerHandler] diff is -21681529
[eDVBLocalTimerHandler] we have correction 0
[eDVBLocalTimerHandler] diff after add correction is -21681529
[eDVBLocalTimerHandler] use stored correction(<5 min)
[eDVBLocalTimerHandler] update RTC
[eDVBLocalTimerHandler] time update to 04:18:05
[eDVBLocalTimerHandler] m_time_difference is -21681529
[eDVBLocalTimerHandler] set Linux Time
[EPGC] 4553752 bytes for cache used
[timer.py] timewarp - re-evaluating all processed timers.
It's now Sun May 15 04:18:11 2011
next real activation is Fri Jan 20 01:56:40 2012
[timer.py] next activation: Sun May 15 04:19:51 2011 (in 99995 ms)
eHdmiCEC: received message
[Trashcan] /media/net/wd/movie/.Trash: bytesToRemove -73688940544
[Trashcan] /media/net/wd/movie/.Trash: Bytes to remove: -73688940544
[Trashcan] /media/net/wd/movie/.Trash: Size now: 1536991929
[Trashcan] /media/net/wd/movie/.Trash: Size now: 1536991929
job Components.Task.Job name=Cleaning Trashes #tasks=1 completed with [] in None
Traceback (most recent call last):
File "/usr/lib/enigma2/python/mytest.py", line 619, in <module>
runScreenTest()
File "/usr/lib/enigma2/python/mytest.py", line 502, in runScreenTest
runReactor()
File "/usr/lib/enigma2/python/mytest.py", line 91, in runReactor
reactor.run(installSignalHandlers=False)
File "/usr/lib/python2.6/site-packages/twisted/internet/base.py", line 1166, in run

--- <exception caught here> ---
File "/usr/lib/python2.6/site-packages/twisted/internet/base.py", line 1178, in mainLoop

File "/usr/lib/enigma2/python/e2reactor.py", line 158, in doPoll

exceptions.OverflowError: long int too large to convert to int

Any hints ?

Matt.

[cartman11]

I have been having the same issues sice 2.3 update, but did a full CLEAN install yesterday dont use any old setting do a new rescan and box is running like a dream now!!
Got to be worth a try! Good luck :D

[mateoosh]

hmm, maybe you're right. But I did clean install, after that only uploaded my channel list. Maybe here's the reason. Anyway, will see if NTP-timesynchronization helps.

[Rob van der Does]

Here's small part of the log (whole log have over 1.4 GB!!!)
Any hints ?

Only one: set debug log size to the default 4MB.

[mateoosh]

Only one: set debug log size to the default 4MB.

no no - I meant "any hints regarding box-hanging issue ?" ...

[Rob van der Does]

Only one: set debug log size to the default 4MB.

no no - I meant "any hints regarding box-hanging issue ?" ...
LOL, yes clear. But it makes debuglogs readable.