NFS4 BAD_STATEID loop (kernel 3.0)

From /proc/mounts:

Dear All,

On a system running kernel 3.0, mounting a Solaris NFS4 export, we observe a continuous 20Mbit/sec exchange between client and server that had been occurring for 10 days.

No.     Time            Source                Destination           Protocol Size  Info
   9880 11:40:12.833617 172.29.190.21         172.29.120.140        NFS      1122  V4 COMPOUND Call (Reply In 9881) <EMPTY> PUTFH;WRITE;GETATTR

Frame 9880: 1122 bytes on wire (8976 bits), 1122 bytes captured (8976 bits)

    Arrival Time: Oct 17, 2011 11:40:12.833617000 BST
    Frame Length: 1122 bytes (8976 bits)
    Capture Length: 1122 bytes (8976 bits)

Ethernet II, Src: ChelsioC_06:68:f9 (00:07:43:06:68:f9), Dst: All-HSRP-routers_be (00:00:0c:07:ac:be) Internet Protocol, Src: 172.29.190.21 (172.29.190.21), Dst: 172.29.120.140 (172.29.120.140) Transmission Control Protocol, Src Port: 816 (816), Dst Port: nfs (2049), Seq: 5199745, Ack: 275801, Len: 1056 Remote Procedure Call, Type:Call XID:0x5daa6e93
Network File System

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 0
    Operations (count: 3)
        Opcode: PUTFH (22)
            filehandle
                length: 36
                [hash (CRC-32): 0x6e4b15f3]
                decode type as: unknown
                filehandle: 7df3a75d5e1cd908000ab44c5b000000efc80200000a0300...
        Opcode: WRITE (38)
            stateid
                seqid: 0x00000000
                Data: 4e06f15b800f82e300000000
            offset: 11392
            stable: FILE_SYNC4 (2)
            Write length: 814
            Data: <DATA>
                length: 814
                contents: <DATA>
                fill bytes: opaque data
        Opcode: GETATTR (9)
            GETATTR4args
                attr_request
                    bitmap[0] = 0x00000018
                        [2 attributes requested]
                        mand_attr: FATTR4_CHANGE (3)
                        mand_attr: FATTR4_SIZE (4)
                    bitmap[1] = 0x00300000
                        [2 attributes requested]
                        recc_attr: FATTR4_TIME_METADATA (52)
                        recc_attr: FATTR4_TIME_MODIFY (53)

No.     Time            Source                Destination           Protocol Size  Info
   9881 11:40:12.833956 172.29.120.140        172.29.190.21         NFS      122   V4 COMPOUND Reply (Call In 9880) <EMPTY> PUTFH;WRITE

Frame 9881: 122 bytes on wire (976 bits), 122 bytes captured (976 bits)
Arrival Time: Oct 17, 2011 11:40:12.833956000 BST
[Time delta from previous captured frame: 0.000339000 seconds]
Frame Length: 122 bytes (976 bits)
Capture Length: 122 bytes (976 bits)
Ethernet II, Src: Cisco_1e:f7:80 (00:13:5f:1e:f7:80), Dst: ChelsioC_06:68:f9 (00:07:43:06:68:f9) Internet Protocol, Src: 172.29.120.140 (172.29.120.140), Dst: 172.29.190.21 (172.29.190.21) Transmission Control Protocol, Src Port: nfs (2049), Dst Port: 816 (816), Seq: 275801, Ack: 5200801, Len: 56 Remote Procedure Call, Type:Reply XID:0x5daa6e93
Network File System

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Status: NFS4ERR_BAD_STATEID (10025)
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    Operations (count: 2)
        Opcode: PUTFH (22)
            Status: NFS4_OK (0)
        Opcode: WRITE (38)
            Status: NFS4ERR_BAD_STATEID (10025)

We should in principle be able to recover a BAD_STATEID error by running the state recovery thread. It's a shame that the machine was rebooted, but does your syslog trace perhaps show any state recovery thread errors?

Quoted 4 lines · * Trond Myklebust ([email protected]) wrote:

We should in principle be able to recover a BAD_STATEID error by running the state recovery thread. It's a shame that the machine was rebooted, but does your syslog trace perhaps show any state recovery thread errors?

There were no other nfs related messages reported between the initial blocked task and rebooting the machine later. Additionally, there were no nfs related messages from bootup of the machine until the blocked task.

