[VU+ Solo4K] Write error that is not write error

[B-N]

Odd to be hoping for something to break.

That is true But as an old programmer I believe that a bug that shows itself is better than one that is hiding.

And my wish came trough this morning :-/ Your SIGUSR1 handler seem to be in place but does not get activated. Implies some other signal? Is it easy to expand you handler to show more signals? I guess catching/tracing all possible signals may cause havoc.

<241374.855> [RecordTimer] activating state 2
<241374.855> [RecordTimer] start recording
<241374.857> [Config] getResolvedKey config.usage.blinking_rec_symbol_during_recording empty variable.
<241374.857> [Config] getResolvedKey config.usage.blinking_rec_symbol_during_recording empty variable.
<241374.857> [eDVBServiceRecord] Recording to /media/autofs/RATATOSK/movie/20161203 0755 - TV4 HD - Nyhetsmorgon.ts...
<241374.868> [eDVBServiceRecord] start recording...
<241374.868> [eDVBServiceRecord] RECORD: have 1 video stream(s) (0417), and 1 audio stream(s) (0be7), and the pcr pid is 0417, and the text pid is 179a
<241374.868> [eDVBServiceRecord] ADD PID: 0000
<241374.868> [eDVBServiceRecord] ADD PID: 004f
<241374.868> [eDVBServiceRecord] ADD PID: 0417
<241374.868> [eDVBServiceRecord] ADD PID: 0be7
<241374.868> [eDVBServiceRecord] ADD PID: 179a
<241374.870> [setIoPrio] realtime level 7 ok
<241374.870> [eFilePushThreadRecorder] THREAD START
<241374.870> [eFilePushThread] eFilePushThreadRecorder::thread setting SIGUSR1 handler
<241377.993> [eDVBServiceRecord] pcr of eit change: 40a51a3e
<241377.993> [eDVBServiceRecord] now running: Nyhetsmorgon (12900 seconds)
<241377.993> [eDVBDemux] open demux /dev/dvb/adapter0/demux0
<241377.993> [eDVBSectionReader] DMX_SET_FILTER pid=18
<241468.781> [SoftcamManager] oscam-latest already running
<241468.782> [SoftcamManager] Checking if oscam-latest is frozen
<241468.783> [eConsoleAppContainer] Starting /bin/sh
<241468.907> [eMainloop::processOneEvent] unhandled POLLERR/HUP/NVAL for fd 67(16)
<241470.796> [SoftcamManager] oscam-latest is responding like it should
<241470.797> [Task] job Components.Task.Job name=SoftcamKontroll #tasks=1 completed with [] in None
<241611.041> [eDVBRecordFileThread] wait: aio_return returned failure: Interrupted system call
<241611.041> [eFilePushThreadRecorder] WRITE ERROR, aborting thread: Interrupted system call
<241611.042> [eDVBRecordFileThread] waiting for aio to complete
<241611.042> [eDVBRecordFileThread] Waiting for I/O to complete
<241611.042> [eDVBServiceRecord] record write error
<241611.042> [eDVBServiceRecord] stop recording!
<241611.043> [eFilePushThreadRecorder] stopping thread.
<241611.043> [eFilePushThread] eFilePushThreadRecorder::stop raising SIGUSR1
<241611.044> [eFilePushThread] signal_handler entered for signal 10
<241611.047> [eDVBRecordFileThread] buffer usage histogram (40 buffers of 188 kB)
<241611.048> [eDVBRecordFileThread]   0:      5
<241611.048> [eDVBRecordFileThread]   1:    721
<241611.048> [eDVBRecordFileThread]   2:    714
<241611.153> [eFilePushThreadRecorder] THREAD STOP
<241611.159> [eDVBTSTools] setSource loading streaminfo for /media/autofs/RATATOSK/movie/20161203 0755 - TV4 HD - Nyhetsmorgon.ts
<241611.161> [eDVBServiceRecord] fixed up 40a51a3e to 4187b (offset 0)
<241611.163> [RecordTimer] WRITE ERROR on recording, disk full?
<241611.163> [Notifications] RemovePopup, id = DiskFullMessage
<241611.163> [Notifications] AddPopup, id = DiskFullMessage
<241674.100> [CrossEPG_Auto] onTimer occured at lör  3 dec 2016 07.59.59
<241674.101> [CrossEPG_Auto] poll delaying as recording.
<241674.101> [CrossEPG_Auto] Enough Retries, delaying till next schedule. lör  3 dec 2016 07.59.59
<241674.105> [Skin] processing screen MessageBox:
<241674.113> [Skin] processing screen MessageBox_summary:
<241674.117> [CrossEPG_Auto] Time set to sön  4 dec 2016 08.00.00 (now=lör  3 dec 2016 07.59.59)
<241674.119> [CrossEPG_Auto] Time set to sön  4 dec 2016 08.00.00 (now=lör  3 dec 2016 07.59.59)

 

[birdman]

And my wish came trough this morning :-/ Your SIGUSR1 handler seem to be in place but does not get activated.

