Intermittent failing test: testFDSite

[mindhells]

This error appears from time to time. I've been looking for the conditions to reproduce it with no luck so far.

    ______________________________ Test.testFDSite ________________________________
    self = <fract4d.tests.test_fract4d.Test testMethod=testFDSite>
        def testFDSite(self):
            xsize = 64
            ysize = int(xsize * 3.0 / 4.0)
            im = image.T(xsize, ysize)
            (rfd, wfd) = os.pipe()
            site = fract4dc.fdsite_create(wfd)
        
            file = self.compileColorMandel()
        
            for x in range(2):
                handle = fract4dc.pf_load(file)
                pfunc = fract4dc.pf_create(handle)
                fract4dc.pf_init(pfunc, pos_params, self.color_mandel_params)
                cmap = fract4dc.cmap_create(
                    [(0.0, 0, 0, 0, 255),
                     (1 / 256.0, 255, 255, 255, 255),
                     (1.0, 255, 255, 255, 255)])
        
                fract4dc.calc(
                    params=[0.0, 0.0, 0.0, 0.0,
                            4.0,
                            0.0, 0.0, 0.0, 0.0, 0.0, 0.0],
                    antialias=0,
                    maxiter=100,
                    yflip=0,
                    nthreads=1,
                    pfo=pfunc,
                    cmap=cmap,
                    auto_deepen=0,
                    periodicity=1,
                    render_type=0,
                    image=im._img,
                    site=site,
                    asynchronous=True)
        
                nrecved = 0
                while True:
                    if nrecved == x:
                        # print "hit message count"
                        fract4dc.interrupt(site)
        
                    nb = 2 * 4
                    bytes = os.read(rfd, nb)
                    if len(bytes) < nb:
                        self.fail(
                            "bad message with length %s, value %s" %
    >                       (len(bytes), bytes))
    E                   AssertionError: bad message with length 4, value b'\x03\x00\x00\x00'
    fract4d/tests/test_fract4d.py:579: AssertionError

In gtkfractal.py we have the onDatacallback (the file descriptor associated with the site is watched). 1st thing this method tries to read from the pipe, if it doesn't get the full message (this appears to be the problem in this test) it puts the data into a buffer class member and waits till the next call.

In this test we call fract4dc.interrupt(site) which turns a flag interrupted=true in the underlying C++ object. This doesn't stop the calculation job right away but instead lets the worker thread (see the calc function arguments contains asynchronous=True) to no proceed to the next "iteration"... so we have no guarantee the message has been written by the time we try to read it in the next instruction bytes = os.read(rfd, nb).

[dragonmux]

Most likely this is caused by some delay in the kernel and that the kernel is allowed to return from read() early - it might be worth seeing if this can be made to more safely guarantee a read of the right length as read() will return an empty buffer when at EOS/EOF

It should be telling if the problem goes away with a short (10us-ish) sleep between the interrupt call and calling os.read().

[mindhells]

I’ve tried a sleep in between interrupt and read. For this specific example appears to work, although I cannot tell for sure since the error is intermittent. Anyway, would the test still be worthy if we do that?
As far as I know, being this example an “asynchronous calculation”, the message is written into the pipe by a thread different from the “main”. Meaning you can reach the read instruction in python before the write operation in C++ completes. I don’t know about the internals of os.read (or its write counterpart in C++), is that what you mean about kernel delay? could this actually happen?

[mindhells]

@DX-MON please have a look at #108

[dragonmux]

That the sleep worked says it's a mix between inter-thread scheduling timings and the time the kernel needs to synchronise data from the write to the read side of the pipe as this doesn't happen instantly.

You are correct that this can actually happen and is exactly what I was driving at. The rest of the test is fine as all we're doing by adding a sleep or select() is making it so we back off to let the kernel catch up like we'd naturally get from the code normally found around the loop which we're short-circuiting with the interrupt call.

substrate has the same problem with its console tests that involve a PTMX and PTS pair (pipes but for TTYs) and a lot of the issue is, as far as I have been able to work out, to do with the kernel expecting the read and write halves to be used by different processes where the scheduling delay between them and time to copy in and out of userspace takes care of sync.