242 replies to this topic

[paneologist]

also had this that morning:

2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [TIMER] stop recording on tuner: C
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eDVBServiceRecord] stop recording!
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] read got interrupted by signal, stop: 0
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: message repeated 1098 times: [ [eFilePushThreadRecorder] read got interrupted by signal, stop: 0]
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 100
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePush] SIGUSR1 received
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] read got interrupted by signal, stop: 1
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eDVBRecordFileThread] waiting for aio to complete
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eDVBRecordFileThread] buffer usage histogram (40 buffers of 188 kB)
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eDVBRecordFileThread]   0:     55
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eDVBRecordFileThread]   1:   5807
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eDVBRecordFileThread]   2:   5689
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 99
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 98
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 97
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 96
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 95
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 94
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 93
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePush] SIGUSR1 received
2023-08-17T03:35:00+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] THREAD STOP

 

 

hm.. just a few ideas to the topic problem:

-as a signal isn't received sometimes... I would check any code in use, if somewhere interrupts are being disabled for some reason, e.g. timing?

-or signal gets caught at another place...

-if the box was cheaper, I would also try a 1:1 copy on another box.

-what about different firmware revisions?

[Old Satterhand]

 

 

 

I really would like to have a working box and working recordings again.

 

Please try the following steps:

 

• delete epg.dat in the root of the HD.
• switch off the STB to prevent E2 saving a new epg.dat .
• Switch off half of your virtual tuners.
• Report the results

If you need more tuners during testing you can add one by one, until.....

 

didn't work. box got stuck twice.

 

I think that the problem I encountered is not the same.

Looks like mine has tot do with the size of epg.dat.

 

In fact, in my case E2 was not halted, but way to slow.

One command took a minute or so to be processed.

 

With 4 DVB-C tuners disabled, the size does not grow over 12 Mbyte, after more than a week.

 

Thanks for testing!

Edited by Old Satterhand, 17 August 2023 - 13:45.

[WanWizard]

hm.. just a few ideas to the topic problem:
-as a signal isn't received sometimes... I would check any code in use, if somewhere interrupts are being disabled for some reason, e.g. timing?
-or signal gets caught at another place...

 
That is indeed the current line of thought: something is blocking the signals from reaching the thread. Erik has promissed to look into this, this level of C++ is far above my pay-grade .
 
Lag seems to be an issue with all VU+ boxes, I notice that even on my Solo 4K, simply switching the box on or off using the remote, there is a 2-3 second gap between the power button on the box flashing and the display reacting or the TV being switched on or off by CEC.
 

-what about different firmware revisions?

 

What kind of firmware do you mean?

[paneologist]

What kind of firmware do you mean?

 

I think about any ASICs, microcontrollers/PROMs/PLDs/FPGAs - anything what's on the schematics (I didn't look into), that is pre-programmed

[WanWizard]

That hardly ever changes, very occasionally there is an update of the bootloader, but that's about it.

 

The last driver set for the Duo 4K SE is from october 2021 ( https://github.com/O...xy-vuduo4kse.bb ) so that is the same as in 8.3-release.

[Dimitrij]

WanWizard

 

Maybe build enigma2_vuduo4kse.ipk in [filepush] revert back to 2020-11-23 PR for test paneologist

Attached Files

•  filepush revert back to 2020-11-23.zip   4.77KB   3 downloads

Edited by Dimitrij, 18 August 2023 - 07:18.

[paneologist]

WanWizard

 

Maybe build enigma2_vuduo4kse.ipk in [filepush] revert back to 2020-11-23 PR for test paneologist

sounds like a good idea.

 

cause I am puzzled much more now. Despite of modified enigma2 binary, box got stuck this morning:

2023-08-18T05:15:30+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 211
2023-08-18T05:15:30+02:00 stb1.swabian.net enigma2: [gRC] main thread is non-idle! display spinner!
2023-08-18T05:15:30+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 210
[...]
2023-08-18T05:15:50+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 2
2023-08-18T05:15:51+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 1
2023-08-18T05:15:51+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] thread could not be stopped! Killed anyway.

maybe the fate is already sealed on spinner display?

 stb1debuglog7.txt   259.8KB   2 downloads

[WanWizard]

We've already stated we won't revert that code.

 

The spinner is a visual of the symptom, it pops up if the reactor loop doesn't get control back in time, which means some process is started by the loop which runs too long (or in a loop).

 

According to Erik, signals are deferred until the loop gets control back, so we assume at this moment that this "some process" is also the cause of the recording thread not stopping.

 

So both are a symptom of the same problem, they are not the problem in itself.

 

Now, the question is, what is running in Enigma on your box that does this.

 

I see in the log several times:

2023-08-18T05:07:25+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 250
2023-08-18T05:07:25+02:00 stb1.swabian.net enigma2: [eFilePush] SIGUSR1 received