Yes it does. That's these entries:

<241611.043> [eFilePushThread] eFilePushThreadRecorder::stop raising SIGUSR1
<241611.044> [eFilePushThread] signal_handler entered for signal 10

As far as I can see, in this case there has been a problem writing to the network file share, so the recording was stopped. That's this bit:

<241611.163> [RecordTimer] WRITE ERROR on recording, disk full?

The "disk full" is just a guess.

So in this case it seems all has gone as intended once there is a write failure for the recording.
Was the remote server full?
Was there a network issue (router down?).
Was there anything in the server system logs about errors?

 

[birdman]

I does not make a lot of sense to use synchronous writes as each write access will block the box for a while.

Unless you specify that you really want a synchronous write (unusual) all writes are effectively asynchronous, as they just get written to the buffer cache, which is flushed to disk/remote server asynchronously.

The place where async I/O will make a difference is in reading, as you don't have to wait for the result so can post future reads and then get on with something else.

 

[birdman]

So in this case it seems all has gone as intended once there is a write failure for the recording.

Although it may still be reporting the "Success" as a failure - that may be after the end of the part of the log you reported.

 

[birdman]

As far as I can see, in this case there has been a problem writing to the network file share, so the recording was stopped.

I now see what you mean.
It's reporting Interrupted System Call before the code sends USR1 (which it does when the thread is shutdown).
So there must be another signal raised. But any other signal should result in enigma2 stopping....

...except SIGCHLD. Perhaps that's the next thing to look at...but if you re getting that and not handling it you should (I think) be seeing zombie process (<defunct> in ps -ef output).

 

[B-N]

There IS actually a process that ends 141 seconds before the interrupt:

<241468.781> [SoftcamManager] oscam-latest already running
<241468.782> [SoftcamManager] Checking if oscam-latest is frozen
<241468.783> [eConsoleAppContainer] Starting /bin/sh
<241468.907> [eMainloop::processOneEvent] unhandled POLLERR/HUP/NVAL for fd 67(16)
<241470.796> [SoftcamManager] oscam-latest is responding like it should
<241470.797> [Task] job Components.Task.Job name=SoftcamKontroll #tasks=1 completed with [] in None
<241611.041> [eDVBRecordFileThread] wait: aio_return returned failure: Interrupted system call

I have checked some of the older logs, and there is the same situation. One or more checking if OSCAM is running before the interrupt. Different delays until the interrupt: 91, 278, 271, 198 seconds. Nothing strange as the check seem to be run around every 10 minutes. Probably has nothing to do with this problem, but just to make sure that the checking is not the problem I will test and disable softcam running check and see if that makes any difference.

By the way: server has 1.5 TB of free space and no errors in its logs. Server DO run some indexing of media files ones in a while. IF the indexing does something stupid, like locking the files it is indexing that would probably create some problems. But that should not be reported as an EINTR. Unless there is something wrong in the aio-code in libc, nfs or kernel. They should be reported as EAGAIN or EWOULDBLOCK, EIO, ENOSPC or something other than EINTR... But you never know for sure as most programs will probably handle EINTR (and partial writes) by just restarting the call so such an error might be plausible. I could disable the indexing.

 

[birdman]

There IS actually a process that ends 141 seconds before the interrupt:

I noticed that, but any signal should be virtually instantaneous.

Server DO run some indexing of media files ones in a while. IF the indexing does something stupid, like locking the files it is indexing that would probably create some problems. But that should not be reported as an EINTR.

More importantly to get EINTR there must have been a signal generated, but there is no sign of one, and no particular reason for one.

I'm rebuilding enigma2 with SIGPIPE and SIGCHLD handled in the same way as SIGUSR1 - to see if that is what it is.