One thing that may be of interest is that the user in question with the blocked task had hit their quota hard limit. (It was the same user that had the issue i reported earlier too on the same filesystem).

Kind regards,
..david

Can you tell us a little more about the server? Which release of Solaris? What hardware?

I'm assuming then that your network trace showed no sign of any OPEN calls of that particular file, just retries of the WRITE?

No.     Time            Source                Destination           Protocol Size  Info
     39 15:33:59.077143 172.29.190.28         172.29.120.140        NFS      370   V4 COMPOUND Call (Reply In 40) <EMPTY> PUTFH;WRITE;GETATTR

Frame 39: 370 bytes on wire (2960 bits), 370 bytes captured (2960 bits)
Ethernet II, Src: ChelsioC_07:49:6f (00:07:43:07:49:6f), Dst: All-HSRP-routers_be (00:00:0c:07:ac:be) Internet Protocol, Src: 172.29.190.28 (172.29.190.28), Dst: 172.29.120.140 (172.29.120.140) Transmission Control Protocol, Src Port: omginitialrefs (900), Dst Port: nfs (2049), Seq: 40433, Ack: 7449, Len: 304 Remote Procedure Call, Type:Call XID:0x43ce4e16
Network File System

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 0
    Operations (count: 3)
        Opcode: PUTFH (22)
            filehandle
                length: 36
                [hash (CRC-32): 0x6e4b15f3]
                decode type as: unknown
                filehandle: 7df3a75d5e1cd908000ab44c5b000000efc80200000a0300...
        Opcode: WRITE (38)
            stateid

Date: Mon, 24 Oct 2011 17:31:42 +0200
From: Trond Myklebust <[email protected]>
To: David Flynn <[email protected]>
Cc: [email protected], Chuck Lever <[email protected]>
X-Mailer: Evolution 3.0.3 (3.0.3-1.fc15)
Organization: NetApp Inc
Subject: Re: NFS4 BAD_STATEID loop (kernel 3.0.4)

Quoted 9 lines · David Flynn

No.     Time            Source                Destination           Protocol Size  Info
     39 15:33:59.077143 172.29.190.28         172.29.120.140        NFS      370   V4 COMPOUND Call (Reply In 40) <EMPTY> PUTFH;WRITE;GETATTR

Frame 39: 370 bytes on wire (2960 bits), 370 bytes captured (2960 bits)
Ethernet II, Src: ChelsioC_07:49:6f (00:07:43:07:49:6f), Dst: All-HSRP-routers_be (00:00:0c:07:ac:be) Internet Protocol, Src: 172.29.190.28 (172.29.190.28), Dst: 172.29.120.140 (172.29.120.140) Transmission Control Protocol, Src Port: omginitialrefs (900), Dst Port: nfs (2049), Seq: 40433, Ack: 7449, Len: 304 Remote Procedure Call, Type:Call XID:0x43ce4e16
Network File System

Quoted 15 lines

    [Program Version: 4]
    [V4 Procedure: COMPOUND (1)]
    Tag: <EMPTY>
        length: 0
        contents: <EMPTY>
    minorversion: 0
    Operations (count: 3)
        Opcode: PUTFH (22)
            filehandle
                length: 36
                [hash (CRC-32): 0x6e4b15f3]
                decode type as: unknown
                filehandle: 7df3a75d5e1cd908000ab44c5b000000efc80200000a0300...
        Opcode: WRITE (38)
            stateid

Do you have an example of the stateid argument's value? Does it change at all between separate WRITE attempts?

Do you have an example of the stateid argument's value? Does it change at all between separate WRITE attempts?

Quoted 2 lines · * Trond Myklebust ([email protected]) wrote:

Do you have an example of the stateid argument's value? Does it change at all between separate WRITE attempts?

Further to all this, i've just had a similar fault on another machine,

Quoted 5 lines · * David Flynn ([email protected]) wrote:

Quoted 2 lines · * Trond Myklebust ([email protected]) wrote:

Do you have an example of the stateid argument's value? Does it change at all between separate WRITE attempts?

Further to all this, i've just had a similar fault on another machine,

Using the same kernel, same mountpoint as before, we're currently experiencing a loop involving NFS4ERR_STALE_CLIENTID. Trace:
ftp://ftp.kw.bbc.co.uk/davidf/priv/saesheil.pcap