which indicates again that signaling is blocked while that stop loop is running, and as soon as it is finished, the signal comes through immediately (as signals don't get lost, they can only be deferred by a block mask).
 

[WanWizard]

p..s that log clearly indicates it is not a bug in the thread code itself, as it works well several times. Until there is a moment something starts that never finishes...

 

I can reproduce that easily on my VU+ Solo 4K, using the bluetooth remote. Zap to a new channel, and immediately switch the box to standby using the remote: result is a spinner and a hanging box.
Problem is a timing issue between two pieces of code that run asynchronously. If one finishes before the second starts, the second goes into an endless loop, and the reactor loop never gets control back.

 

I'm thinking about a way to add debug logging to the reactor loop itself, so we can see exactly what is called when, and maybe that will tell us more.

[paneologist]

Still wondering, why the change with the kill still resulted in a stuck box.

I could start enigma2 with strace, to see what exactly happens at that time.... I think I did this kind of debugging a while ago on my xtrend stb. it handled the extra load quite well.

 

and in case of a stuck. processlist?

 

or is something unusual running in general? attached "ps -aux" output  psaux1.txt   9.89KB   1 downloads

what comes into my mind: nfsd, ntpd, minidlna, logger, syslog.

(and by the way, any possibility to stop smbd and nmbd from running? don't have a microsoft network. I use nfs for fie sharing, cups for printing...)

[WanWizard]

Because I think the recording thread is not the cause of the problem, it is a symptom that shows itself the moment something else is stuck.

 

The filepush threads run completely detached from the reactor mainloop (which is why signalling is used to stop them), so they can never be the cause of a spinner (the indicator the main loop is stuck).

 

And no, it is not something that runs as a linux process, it something run inside Enigma. Something (most likely a plugin) is activated, either via a callback of a timer somewhere, the mainloop calls the event, and the call never returns.

 

That is why I hope adding debugging to the mainloop itself might shed some light on what is exactly called when. I'm not sure if strace will show you details of what is going on in Python, it might be difficult to relate the C calls shown back to python code.

[Erik Slagter]

 

you may be right. and I crowed to soon.
It happened again. Just installed "enigma2-plugin-extensions-multirc", rebooted (unintentially while a recording was made), looked into openwebif, looked through timers and recordings and.. spinner.

 

Please disable automatic timeshift (which is also a recording), and see if that makes a difference.

 

I have a feeling that nobody here that don't experience this issue uses timeshift? @Abu, do you?

 

I am using it. And no problems.

[Erik Slagter]

Problem this

 

2023-08-08T10:19:04+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 74
2023-08-08T10:19:04+02:00 stb1.swabian.net enigma2: [gRC] main thread is non-idle! display spinner! ---->!!!!
2023-08-08T10:19:04+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] stopping thread: 73

 

safeguard = 0  Why???

not run kill();

 

2023-08-08T10:19:12+02:00 stb1.swabian.net enigma2: [eFilePushThreadRecorder] thread could not be stopped!

	if(safeguard > 0)
		kill();
	else
		eWarning("[eFilePushThreadRecorder] thread could not be stopped!");

original code

void eFilePushThreadRecorder::stop()
{
	static const struct timespec timespec_1 = { .tv_sec =  0, .tv_nsec = 1000000000 / 10 };
	int safeguard;

	if (m_stop == 1)
	{
		eDebug("[eFilePushThreadRecorder] requesting to stop thread but thread is already stopped");
		return;
	}

	m_stop = 1;

	for(safeguard = 100; safeguard > 0; safeguard--)
	{
		eDebug("[eFilePushThreadRecorder] stopping thread: %d", safeguard);
		sendSignal(SIGUSR1);

		nanosleep(&timespec_1, nullptr);

		if(m_stopped)
			break;
	}

	if(safeguard > 0)
		kill();
	else
		eWarning("[eFilePushThreadRecorder] thread could not be stopped!");

maybe...

+	kill();
-	if(safeguard > 0)
-		kill();
-	else
-		eWarning("[eFilePushThreadRecorder] thread could not be stopped!");
}

or

safeguard >= 1

 

Kill does not do what it suggests. Look at the code. It calls "join" the thread, which is not the same as killing it. You can't kill a thread.

 

Maybe the "nanosleep" is too small, not yielding the cpu to the thread to allow doing it's thing.

[Erik Slagter]

 

Need this

	for(safeguard = 100; safeguard > 0; safeguard--)
	{
		eDebug("[eFilePushThreadRecorder] stopping thread: %d", safeguard);
		sendSignal(SIGUSR1);

		nanosleep(&timespec_1, nullptr);

-		if(m_stopped)
+		if ((m_stopped) || (safeguard == 1))
			break;
	}

 

No, the safeguard counts from 100 to 1. As soon as safeguard == 0, the for condition fails (safeguard > 0) and loop breaks.

[Erik Slagter]

 

 

most times it happens when the box is in standby, running epgrefresh

 

Interesting...  In standby and with epgrefresh the box is tuning/playing services as far I know while not showing them. The big question for now is this a trigger/condition? I never use here epgrefresh, maybe that is also why I never get into this issue.

forget to mention, epgrefresh is set to use "fake recordings"

 

Maybe try option "PiP"?

[Erik Slagter]

I would say first confirm if it is really related to the fake recording alias dummy streaming of the epgrefresh plugin and if so resolved that. I think for now reverting is not an option as it worked as it for years. I never get the described interlock here, but I also never used epgrefresh.

The problem is that you cannot simply revert the code (using git):

- several commits are involved

- some of them already are reverts

- not all of it needs to be reverted

- all commit after this depend on this code/layout. So many hour happy conflict solving for the one who is brave 

[WanWizard]

Based on a suggestion from Erik, a new enigma version for test. This one has changes outside the thread in an attempt to make sure the SIGUSR1 arrives and is not blocked.

 

Attached Files

•  enigma2_3.9+git20836+ffab5b9-r0.0_vuduo4kse.ipk   5.58MB   2 downloads

[WanWizard]

btw, I tested extensively on my Solo 4K with EPGrefresh in fake recording mode, and couldn't reproduce the problem.

[littlesat]

Sounds we’re really try to target the cause instead of hiding symptoms. Thanks wanwizard and erik.

Edited by littlesat, 19 August 2023 - 05:58.

[Dimitrij]

 

        /* this works around the buggy Broadcom encoder that always returns even if there is no data */
        /* (works like O_NONBLOCK even when not opened as such), prevent idle waiting for the data */
        /* this won't ever hurt, because it will return immediately when there is data or an error condition */

void eFilePushThreadRecorder::thread()
{
#ifndef HAVE_HISILICON
	ignore_but_report_signals();
	hasStarted(); /* "start()" blocks until we get here */
#endif
	setIoPrio(IOPRIO_CLASS_RT, 7);
	eDebug("[eFilePushThreadRecorder] THREAD START");

#ifdef HAVE_HISILICON
	/* we set the signal to not restart syscalls, so we can detect our signal. */
	struct sigaction act;
	act.sa_handler = signal_handler; // no, SIG_IGN doesn't do it. we want to receive the -EINTR
	act.sa_flags = 0;
	sigaction(SIGUSR1, &act, 0);
	hasStarted();
#endif

	/* m_stop must be evaluated after each syscall */
	/* if it isn't, there's a chance of the thread becoming deadlocked when recordings are finishing */
	while (!m_stop)
	{
#ifndef HAVE_HISILICON
		/* this works around the buggy Broadcom encoder that always returns even if there is no data */
		/* (works like O_NONBLOCK even when not opened as such), prevent idle waiting for the data */
		/* this won't ever hurt, because it will return immediately when there is data or an error condition */

		struct pollfd pfd = { m_fd_source, POLLIN, 0 };
		poll(&pfd, 1, 100);
		/* Reminder: m_stop *must* be evaluated after each syscall. */
		if (m_stop)
			break;

		ssize_t bytes = ::read(m_fd_source, m_buffer, m_buffersize);
		/* And again: Check m_stop regardless of read success. */
		if (m_stop)
			break;
#else
		ssize_t bytes = ::read(m_fd_source, m_buffer, m_buffersize);
#endif
		if (bytes < 0)
		{
			bytes = 0;
#if HAVE_HISILICON
			/* Check m_stop after interrupted syscall. */
			if (m_stop) {
				break;
			}
#endif
			if (errno == EINTR || errno == EBUSY || errno == EAGAIN)
			{
#if HAVE_HISILICON
				usleep(100000);
#endif
				continue;
			}
			if (errno == EOVERFLOW)
			{
				eWarning("[eFilePushThreadRecorder] OVERFLOW while recording");
				++m_overflow_count;
				continue;
			}
			eDebug("[eFilePushThreadRecorder] *read error* (%m) - aborting thread because i don't know what else to do.");
			sendEvent(evtReadError);
			break;
		}

#ifdef SHOW_WRITE_TIME
		struct timeval starttime = {};
		struct timeval now = {};
		gettimeofday(&starttime, NULL);
#endif
		int w = writeData(bytes);
#ifdef SHOW_WRITE_TIME
		gettimeofday(&now, NULL);
		suseconds_t diff = (1000000 * (now.tv_sec - starttime.tv_sec)) + now.tv_usec - starttime.tv_usec;
		eDebug("[eFilePushThreadRecorder] write %d bytes time: %9u us", bytes, (unsigned int)diff);
#endif
		if (w < 0)
		{
			eWarning("[eFilePushThreadRecorder] WRITE ERROR, aborting thread: %m");
			sendEvent(evtWriteError);
			break;
		}
	}
	flush();
	sendEvent(evtStopped);
	eDebug("[eFilePushThreadRecorder] THREAD STOP");
}

void eFilePushThreadRecorder::start(int fd)
{
	m_fd_source = fd;
	m_stop = 0;
	run();
}

void eFilePushThreadRecorder::stop()
{
	/* if we aren't running, don't bother stopping. */
	if (m_stop == 1)
		return;
	m_stop = 1;
	eDebug("[eFilePushThreadRecorder] stopping thread."); /* just do it ONCE. it won't help to do this more than once. */
	sendSignal(SIGUSR1);
	kill();
}

errno == EAGAIN

			if (errno == EINTR || errno == EBUSY || errno == EAGAIN)
			{
#if HAVE_HISILICON
				usleep(100000);
#endif
				continue;

 

Edited by Dimitrij, 19 August 2023 - 08:43.