记录一次wireshark抓包分析nfsv4 on macos

Status: NFS4ERR_STALE (70) file no longer exists
发生在想lock 时 ，文件已经被别的进程lock住，过了一段时间后再去open_reclaim时，该文件
已经被remove掉了，反应在上层：[Errno 5] Input/output error

跑完一段压力测试之后，得到报错信息如下：

[CRITICAL] 2020-05-14 23:49:44,192 Group-0: read failure for file testfile22658, error is [Errno 5] Input/output error
[CRITICAL] 2020-05-14 23:49:55,130 Group-2: rm error happen for file testfile71055, error is [Errno 5] Input/output error

查看抓包信息：

从原始包中，打开statistics ---> Conversations ---> TCP， 查看server ip 对应的 port：

然后 filter：

tcp.port == 63538 or tcp.port == 63540 or tcp.port == 63541

再导出选择的包：file ---> export specified packets or file ---> export packet dissections ---> as csv

进入分析阶段：
报错的时间是 49:44,192
从pcap中过滤附近时间段：frame.time >= "May 15, 2020 14:49:44.190"
然后搜索和 file:testfile22658 有关的error信息：
Status: NFS4ERR_STALE (70) ---> file no longer exists
[Stream index: 0]

nfs.nfsstat4 == 70
现在过滤 nfs.nfsstat4 == 70 的 进程，发现是open_reclaim时发生的, 一共两个，正好对应了最初我们获得的error信息，并且stream也一一对应了。
stream0 对应的是group0, stream2 对应的是group2的。

再查open_reclaim，nfs.tag == "open_reclaim"， 发现有百十个open_reclaim，reclaim成功的话，会返回 一个stateID,如果失败就会返回Status: NFS4ERR_STALE (70)

我们先分析第一个error： testfile22658
可 ctrl+f 调出 search 栏，选string: NFS4ERR_STALE 得到 file hash

再搜索这个file hash，看看这个文件在error之前发生了什么：
36551 group0 请求了一个读lock：

Opcode: LOCK (12)
    locktype: READ_LT (1)

36552 reply ：

LOCK Status: NFS4ERR_EXPIRED

几毫秒之后，37467 group1 请求了一个写lock，优先级高于读lock：

Opcode: LOCK (12)
    locktype: WRITE_LT (2)

37468 reply:

Opcode: LOCK (12)
    Status: NFS4_OK (0)

然后 group1 把 testfile22658 rename: .nfs.20051250.04f8

Opcode: RENAME (29)
    Name: testfile22658
        length: 13
        contents: testfile22658
        fill bytes: opaque data
    Name: .nfs.20051250.04f8
        length: 18
        contents: .nfs.20051250.04f8
        fill bytes: opaque data

group1 unlock 这个 名字为.nfs.20051250.04f8， file hash依然为：[hash (CRC-32): 0x16da1980]的file
并且在 37500， remove掉了这个file：

Opcode: REMOVE (28)
    Name: .nfs.20051250.04f8
        length: 18
        contents: .nfs.20051250.04f8
        fill bytes: opaque data

然后呢，group0 因为在36551 请求lock file hash 0x16da1980,被告知 NFS4ERR_EXPIRED 过期无效了，
于是它等到37897时，发起了 open_reclaim，然而 file已经被remove，它只能得到一个NFS4ERR_STALE file no longer exists 的结果了:`

37897:

Tag: open_reclaim
    length: 12
    contents: open_reclaim

37899 reply:

Opcode: OPEN (18)
    Status: NFS4ERR_STALE (70)

在macos的上层 被捕获到的异常 是 Input/output error.

第二个error 也是类似原因。

获得技能：

1. 通过 statistics ---> Conversations ---> TCP， 来查询要过滤的port
2. 将stream，file hash都加入列，方便过滤追踪
3. ctrl+f ， 用string来搜索关键信息，可以在浏览全局的模式下查有效信息
4. 导出csv，方便mark重要信息
5. 理解 lock 失效后 有reclaim机制再尝试打开，大多数会成功，不成功的话目前只遇到rm导致的file no exist， 或许还有别的异常，期待进一步观察。