Unfortunately, this is resulting in about 40 nodes doing their best to kill the poor solaris server. Generating a combined total of 250Mbit/sec towards the NFS server (collecting a little under 200Mbit/sec of replies).

Have we not heard of exponential backoff?

This seems to require major attention, given that this amounted to a site wide DoS: going round all the machines and killing the processes that were having major problems brought the situation back under control. Frankly i'd rather that you panicked the kernel than this.

Quoted 2 lines

Using the same kernel, same mountpoint as before, we're currently experiencing a loop involving NFS4ERR_STALE_CLIENTID.

The problem seems like a split-brain issue on the server... On the one hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

-----Original Message-----
From: David Flynn [mailto:[email protected]]
Sent: Saturday, October 29, 2011 8:02 PM
To: Myklebust, Trond
Cc: David Flynn; [email protected]; Chuck Lever
Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 2 lines · * Trond Myklebust ([email protected]) wrote:

Quoted 2 lines

Using the same kernel, same mountpoint as before, we're currently experiencing a loop involving NFS4ERR_STALE_CLIENTID.

...

Quoted 1 line

The problem seems like a split-brain issue on the server... On the

Quoted 3 lines

hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

Thank you for the quick update, especially at the weekend. I'm

it is possible that the STALE_CLIENTID issue is a by-product of the BAD_STATEID issue from earlier. We have observed several times the BAD_STATEID loop, but the CLIENTID problem only seemed to occur when

40+ nodes were all showing problems.

After killing off sufficient processes, the some of the machines then recovered of their own accord. So your conclusion that there is a

sounds reasonable.

On any such possible backoff, the previous case was with quite small requests in quite a tight loop that seemed to cause the server grief. This morning, a machine with a 10GbE interface had a BAD_STATEID issue

involving some much larger writes[1], resulting in 1.6Gbit/sec from

machine alone. Thankfully there was only a second machine with 1GbE interfaces bringing the total up to 2.5Gbit/sec.

It is this ability for a group of clients to make matters worse that

as any fault with Solaris.

(In a similar vein, it can be just as frustrating trying to get a

looping like this - it is often impossible to kill the process that

problem; for these, we had to resort to deleting the files using NFSv3

was working quite happily))

Quoted 7 lines

-----Original Message-----
From: David Flynn [mailto:[email protected]]
Sent: Saturday, October 29, 2011 8:02 PM
To: Myklebust, Trond
Cc: David Flynn; [email protected]; Chuck Lever
Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 5 lines

Quoted 2 lines · * Trond Myklebust ([email protected]) wrote:

Quoted 2 lines

Using the same kernel, same mountpoint as before, we're currently experiencing a loop involving NFS4ERR_STALE_CLIENTID.

...

Quoted 1 line

The problem seems like a split-brain issue on the server... On the

one

Quoted 5 lines

Quoted 3 lines

hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

Thank you for the quick update, especially at the weekend. I'm

wondering if

Quoted 3 lines

it is possible that the STALE_CLIENTID issue is a by-product of the BAD_STATEID issue from earlier. We have observed several times the BAD_STATEID loop, but the CLIENTID problem only seemed to occur when

all

Quoted 4 lines

40+ nodes were all showing problems.

After killing off sufficient processes, the some of the machines then recovered of their own accord. So your conclusion that there is a

server issue

Quoted 5 lines

sounds reasonable.

On any such possible backoff, the previous case was with quite small requests in quite a tight loop that seemed to cause the server grief. This morning, a machine with a 10GbE interface had a BAD_STATEID issue

but

Quoted 1 line

involving some much larger writes[1], resulting in 1.6Gbit/sec from

that

Quoted 4 lines

machine alone. Thankfully there was only a second machine with 1GbE interfaces bringing the total up to 2.5Gbit/sec.

It is this ability for a group of clients to make matters worse that

is just as bad

Quoted 1 line

as any fault with Solaris.

Sure, but gone are the days when NFS had "reference implementations" that everyone had to interoperate with. NFSv4 is a fully documented protocol which describes how both clients and servers are supposed to work. If either the client or server fail to work according to that documentation, then bad things will happen.

