EOSd issues

Site Administrators
#1

Hi All,

We are seeing some strange problems and am wondering if anyone can take a look.

We are currently running EOS 4.5.20 and eosd 4.5.20.

Here is a simple php code snippet that opens a file for writing, writes some bytes and closes the file:

$chunk_size = strlen($data);
$pass = false;
$fh = fopen($chunkFile, 'wb');
if ($fh !== false) {
    $written = fwrite($fh, $data, $chunk_size);
    fclose($fh);

    //at this point the file should have written, lets have a look.
    if ($chunk_size != $written) {
        log('chunk_size!=written');
    } else if ($chunk_size != filesize($chunkFile)) {
        log('chunk_size!=filesize())');
    } else {
        $pass = true;
    }
} else {
    log(‘fopen failed');
}

We see 4 scenarios where this is failing

Scenario 1: fopen() fails

This is reflected in the eosd logs as an error for file open. Wrapping the above code in a loop that retires up to 100 times seems to resolve this but there is no reason it should have failed to begin with.

What can we do on our end to make this better?

Scenario 2: fwrite() fails

In php the fwrite() function returns how many bytes has been written. When a write is successful its return value should be the size of the data being written. Sometimes it fails and is reflected in the eosd logs:

200702 00:59:04 t=1593651544.011208 f=DoWrite l=ERROR tid=00007fab30ffd700 s=CacheEntry:342 error while writing piece off=0, len=10

Wrapping the above code in a loop that retries up to 100 times seems to resolve this. What can we do on our end to make this better?

Scenario 3: filesize() does not match

Sometimes after a successful fwrite() we test the file with php’s filesize() function and the sizes do not match. I have not seen anything in particular in the EOS logs to link to this but our php logs do report many “chunk_size!=filesize()”

Wrapping the above code in a loop that retries up to 100 times seems to sometimes resolve this. What can we do on our end to make this better?

Scenario 4: code passes fine without error but the file in EOS is 0 bytes!

This is probably the worst out of the four as eosd is not returning any errors back to the filesystem back to php. But looking at eosd logs and FST logs I see the following:

From eosd log:
200701 10:35:25 t=1593599725.092130 f=fileOpen l=ERROR tid=00007f801c7fd700 s=XrdIo:233 error= "open failed url=root://*AAwADAA@eoscs.cdn.aarnet.edu.au:1094///#curl#/eos/something/something/something/something/something/something/something/file3?eos.app=fuse&eos.bookingsize=0&eos.encodepath=1&eos.lfn=fxid:65c87622&fst.valid=1593599673, errno=0, errc=306, msg=[FATAL] Redirect limit has been reached"

From eosd log:
200701 10:35:25 t=1593599725.092292 f=MakeOpen l=ERROR tid=00007f801c7fd700 s=LayoutWrapper:131 file root://*AAwADAA@eoscs.cdn.aarnet.edu.au///#curl#/eos/something/something/something/something/something/something/something/file3 is already closed - won't open

From FST log:
217451 FstOfs_open: *AAwADAA.8008:121@crlt-k8 Unable to open - fst validity expired /#curl#/eos/something/something/something/something/something/something/something/file3; invalid argument

What do these error messages actually mean?
What can we do on our end to make this better?

Cheers,
Michael

Michael D’Silva • Cloud Services

AARNet Pty Ltd
m: +61 403191855
e: michael.dsilva@aarnet.edu.au
w: aarnet.edu.au
a: AARNet, Level 1, 62 Lygon St, Carlton South VIC 3053, Australia

#2

You should probably check the return code of fclose. This is the only point where write can actually report an error since most of it is asynchronous.

#3

Hi @apeters,

Thanks for taking a look. fclose() in php returns a boolean and we have modified the code to catch and report when fclose() fails.

Will update soon.

Cheers,
Michael D’Silva

#4

Hi @apeters,
So far fclose has not returned false.
Cheers,
Michael D’Silva

#5

Hi @apeters,

In the past 7 days fclose() has not returned false. I think it is safe to say that the problem is not fclose().

What should we look at next?

Cheers,
Michael D’Silva

#6

Hi Michael,
to catch all the errors, the only way is to run the mounts with:

EOS_FUSE_LAZYOPENRW=0

There is a certain error path happening on an FST, which eosd cannot see if you run eosd in asynchronous mode.

This has a latency price, but you get errors as they happen.

Cheers Andreas.

#7

Hi Andreas,

Originally we had LAZYOPENRW disabled when we first started to scale our system and noticed slow performance and have been running with it enabled for some years now and do not feel comfortable disabling it at this time.

That said, I’ve looked into FST errors for the times where scenario 1+2+3 happens and found the following FST errors from around the same time frames.

  • “no FMD record found”
  • “cannot set net parameters on filesystem”

Note that it is possible that these FST errors may be unrelated to our issues and that it simply lines up with client errors in term of time. (Less than a second older than client side errors)

What should we do/look at next?

Cheers,
Michael D’Silva

#8

Sorry Michael,
I was too long on vacation … the problem can be summarized like this:

  • if you don’t have a single synchronization point in the POSIX calls, you cannot catch errors until the file is succesfully written.

To be sure that a file is written in POSIX, you have to call ‘fsync’. This will make all latency visible to you and you have to adapt your server code to deal with that.

Otherwise there is no other good solution with ‘eosd’.

Andreas

#9

Hi @apeters,

Hope your holiday was fun and relaxing, here in Melbourne we are locked down and can’t go beyond 5km form our homes.

Do we need to set EOS_FUSE_SYNC=1 (currently set to default 0) to allow EOSd to fsync?(https://gitlab.cern.ch:8443/dss/eos/-/blob/master/fuse/eosfuse.cc#L1573)

Is there much of a performance hit for EOS_FUSE_SYNC=1 compared to not and compared to EOS_FUSE_LAZYOPENRW=0 ?

Cheers,
Michael D’Silva

#10

Hi Michael,
it is probably worse because it only changes the point where in the IO sequence you wait for a response.
If you do:
open <---- ! lazy open waits here
write <----- fsync waits for all writes
close <----- when writing you don’t have any state change on close, so nobody waits here
But if you need to know your data was written, you need to call fsync.

I know, this is not good news. It is a little bit like UDP vs TCP …

Andreas.

#11

Hi Andreas,
This is still good information we can use for testing.
To confirm what settings should we test with, is it both EOS_FUSE_SYNC=1 and EOS_FUSE_LAZYOPENRW=0? or just the one?
Cheers,
Michael D’Silva