It will take an hour or so (as I improved my build set-up, so it's had to start from scratch again for the whole image.

 

[birdman]

I'm rebuilding enigma2 with SIGPIPE and SIGCHLD handled in the same way as SIGUSR1 - to see if that is what it is.

It will take an hour or so (as I improved my build set-up, so it's had to start from scratch again for the whole image.

OK. Here is is. Perhaps this one will track down why EINTR gets returned.

View attachment 51585

 

[B-N]

Sorry, something is wrong with the attachment, I get this error:

vBulletin Message
Invalid Attachment specified. If you followed a valid link, please notify the administrator

 

[B-N]

A thought: What about SIGALRM? Is there any place it might not get handled and SA_RESTART not set on sa_flags?

 

[birdman]

Sorry, something is wrong with the attachment, I get this error:

Odd. So do I now, but it worked OK when I first posted it (I checked as it was name as "Attachment.." rather than the name of the file which I uploaded.)

A thought: What about SIGALRM? Is there any place it might not get handled and SA_RESTART not set on sa_flags?

Well, the relevant thing to ask is what would happen if it didn't get handled - and I think that the default handler would crash the program. Also, it's not whether it gets handled: it's the raising of a signal that is causing the EINTR.

Here's that attachment again:

View attachment enigma2-4.2.020-signals.zip

I could build one to check for SIGALRM too, but in order to test for it I have to replace any current handler for it (not that I can find any) and hence it wodul be ignored.
(A pity the PL/1 condition mechanism doesn't exists here...)

 

[B-N]

I just got one of those "Success" errors, but nothing interesting just before the error? Or does "<592506.062> [eFilePushThread] signal_handler entered for signal 17" say anything?

<592505.902> [SoftcamManager] oscam-latest already running
<592505.903> [SoftcamManager] Checking if oscam-latest is frozen
<592505.903> [eConsoleAppContainer] Starting /bin/sh
<592506.062> [eFilePushThread] signal_handler entered for signal 17
<592506.062> [eFilePushThread] signal_handler - reaped 18062, state:00000000
<592506.062> [eMainloop::processOneEvent] unhandled POLLERR/HUP/NVAL for fd 67(16)
<592506.063> [SoftcamManager] oscam-latest is responding like it should
<592506.071> [Task] job Components.Task.Job name=SoftcamKontroll #tasks=1 completed with [] in None
<592657.917> [eDVBRecordFileThread] wait: aio_return returned failure: Success
<592657.917> [eFilePushThreadRecorder] WRITE ERROR, aborting thread: Success
<592657.917> [eDVBRecordFileThread] waiting for aio to complete
<592657.917> [eDVBRecordFileThread] Waiting for I/O to complete
<592657.917> [eDVBServiceRecord] record write error
<592657.917> [eDVBServiceRecord] stop recording!
<592657.918> [eDVBRecordFileThread] Waiting for I/O to complete
<592657.919> [eDVBRecordFileThread] buffer usage histogram (40 buffers of 188 kB)
<592657.920> [eDVBRecordFileThread]   0:    420
<592657.920> [eDVBRecordFileThread]   1:  39534
<592657.920> [eDVBRecordFileThread]   2:  38674
<592657.920> [eFilePushThreadRecorder] stopping thread.
<592657.920> [eFilePushThread] eFilePushThreadRecorder::stop raising SIGUSR1
<592658.036> [eFilePushThread] signal_handler entered for signal 10
<592658.037> [eFilePushThreadRecorder] THREAD STOP
<592658.056> [eDVBTSTools] setSource loading streaminfo for /media/autofs/RATATOSK/movie/20161207 0625 - SVT1 HD - Gomorron Sverige.ts

 

[birdman]

I just got one of those "Success" errors, but nothing interesting just before the error? Or does "<592506.062> [eFilePushThread] signal_handler entered for signal 17" say anything?

Yes - it does. Although what,exactly, I can't say as I'm not sure what signal 17 is on your box.
It's either a SIGPIPE or a SIGCHLD.
Can you login to the box and run:

kill -l

so we can figure out which it is? (I suspect it's SIGCHLD).
You shouldn't be getting either (as far as I can see) so this is the cause of the problem.
I'm also interested that an unhandled POLLERR/HUP/NVAL is reported at the same time.

 

[B-N]

Yes! 17 is SIGCHLD.

root@karakal:~# kill -l
 1) HUP
 2) INT
 3) QUIT
 4) ILL
 5) TRAP
 6) ABRT
 7) BUS
 8) FPE
 9) KILL
10) USR1
11) SEGV
12) USR2
13) PIPE
14) ALRM
15) TERM
16) STKFLT
17) CHLD
18) CONT
19) STOP
20) TSTP
21) TTIN
22) TTOU
23) URG
24) XCPU
25) XFSZ
26) VTALRM
27) PROF
28) WINCH
29) POLL
30) PWR
31) SYS
32) RTMIN
64) RTMAX

 

[birdman]

Yes! 17 is SIGCHLD.

Good.
It seems to be a mips thing which makes 12 SYS, so 17 becomes USR2 and CHLD moves to 18.
The arm ones look like the x86 ones.

So, that signal would cause your problem.

Now we just have to find out what sent it and how it can be sent when the running code doesn't expect to see any signals (except the USR1 ones it sends itself to abort async I/O).

All of this is asynchronous and can be the result of anything anywhere in the program. Indeed SIGCHLD is the result of some other process...

 

[B-N]

Thought I should report a bit what happened next with my recording problems.

Figured it was important to decide if it was a software problem or a real hardware problem. To test this I started thinking it might be easiest to just test different images, but trying images that does not have to close heritage to ViX. The part of the code that does recordings seem to be the same in ViX, OpenPLI, VTI and some others. I thought that maybe Blackhole was different enough. So I have now tested Blackhole for more than a month and I have no recording problems!

I am still not sure if the rouge signals comes from inside ViX or are provoked by some behaviour of my local network. It is quite possible that deep down in libc io routines signals are generated and truncated writes return in some special cases. So I still believe ViX recording code is much to sensitive to disturbances and need to be rewritten to check and use all return values and restart write calls.

The downside of Blackhole is that I miss some of the nice features of ViX, but working recordings are much more important to me