NFS4ERR_EXPIRED - Linux NFS client bug (fixed)

Another blog entry saved as draft for a long time and waiting to be published... better late than never, so let's do it now.
Over three years ago I found a bug in Linux nfs v4.0 client which results in applications temporarily not being able to open a file and getting an error. While this is due to a bug in the nfs v4.0 client code, depending on a specific nfs server you might or might not hit the issue. For example, both Linux and Solaris NFS servers will trigger the bug, while NetApp/ONTAP won't.

Once I debuged and understood the problem and was able to reproduce it. Then I ended up with a temporary workaround and later submitted two patches to Linux kernel which quickly have been integrated into Linux 5.6 and backported to some older versions (see the patches at the very end of this blog entry).

Let's look in more detail at the issue.

btw: some output has been abbreviated and/or modified to remove irrelevant details or to anonymize details.

An application written in java was sometimes failing to open a file with the below exception:

Caused by: java.io.FileNotFoundException: /.../latest.link (Input/output error) 
        at java.io.FileInputStream.open0(Native Method) 
        at java.io.FileInputStream.open(FileInputStream.java:195) 
        at java.io.FileInputStream.<init>(FileInputStream.java:138) 
        ...

Developers added an retry logic which helped. Usually after few retries the application was able to open the affected file fine. This was happening to different files, at different times on multiple servers. Even to files which were created long time ago (don't get fooled by the java.io.FileNotFoundException).

To understand how a file is accessed by the application (although some other applications were affected too), I wrote the below code based on the affected application.

$ cat Test.java
import java.io.*;
...

public class Test {
    public static void main(String[] args) {
        FileUtils fu = new FileUtils();
        File dir = new File("/mnt/.../indexweights");
        File ft = new File("/tmp/foo");
        try {
            ft = fu.resolveLinkFile(dir);
        } catch (IOException e) {
            System.out.println("IOException: " + e.getMessage());
            e.printStackTrace();
        } finally {
            System.out.println("Destination path: " + ft.getAbsolutePath());
        }
    }
}

Let's run it under strace and see what system calls it calls: 

$ strace -tTfv -o /tmp/a -e trace=file,close,read java Test
Destination path: /mnt/...

$ grep -A2 latest.link /tmp/a
4422  15:33:38 open("/mnt/.../indexweights/latest.link", O_RDONLY) = 5 <0.069349>
4422  15:33:38 read(5, "...", 8192) = 11 <0.000010>
4422  15:33:38 close(5)                 = 0 <0.069149>

It is just a simple open() with O_RDONLY followed by read() and close(). Nothing suspicious. The error is happening with open() though, based on the java stack in the app log.
I did run the test program multiple times on affected servers and tried to access the affected files, but couldn't trigger the issue.

We modified one of the affected applications and added a retry logic for failed file opens, we also run part of the application under strace to see what's the actual error reported by open().  Let's see an example output:

$ egrep ' open\(|open resume' .../XXX.out.20190625220935.26281
...
[pid 133595] 22:10:17 open("/mnt/.../latest.link", O_RDONLY <unfinished ...>
[pid 133595] 22:10:17 <... open resumed> ) = -1 EIO (Input/output error) <0.069362>
...
[pid 133595] 22:10:21 open("/mnt/.../latest.link", O_RDONLY <unfinished ...>
[pid 133595] 22:10:21 <... open resumed> ) = -1 EIO (Input/output error) <0.069204>
...
[pid 133595] 22:10:29 open("/mnt/.../latest.link", O_RDONLY <unfinished ...>
[pid 133595] 22:10:29 <... open resumed> ) = 192 <0.487662>

The open() failed with EIO two times and then succeeded the third time.
Given these are nfs4 mount points with "hard" mount option we shouldn't be getting EIO though.
When the issue happens no errors reported in system logs.
I also collected network traffic for the above failures.