While I could litter the client code with lots of little tricks to be "defensive" in the face of buggy servers, that isn't going to solve
anything: the server will still be buggy, and the client will still be faced with a situation that it cannot resolve.

Quoted 1 line

(In a similar vein, it can be just as frustrating trying to get a

client to stop

Quoted 1 line

looping like this - it is often impossible to kill the process that

triggered the

Quoted 1 line

problem; for these, we had to resort to deleting the files using NFSv3

(which

Quoted 1 line

was working quite happily))

'kill -9' should in principle work to kill off the process. Was that failing to work?

-----Original Message-----
From: Chuck Lever [mailto:[email protected]]
Sent: Saturday, October 29, 2011 8:23 PM
To: Myklebust, Trond
Cc: David Flynn; [email protected]
Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 22 lines · Trond

Quoted 7 lines

-----Original Message-----
From: David Flynn [mailto:[email protected]]
Sent: Saturday, October 29, 2011 8:02 PM
To: Myklebust, Trond
Cc: David Flynn; [email protected]; Chuck Lever
Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 5 lines

Quoted 2 lines · * Trond Myklebust ([email protected]) wrote:

Quoted 2 lines

Using the same kernel, same mountpoint as before, we're currently experiencing a loop involving NFS4ERR_STALE_CLIENTID.

...

Quoted 1 line

The problem seems like a split-brain issue on the server... On the

one

Quoted 5 lines

Quoted 3 lines

hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

Thank you for the quick update, especially at the weekend. I'm

wondering if

Quoted 3 lines

it is possible that the STALE_CLIENTID issue is a by-product of the BAD_STATEID issue from earlier. We have observed several times the BAD_STATEID loop, but the CLIENTID problem only seemed to occur

Quoted 4 lines

all

Quoted 3 lines

40+ nodes were all showing problems.

After killing off sufficient processes, the some of the machines

Quoted 5 lines

Quoted 1 line

recovered of their own accord. So your conclusion that there is a

server issue

Quoted 3 lines

sounds reasonable.

On any such possible backoff, the previous case was with quite

Quoted 1 line

Quoted 1 line

requests in quite a tight loop that seemed to cause the server

Quoted 6 lines

Quoted 2 lines

This morning, a machine with a 10GbE interface had a BAD_STATEID issue

but

Quoted 1 line

involving some much larger writes[1], resulting in 1.6Gbit/sec from

that

Quoted 1 line

machine alone. Thankfully there was only a second machine with

Quoted 3 lines

Quoted 3 lines

interfaces bringing the total up to 2.5Gbit/sec.

It is this ability for a group of clients to make matters worse

Quoted 6 lines

is just as bad

Quoted 1 line

as any fault with Solaris.

Sure, but gone are the days when NFS had "reference implementations" that everyone had to interoperate with. NFSv4 is a fully documented protocol which describes how both clients and servers are supposed

Quoted 4 lines

work. If either the client or server fail to work according to that documentation, then bad things will happen.

While I could litter the client code with lots of little tricks to

Quoted 2 lines

"defensive" in the face of buggy servers, that isn't going to solve
anything: the server will still be buggy, and the client will still

Quoted 8 lines

faced with a situation that it cannot resolve.

Quoted 1 line

(In a similar vein, it can be just as frustrating trying to get a

client to stop

Quoted 1 line

looping like this - it is often impossible to kill the process that

triggered the

Quoted 2 lines

problem; for these, we had to resort to deleting the files using NFSv3

Quoted 5 lines

(which

Quoted 1 line

was working quite happily))

'kill -9' should in principle work to kill off the process. Was that failing to work?

The trick is knowing which process to kill. Generally you have to

manager thread in this case.

No. Not in this case: the state manager was doing RENEW, then exiting because it was told all is A_OK by the server.
The open() system call would be the one that was looping.

OK. This is the first time I've seen this tcpdump.

The problem seems like a split-brain issue on the server... On the one hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

IOW: This isn't a problem I can fix on the client whether or not I add exponential backoff. The problem needs to be addressed on the server by the Solaris folks....

-----Original Message-----
From: J. Bruce Fields [mailto:[email protected]]
Sent: Saturday, October 29, 2011 8:15 PM
To: Myklebust, Trond
Cc: David Flynn; [email protected]; Chuck Lever
Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 3 lines · Trond Myklebust

