U4 didn't complete the shutdown to deep standby process

Moderators: Gully, peteru

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

U4 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Wed Jan 01, 2020 16:19

As per title.
U4 was in standby, recording. The UI shut down as per timer after event action. However the system didn't power down, the front panel was still showing the stale date/time from its last update as well as the usual icons.
The front panel power button didn't respond, nor did it recognise the remote's POWER toggle.
The network was shutdown as I couldn't ping the U4.
The U4 didn't start at its next scheduled time.

This same thing has happened a few times previously on our U4.

What is the significance, if any, of the absence of the below state -

Code: Select all

consoleFd 10
[MAIN] executing main
I notice they're usually reported on successful shut downs, but weren't in this failed shutdown case.

Failed shutdown -

Code: Select all

{7017}< 56429.929> [eInit] reached rl -1
xt stopped service 654
TuxTxt service started 654
TuxTxt running thread...(654)
TuxTxt stopped service 654
TuxTxt service started 654
TuxTxt running thread...(654)
TuxTxt stopped service 654
TuxTxt service started 654
TuxTxt running thread...(654)
TuxTxt stopped service 654
TuxTxt service started 654
TuxTxt running thread...(654)
TuxTxt stopped service 654

Successful shutdowns -
Example #1

Code: Select all

{846}< 14186.267> [eInit] reached rl -1
consoleFd 10
[MAIN] executing main
TuxTxt service started 654
TuxTxt running thread...(654)
TuxTxt stopped service 654
TuxTxt service started 909
TuxTxt running thread...(909)
TuxTxt stopped service 909
TuxTxt service started 242
...
Example #2

Code: Select all

{847}<  1009.426> [eInit] reached rl -1
consoleFd 10
[MAIN] executing main
TuxTxt service started 909
TuxTxt running thread...(909)
TuxTxt stopped service 909
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
...
Example #3

Code: Select all

{884}<  6917.314> [eInit] reached rl -1
consoleFd 10
[MAIN] executing main
TuxTxt service started 909
TuxTxt running thread...(909)
TuxTxt stopped service 909
TuxTxt service started 909
TuxTxt running thread...(909)
TuxTxt stopped service 909

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

Re: U4 didn't complete the shutdown to deep standby process

Post by prl » Wed Jan 01, 2020 17:31

Grumpy_Geoff wrote:
Wed Jan 01, 2020 16:19
Failed shutdown -

Code: Select all

{7017}< 56429.929> [eInit] reached rl -1
xt stopped service 654
TuxTxt service started 654
...

Is the missing "TuxT" at the beginning of the line just a copy/paste slip?
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 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Wed Jan 01, 2020 18:18

prl wrote:
Wed Jan 01, 2020 17:31
Grumpy_Geoff wrote:
Wed Jan 01, 2020 16:19
Failed shutdown -

Code: Select all

{7017}< 56429.929> [eInit] reached rl -1
xt stopped service 654
TuxTxt service started 654
...

Is the missing "TuxT" at the beginning of the line just a copy/paste slip?

No, that's how it is - appears to be a write from two threads, one over the top of the other.
So, the absent lines could have been gazumped - but both lines?

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

Re: U4 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Wed Jan 01, 2020 18:56

I should add this also happens on occasion to our T2. I've not experienced it on the T4, but it doesn't have any USB non-storage devices connected, whereas the other two do (USB tuners).

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

Re: U4 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Mon Jan 27, 2020 15:01

Another failed shutdown occured yesterday. This time the debug log had the entries that were missing from the previous failure -

Code: Select all

consoleFd 10
[MAIN] executing main
Unit was in standby prior to shut down via Power Timer. Same symptoms as previous - front panel in standby mode, stale clock, other indicators frozen. Ethernet lights still blinking.
The front panel power button didn't respond, nor did it recognise the remote's POWER toggle.
The U4 didn't start at its next scheduled time.

My suspect is still the USB drivers (USB tuner attached).

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

Re: U4 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Tue Jan 28, 2020 17:27

Well shove me sideways up a dead bear's bum. My T4 just decided it didn't want to finish shutting down; there goes my "USB theory".
The network ports are still blinking, but it can't be pinged. TV screen still has 'Your Beyonwiz T4 is shutting down.". I can't report on the front panel status as it got dislodged when something fell on the front edge of the T4, so it needs a visit to Dr. Warkus' surgery.

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

Re: U4 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Mon Mar 02, 2020 22:18

Once again the U4 didn't correctly complete its shut down processes and was left hanging and then failed to start up as per its schedule.
The front panel clock showed the same time as the debug log reported for the current linux time.
:cry:

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

