Frequent Fpolicy server disconnection due to Keep-Alive packet loss

Last updated
Save as PDF
Share
1. Share
2. Tweet
3. Share

Views:: 235

Visibility:: Public

Votes:: 0

Category:: ontap-9

Specialty:: nas

Last Updated:

Applies to

ONTAP 9
FPolicy

Issue

FPolicy server frequently reconnects
EMS:

Wed May 03 14:47:26 +0100 [node1: fpolicy: fpolicy.server.disconnect:error]: Connection to the FPolicy server "10.0.0.223" of policy "svm1_policy" is broken for Vserver svm1( reason: "Read returned error while reading message from FPolicy server." )

Wed May 03 14:47:27 +0100 [node1: fpolicy: fpolicy.server.connect:notice]: Control channel with the FPolicy server "10.0.0.223" of policy "svm1_policy" is established for Vserver svm1.

Wed May 03 14:47:27 +0100 [node1: fpolicy: fpolicy.server.disconnect:error]: Connection to the FPolicy server "10.0.0.223" of policy "svm1_policy" is broken for Vserver svm1( reason: "Read returned error while reading message from FPolicy server." ).

Wed May 03 14:47:28 +0100 [camsan106: fpolicy: fpolicy.server.connect:notice]: Control channel with the FPolicy server "10.0.0.223" of policy "svm1_policy" is established for Vserver svm1.

Packet trace analysis:

33 2023-05-03 15:47:26,751239    10.0.0.136    10.0.0.223     TCP        24151    1647395208  2391490589 0 24151 → 35016 [RST, ACK] Seq=1647395208 Ack=2391490589 Win=0 Len=0 TSval=1285395483 TSecr=3074462851
37 2023-05-03 15:47:27,019697    10.0.0.136    10.0.0.223     FPOLICY    26102    2310557340  897551950  2 Negotiate Request: Policy: a1002_policy
39 2023-05-03 15:47:27,021194    10.0.0.223    10.0.0.136     FPOLICY    35016    897551950   2310557773 2 Negotiate Response: Policy: a1002_policy, Version 2.0

41 2023-05-03 15:47:27,960739    10.0.0.136    10.0.0.223     TCP        24177    3655300098  2366533469 1 24177 → 35015 [RST, ACK] Seq=3655300098 Ack=2366533469 Win=0 Len=0 TSval=184933870 TSecr=3074464022
45 2023-05-03 15:47:28,228675    10.0.0.136    10.0.0.223     FPOLICY    26105    1645296941  1953409075 3 Negotiate Request: Policy: a1001_policy
47 2023-05-03 15:47:28,229724    10.0.0.223    10.0.0.136     FPOLICY    35015    1953409075  1645297374 3 Negotiate Response: Policy: a1001_policy, Version 2.0

Note:

14:47:26, ONTAP sent an RST to tear down the TCP session.
14:47:27, established a new Fpolicy connection session
14:47:27, sent an RST to close the unresponsive session
14:47:27, established another new Fpolicy connection session

Fpolicy log:

14:47:26 +01:00 [kern_fpolicy:info:6892] updateStatusTable[disconnect]:: Modified entry vs[3] policy[a1002_policy] server[10.0.0.223] [0x0x80804f800] src/fsm/fsm_external_engine.cc:4950 14:47:26 +01:00 [kern_fpolicy:info:6892] Server DISCONNECTED with retVal = 9366. [0x0x80804f800] src/fsm/fsm_task.cc:2608 14:47:27 +01:00 [kern_fpolicy:info:6892] Establish TCP connection was successful.[0x0x808050700] src/fsm/fsm_external_engine.cc:5015
14:47:27 +01:00 [kern_fpolicy:info:6892] FPolicy handshake was successful.[0x0x808050700] src/fsm/fsm_external_engine.cc:5025

14:47:27 +01:00 [kern_fpolicy:info:6892] updateStatusTable[disconnect]:: Modified entry vs[3] policy[a1001_policy] server[10.0.0.223] [0x0x80804f800] src/fsm/fsm_external_engine.cc:4950
14:47:28 +01:00 [kern_fpolicy:info:6892] FPolicy handshake was successful.[0x0x80804fd00] src/fsm/fsm_external_engine.cc:5025