Write error that is not write error

[B-N]

It would also be interesting to check the return value of aio_return (how much that really was written) compared to the aio_nbytes in the aio_write call. To check for partial/short write. Maybe not so easy as it depends on the len parameter in a couple of call levels?

[birdman]

Is it much work for you to add some signal debug statements?

Not once I've got the first one done, which has thrown up a problem, but that's just something else to fix/workaround...

Is the handling of for example arithmetic exceptions different on a VU+ Solo 4K, ARM, than on other hardware?

No, and if these signals were being thrown you'd get a crash as there's no handler for them. The fact that there is no crash (just an error) indicates that it is SIGUSR1 being thrown by the program itself, as that's the only signal with a handler that does nothing.

[birdman]

Sorry for the delay. I was re-doing my development environment to have more space for it. It's now tidy...

Here's an enigma2 executable (all that is needed) for a vusolo4k that contains some printed info when a SIGUSR1 signal is raised and handled.

This is for 4.2.018.

enigma2-4.2.018-USR1-vusolo4k.zip

To install it you'll need to

init 4
cd /usr/bin/
cp -p enigma2 enigma2.orig
cp {new-file} enigma2
chmod 755 enigma2
init 3

Then, if you get the error again we can see where the signal is being sent from.

If you're running a version other than 4.2.018, let me know.

[B-N]

Thank you!

I had updated to 4.2.019 this morning, before reading this, but I installed it anyway and the receiver seems to be running fine.

Now I just hope there are new write errors, its been quiet for a a couple of days.

[birdman]

I had updated to 4.2.019 this morning, before reading this, but I installed it anyway and the receiver seems to be running fine.

Should be fine. I can't think of any changes that would cause a problem.

Now I just hope there are new write errors, its been quiet for a a couple of days.

Odd to be hoping for something to break.

I haven't added any code to try to fix the errors - I thought I'd see where they were occurring first.

[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.

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?