Re: U4 didn't complete the shutdown to deep standby process

Post by prl » Tue Mar 03, 2020 11:15

I'm a bit unclear about the order here. Were you watching the U4 front panel at the time it shut down, or did it stay stuck that way?

Updating the front panel clock will stop as soon as the main dispatch loop in enigma2 stops running (or is blocked from running, e.g. by enigma2 wandering off into an infinite loop).

The front panel display should be cleared at about the same time as the "is shutting down" message appears on the TV. But I'm not sure how the shutdown would be initiated if the dispatch loop is wedged (unless it got wedged sometime between the "is shutting down" message and clearing the front panel).
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 didn't complete the shutdown to deep standby process

Post by Grumpy_Geoff » Tue Mar 03, 2020 11:26

prl wrote:
Tue Mar 03, 2020 11:15
I'm a bit unclear about the order here. Were you watching the U4 front panel at the time it shut down, or did it stay stuck that way?
I wasn't watching it. It stayed stuck at "12:19" though, as per the enigma2 shutdown.
prl wrote:
Tue Mar 03, 2020 11:15
Updating the front panel clock will stop as soon as the main dispatch loop in enigma2 stops running (or is blocked from running, e.g. by enigma2 wandering off into an infinite loop).

The front panel display should be cleared at about the same time as the "is shutting down" message appears on the TV. But I'm not sure how the shutdown would be initiated if the dispatch loop is wedged (unless it got wedged sometime between the "is shutting down" message and clearing the front panel).

As far as I know, enigma2 did shut down -

Code: Select all