OK. This is the first time I've seen this tcpdump.

The problem seems like a split-brain issue on the server... On the

Quoted 5 lines

hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

IOW: This isn't a problem I can fix on the client whether or not I

Quoted 2 lines

exponential backoff. The problem needs to be addressed on the server by the Solaris folks....

Is there any simple thing we could do on the client to reduce the

these sorts of loops?

Given that we know there are bad servers out there it might be nice to

it's not complicated.

(Though as a server implementer my purely selfish impulse is to leave

as they are since it ensures I'll get bug reports if I screw up....)

Quoted 5 lines

From: J. Bruce Fields [mailto:[email protected]]

Quoted 3 lines · Trond Myklebust

OK. This is the first time I've seen this tcpdump.

The problem seems like a split-brain issue on the server... On the

one

Quoted 5 lines

Quoted 5 lines

hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

IOW: This isn't a problem I can fix on the client whether or not I

add

Quoted 3 lines

Quoted 2 lines

exponential backoff. The problem needs to be addressed on the server by the Solaris folks....

Quoted 1 line

Is there any simple thing we could do on the client to reduce the

impact of

Quoted 1 line

these sorts of loops?

WHY? Those loops aren't supposed to happen if the server works according to spec.

Quoted 15 lines · Trond

Quoted 5 lines

From: J. Bruce Fields [mailto:[email protected]]

Quoted 3 lines · Trond Myklebust

OK. This is the first time I've seen this tcpdump.

The problem seems like a split-brain issue on the server... On the

one

Quoted 5 lines

Quoted 5 lines

hand, it is happily telling us that our lease is OK when we RENEW. Then when we try to use said lease in an OPEN, it is replying with STALE_CLIENTID.

IOW: This isn't a problem I can fix on the client whether or not I

add

Quoted 3 lines

Quoted 2 lines

exponential backoff. The problem needs to be addressed on the server by the Solaris folks....

Quoted 6 lines

Quoted 1 line

Is there any simple thing we could do on the client to reduce the

impact of

Quoted 1 line

these sorts of loops?

WHY? Those loops aren't supposed to happen if the server works according to spec.

Yes, and it's not something I care that strongly about, really, my only observation is that this sort of failure (an implementation bug on one side or another resulting in a loop) seems to have been common (based on no hard data, just my vague memories of list threads), and the results fairly obnoxious (possibly even for unrelated hosts on the network). So if there's some simple way to fail more gracefully it might be helpful.

-----Original Message-----
From: Chuck Lever [mailto:[email protected]]
Sent: Saturday, October 29, 2011 8:51 PM
To: J. Bruce Fields
Cc: Myklebust, Trond; David Flynn; [email protected]
Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 2 lines · J. Bruce Fields

Quoted 1 line · Trond

Quoted 1 line

From: J. Bruce Fields [mailto:[email protected]] On Sat, Oct

Quoted 4 lines

Quoted 4 lines

Quoted 4 lines

Quoted 3 lines · Trond Myklebust

OK. This is the first time I've seen this tcpdump.

The problem seems like a split-brain issue on the server... On

Quoted 2 lines

Quoted 2 lines

one

Quoted 1 line

Quoted 1 line

hand, it is happily telling us that our lease is OK when we

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Then when we try to use said lease in an OPEN, it is replying

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

STALE_CLIENTID.

IOW: This isn't a problem I can fix on the client whether or not

Quoted 6 lines

Quoted 6 lines

add

Quoted 4 lines

Quoted 2 lines

exponential backoff. The problem needs to be addressed on the server by the Solaris folks....

Is there any simple thing we could do on the client to reduce the

impact of

Quoted 8 lines

Quoted 4 lines

Quoted 1 line

these sorts of loops?

WHY? Those loops aren't supposed to happen if the server works according to spec.

Yes, and it's not something I care that strongly about, really, my only observation is that this sort of failure (an implementation bug on one side or another resulting in a loop) seems to have been

Quoted 2 lines

(based on no hard data, just my vague memories of list threads), and the results fairly obnoxious (possibly even for unrelated hosts on

network).

Quoted 2 lines

So if there's some simple way to fail more gracefully it might be helpful.

For what it's worth, I agree that client implementations should

behave more gracefully in the face of server problems, be they the

bugs or the result of other issues specific to that server. Problems

make NFSv4 as a protocol look bad.

Quoted 12 lines

-----Original Message-----
From: Chuck Lever [mailto:[email protected]]

Quoted 8 lines · J. Bruce Fields

Yes, and it's not something I care that strongly about, really, my only observation is that this sort of failure (an implementation bug on one side or another resulting in a loop) seems to have been common (based on no hard data, just my vague memories of list threads), and the results fairly obnoxious (possibly even for unrelated hosts on the network).
So if there's some simple way to fail more gracefully it might be helpful.

Quoted 4 lines

For what it's worth, I agree that client implementations should attempt to behave more gracefully in the face of server problems, be they the result of bugs or the result of other issues specific to that server. Problems like this make NFSv4 as a protocol look bad.

I can't see what a client can do in this situation except possibly just give up after a while and throw a SERVER_BROKEN error (which means data loss). That still won't make NFSv4 look good...

-----Original Message-----
From: David Flynn [mailto:[email protected]]
Sent: Saturday, October 29, 2011 9:53 PM
To: Myklebust, Trond
Cc: Chuck Lever; J. Bruce Fields; David Flynn;

Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 4 lines · * Myklebust, Trond ([email protected]) wrote:

Quoted 4 lines

-----Original Message-----
From: Chuck Lever [mailto:[email protected]] On Oct 29, 2011,

Quoted 1 line · J. Bruce Fields

Yes, and it's not something I care that strongly about, really,

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

only observation is that this sort of failure (an implementation bug on one side or another resulting in a loop) seems to have

Quoted 4 lines

Quoted 4 lines

Quoted 4 lines

common (based on no hard data, just my vague memories of list threads), and the results fairly obnoxious (possibly even for unrelated hosts on the network).
So if there's some simple way to fail more gracefully it might

Quoted 4 lines

Quoted 4 lines

Quoted 1 line

helpful.

For what it's worth, I agree that client implementations should attempt to behave more gracefully in the face of server problems,

Quoted 2 lines

Quoted 2 lines

they the result of bugs or the result of other issues specific to that server. Problems like this make NFSv4 as a protocol look

Quoted 4 lines

I can't see what a client can do in this situation except possibly just give up after a while and throw a SERVER_BROKEN error (which means data loss). That still won't make NFSv4 look good...

Indeed, it is a quite the dilemma.

I agree that giving and guaranteeing unattended data loss is bad (data

the behest of an operator is ok, afterall they can always fence a

machine).

Looking at some of the logs again, even going back to the very

appears to be about 600us between retries (RTT=400us). Is there any

make that less aggressive?, eg 1s? -- that'd reduce the impact by

orders of magnitude. What would be the down-side? How often do you expect to get a BAD_STATEID error?

BAD_STATEID is a different matter, and is one that we should have resolved in the NFS client in the upstream kernel. At least on newer clients, we should be trying to reopen the file and re-establish all locks when we get a BAD_STATEID. Can you please remind us which kernel you are using?

That said... Even on new clients, the recovery attempt may fail due to the STALE_CLIENTID bug. That will still hit us when we call OPEN in order to get a new stateid.

-----Original Message-----
From: David Flynn [mailto:[email protected]]
Sent: Saturday, October 29, 2011 11:08 PM
To: Myklebust, Trond
Cc: David Flynn; Chuck Lever; J. Bruce Fields;

Subject: Re: NFS4ERR_STALE_CLIENTID loop

Quoted 4 lines · * Myklebust, Trond ([email protected]) wrote:

BAD_STATEID is a different matter, and is one that we should have resolved in the NFS client in the upstream kernel. At least on newer clients, we should be trying to reopen the file and re-establish all locks when we get a BAD_STATEID. Can you please remind us which

Quoted 1 line

you are using?

Ah, i see. This was all on 3.0.0 and 3.0.4 (a quick check didn't

relevant changes between the two).

Are there any stable patches that can be applied to 3.0.y?

Quoted 1 line

That said... Even on new clients, the recovery attempt may fail due

Quoted 2 lines

the STALE_CLIENTID bug. That will still hit us when we call OPEN in order to get a new stateid.

The interval between retries on that was ~1-1.5ms, could this be made slower? -- same questions as before really.

Quoted 12 lines · * Myklebust, Trond ([email protected]) wrote:

Quoted 12 lines

-----Original Message-----
From: Chuck Lever [mailto:[email protected]]

Quoted 8 lines · J. Bruce Fields

Yes, and it's not something I care that strongly about, really, my only observation is that this sort of failure (an implementation bug on one side or another resulting in a loop) seems to have been common (based on no hard data, just my vague memories of list threads), and the results fairly obnoxious (possibly even for unrelated hosts on the network).
So if there's some simple way to fail more gracefully it might be helpful.

Quoted 8 lines

Quoted 4 lines

For what it's worth, I agree that client implementations should attempt to behave more gracefully in the face of server problems, be they the result of bugs or the result of other issues specific to that server. Problems like this make NFSv4 as a protocol look bad.

I can't see what a client can do in this situation except possibly just give up after a while and throw a SERVER_BROKEN error (which means data loss). That still won't make NFSv4 look good...

Indeed, it is a quite the dilemma.

I agree that giving and guaranteeing unattended data loss is bad (data loss at the behest of an operator is ok, afterall they can always fence a broken machine).

Looking at some of the logs again, even going back to the very original case, it appears to be about 600us between retries (RTT=400us). Is there any way to make that less aggressive?, eg 1s? -- that'd reduce the impact by three orders of magnitude. What would be the down-side? How often do you expect to get a BAD_STATEID error?

..david

David, what would help immensely is if you can find a reliable way of reproducing this. So far we have been unable to find a reproducer.

Quoted 2 lines · * Chuck Lever ([email protected]) wrote:

David, what would help immensely is if you can find a reliable way of reproducing this. So far we have been unable to find a reproducer.

While i've managed to have problems with individual machines, that seem to fail at some random point of their own choosing, the most reliable way to produce problem for us to have a number of nodes updating various RRD files frequently.

Given that i haven't found a reliable and short method for reproducing it either, if we were to re-run the known case and capture all network traffic, would you be able to extract the relevant detail to generate a simulation?

Dear All,

On a system running kernel 3.0, mounting a Solaris NFS4 export, we observe a continuous 20Mbit/sec exchange between client and server that had been occurring for 10 days.

From /proc/mounts:
home:/home/ /home nfs4 rw,relatime,vers=4,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=172.29.190.21,minorversion=0,local_lock=none,addr=172.29.120.140 0 0

Reconciling logs, we find that around the time the exchange started, the kernel reports a process having blocked:

[787321.680029] INFO: task bash:17799 blocked for more than 120 seconds.
[787321.680067] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[787321.680104] bash            D 0000000000000002     0 17799      1 0x00000000
[787321.680131]  ffff880173ad9ca8 0000000000000086 ffff88017216b008 0000000000012a40
[787321.680171]  ffff880173ad9fd8 0000000000012a40 ffff880173ad8000 0000000000012a40
[787321.680211]  0000000000012a40 0000000000012a40 ffff880173ad9fd8 0000000000012a40
[787321.680251] Call Trace:
[787321.680275]  [<ffffffff8110e900>] ? __lock_page+0x70/0x70
[787321.680299]  [<ffffffff815fea2c>] io_schedule+0x8c/0xd0
[787321.680321]  [<ffffffff8110e90e>] sleep_on_page+0xe/0x20
[787321.680344]  [<ffffffff815ff2af>] __wait_on_bit+0x5f/0x90
[787321.680366]  [<ffffffff8110ead3>] wait_on_page_bit+0x73/0x80
[787321.680390]  [<ffffffff81085980>] ? autoremove_wake_function+0x40/0x40
[787321.680416]  [<ffffffff8111aeb5>] ? pagevec_lookup_tag+0x25/0x40
[787321.680439]  [<ffffffff8110ed06>] filemap_fdatawait_range+0xf6/0x1a0
[787321.680483]  [<ffffffffa022e740>] ? nfs_destroy_directcache+0x20/0x20 [nfs]
[787321.680507]  [<ffffffff8111a3b1>] ? do_writepages+0x21/0x40
[787321.680530]  [<ffffffff8110ff8b>] ? __filemap_fdatawrite_range+0x5b/0x60
[787321.680555]  [<ffffffff81110000>] filemap_write_and_wait_range+0x70/0x80
[787321.680580]  [<ffffffff8119b45a>] vfs_fsync_range+0x5a/0x90
[787321.680602]  [<ffffffff8119b4fc>] vfs_fsync+0x1c/0x20
[787321.680628]  [<ffffffffa0222be4>] nfs_file_flush+0x54/0x80 [nfs]
[787321.680653]  [<ffffffff8116d66f>] filp_close+0x3f/0x90
[787321.680675]  [<ffffffff8116e097>] sys_close+0xb7/0x120
[787321.680698]  [<ffffffff816090c2>] system_call_fastpath+0x16/0x1b

A network trace showed the following exchange below being continually repeated. Unfortunately this system too has since been rebooted.

Any thoughts on the matter would be most welcome,

Kind regards,

..david

No. Time Source Destination Protocol Size Info
9880 11:40:12.833617 172.29.190.21 172.29.120.140 NFS 1122 V4 COMPOUND Call (Reply In 9881) <EMPTY> PUTFH;WRITE;GETATTR

Frame 9880: 1122 bytes on wire (8976 bits), 1122 bytes captured (8976 bits)
Arrival Time: Oct 17, 2011 11:40:12.833617000 BST
Frame Length: 1122 bytes (8976 bits)
Capture Length: 1122 bytes (8976 bits)
Ethernet II, Src: ChelsioC_06:68:f9 (00:07:43:06:68:f9), Dst: All-HSRP-routers_be (00:00:0c:07:ac:be) Internet Protocol, Src: 172.29.190.21 (172.29.190.21), Dst: 172.29.120.140 (172.29.120.140) Transmission Control Protocol, Src Port: 816 (816), Dst Port: nfs (2049), Seq: 5199745, Ack: 275801, Len: 1056 Remote Procedure Call, Type:Call XID:0x5daa6e93
Network File System
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Tag: <EMPTY>
length: 0
contents: <EMPTY>
minorversion: 0
Operations (count: 3)

       Opcode: PUTFH (22)
           filehandle
               length: 36
               [hash (CRC-32): 0x6e4b15f3]
               decode type as: unknown
               filehandle: 7df3a75d5e1cd908000ab44c5b000000efc80200000a0300...
       Opcode: WRITE (38)
           stateid
               seqid: 0x00000000
               Data: 4e06f15b800f82e300000000
           offset: 11392
           stable: FILE_SYNC4 (2)
           Write length: 814
           Data: <DATA>
               length: 814
               contents: <DATA>
               fill bytes: opaque data
       Opcode: GETATTR (9)
           GETATTR4args
               attr_request
                   bitmap[0] = 0x00000018
                       [2 attributes requested]
                       mand_attr: FATTR4_CHANGE (3)
                       mand_attr: FATTR4_SIZE (4)
                   bitmap[1] = 0x00300000
                       [2 attributes requested]
                       recc_attr: FATTR4_TIME_METADATA (52)
                       recc_attr: FATTR4_TIME_MODIFY (53)

No. Time Source Destination Protocol Size Info
9881 11:40:12.833956 172.29.120.140 172.29.190.21 NFS 122 V4 COMPOUND Reply (Call In 9880) <EMPTY> PUTFH;WRITE

Frame 9881: 122 bytes on wire (976 bits), 122 bytes captured (976 bits)
Arrival Time: Oct 17, 2011 11:40:12.833956000 BST
[Time delta from previous captured frame: 0.000339000 seconds]
Frame Length: 122 bytes (976 bits)
Capture Length: 122 bytes (976 bits)
Ethernet II, Src: Cisco_1e:f7:80 (00:13:5f:1e:f7:80), Dst: ChelsioC_06:68:f9 (00:07:43:06:68:f9) Internet Protocol, Src: 172.29.120.140 (172.29.120.140), Dst: 172.29.190.21 (172.29.190.21) Transmission Control Protocol, Src Port: nfs (2049), Dst Port: 816 (816), Seq: 275801, Ack: 5200801, Len: 56 Remote Procedure Call, Type:Reply XID:0x5daa6e93
Network File System
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Status: NFS4ERR_BAD_STATEID (10025)
Tag: <EMPTY>
length: 0
contents: <EMPTY>
Operations (count: 2)

       Opcode: PUTFH (22)
           Status: NFS4_OK (0)
       Opcode: WRITE (38)
           Status: NFS4ERR_BAD_STATEID (10025)

--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html