記錄一次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， 或許還有別的異常，期待進一步觀察。