{1047}< 25288.266> [eEPGCache] abort non avail schedule other reading
{1047}< 25288.275> [eEPGCache] nownext finished(1583122739)
{1047}< 25296.011> [eEPGCache] schedule finished(1583122747)
{1047}< 25296.011> [eEPGCache] next update in 5 min
{838}< 25314.897> [InputHotplug] connectionLost? [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion: Connection lost.
]{838}< 25314.897> 
{838}< 25314.901> dvb time sync disabled... so set RTC now to current linux time! Mon 02 Mar 2020 12:19
{838}< 25314.902> set wakeup time to Mon 02 Mar 2020 13:00
{838}< 25314.910> PowerTimerWakeupAuto True
{838}< 25314.910> [eDVBServicePlay] [Timeshift] stopTimeshift
{838}< 25314.910> [eDVBCAService] free slot 0 demux 0 for service 1:0:19:564:506:1013:EEEE0000:0:0:0:
{838}< 25314.910> [eDVBCAService] free service 1:0:19:564:506:1013:EEEE0000:0:0:0:
{838}< 25314.915> [eTSMPEGDecoder] decoder state: play, vpid=ffffffff, apid=ffffffff
{838}< 25314.915> [eDVBPCR0] DEMUX_STOP ok
{838}< 25314.919> [eDVBPCR0] destroy
{838}< 25314.919> [eDVBVideo0] DEMUX_STOP  ok
{838}< 25314.920> [eDVBVideo0] VIDEO_STOP ok
{838}< 25314.920> [eDVBVideo0] VIDEO_CLEAR_BUFFER ok
{838}< 25314.920> [eDVBVideo0] destroy
{838}< 25314.920> [eDVBAudio0] AUDIO_STOP ok
{838}< 25314.920> [eDVBAudio0] DEMUX_STOP ok
{838}< 25314.921> [eDVBAudio0] AUDIO_CLEAR_BUFFER ok
{838}< 25314.921> [eDVBAudio0] AUDIO_CONTINUE ok
{838}< 25314.921> [eDVBAudio0] destroy
{838}< 25314.921> [eDVBText0] DEMUX_STOP ok
{838}< 25314.921> [eDVBText0] destroy
{838}< 25314.922> [eDVBResourceManager] start release channel timer
{838}< 25315.004> [AutoTimer] No changes in configuration, won't parse
{838}< 25315.031> [eDVBDB] ---- saving lame channel db
{838}< 25315.032> [eDVBDB] saved 6 channels and 58 services!
{838}< 25315.057> [eDVBResourceManager] release cached channel (timer timeout)
{838}< 25315.057> [eDVBLocalTimerHandler] remove channel 0x124be18
{838}< 25315.057> [EPGC] remove channel 0x124be18
{838}< 25315.058> [eDVBResourceManager] stop release channel timer
{838}< 25315.153> [eDVBLocalTimeHandler] set RTC to previous valid time
{838}< 25315.153> [eDVBLocalTimerHandler] set RTC Time
{838}< 25315.154> [eInit] - (41) Stream server
{838}< 25315.154> [eInit] - (41) Encoders
{838}< 25315.154> [eInit] - (41) eServiceFactoryDVB
{838}< 25315.154> [eInit] - (41) eServiceFactoryFS
{838}< 25315.154> [eInit] - (41) eServiceFactoryMP3
{838}< 25315.154> [eInit] - (41) eServiceFactoryM2TS
{838}< 25315.154> [eInit] - (41) eServiceFactoryHDMI
{838}< 25315.154> [eInit] - (41) eServiceFactoryTS
{838}< 25315.154> [eInit] - (41) eServiceFactoryWebTS
{838}< 25315.154> [eInit] - (41) eServiceFactoryDVD
{838}< 25315.154> [eInit] - (40) eServiceCenter
{838}< 25315.154> [eInit] - (35) CA handler
{838}< 25315.154> [eInit] - (35) CI Slots
{838}< 25315.154> [eInit] - (30) eActionMap
{838}< 25315.155> [eInit] - (22) Hdmi CEC driver
{838}< 25315.155> [eInit] - (21) input device driver
{838}< 25315.207> [eInit] - (20) AVSwitch Driver
{838}< 25315.207> [eInit] - (20) misc options
{838}< 25315.207> [eInit] - (20) RC Input layer
{838}< 25315.207> [eInit] - (20) UHF Modulator
{838}< 25315.207> [eInit] - (20) DVB-CI UI
{838}< 25315.207> [eInit] - (15) eWindowStyleManager
{838}< 25315.207> [eInit] - (10) gRC
{838}< 25315.207> [gRC] waiting for gRC thread shutdown
{838}< 25315.207> [gRC] thread has finished
{838}< 25315.207> [eInit] - (9) Font Render Class
{838}< 25315.207> [eInit] - (9) gLCD
{838}< 25315.207> [eInit] - (9) GFBDC
{838}< 25315.211> [eInit] - (8) graphics acceleration manager
{838}< 25315.211> [eInit] - (5) Tuxtxt
{838}< 25315.211> [eInit] - (1) Background File Eraser
{838}< 25315.211> [eInit] reached rl -1
ead...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
TuxTxt running thread...(02b)
TuxTxt stopped service 2b
TuxTxt service started 242
TuxTxt running thread...(242)
TuxTxt stopped service 242
TuxTxt service started 644
TuxTxt running thread...(644)
TuxTxt stopped service 644
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
TuxTxt running thread...(02b)
TuxTxt stopped service 2b
TuxTxt service started 242
TuxTxt running thread...(242)
TuxTxt stopped service 242
TuxTxt service started 644
TuxTxt running thread...(644)
TuxTxt stopped service 644
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
TuxTxt running thread...(02b)
TuxTxt stopped service 2b
TuxTxt service started 242
TuxTxt running thread...(242)
TuxTxt stopped service 242
TuxTxt service started 644
TuxTxt running thread...(644)
TuxTxt stopped service 644
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
TuxTxt running thread...(02b)
TuxTxt stopped service 2b
TuxTxt service started 242
TuxTxt running thread...(242)
TuxTxt stopped service 242
TuxTxt service started 644
TuxTxt running thread...(644)
TuxTxt stopped service 644
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
TuxTxt running thread...(02b)
TuxTxt stopped service 2b
TuxTxt service started 242
TuxTxt running thread...(242)
TuxTxt stopped service 242
TuxTxt service started 644
TuxTxt running thread...(644)
TuxTxt stopped service 644
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 23f
TuxTxt running thread...(23f)
TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
TuxTxt stopped service 912
TuxTxt service started 2b
TuxTxt running thread...(02b)
TuxTxt stopped service 2b
TuxTxt service started 242
TuxTxt running thread...(242)
TuxTxt stopped service 242
TuxTxt service started 644
TuxTxt running thread...(644)
TuxTxt stopped service 644

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

Re: U4 didn't complete the shutdown to deep standby process

Post by prl » Tue Mar 03, 2020 14:52

Grumpy_Geoff wrote:
Tue Mar 03, 2020 11:26
As far as I know, enigma2 did shut down -

Code: Select all

TuxTxt stopped service 23f
TuxTxt service started 912
TuxTxt running thread...(912)
...

Those messages all come out of /usr/lib/libtuxtxt.so.0, which is called by enigma2, so perhaps it hasn't. In fact, the log seems consistent with an infinite loop in enigma2 as it shuts down.

TuxTxt appears to handle Teletext, possibly filtering it from the broadcast stream, but I haven't dug into it much. The interface to it in enigma2 is quite small (in components/tuxtxtapp.{h,cpp} & dvb/decoder.cpp).
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 “Bug Reporting and Feature Requests”