PTF thrift client issue (the v6 test case just hangs)

[mhanif]

PTF thrift client side issue at setup time where it gets blocked before invoking SAI thrift API. As soon as we send a SIGINT (Ctrl-C) to the client, it seems to get unblocked and sends the request to the thrift server just before quitting. We can see that the thrift server correctly programs the P4 table. @reshmaintel @vmytnykx can you take a look ?

Originally posted by @mukeshmv in #222 (comment)

[chrispsommers]

Hi @mhanif have you tried running just this test in isolation (no other tests) e.g. from within the saithrift-client container?

Note, there is a way to run gdb on the saithrift server, see https://github.com/Azure/DASH/blob/main/dash-pipeline/README-saithrift.md#debugging-saithrift-server-with-gdb. It would be interesting to see what state the server is in while the test is "hanging." Start GDB, run the test, then CTRL-C the server and issue the backtrace (bt) command.

Have you pushed your dev branch to a repo; can you provide the link? Furthermore, you could submit a PR (mark it as "draft") which would make your repo apparent and someone (me) could download it and try to recreate your scenario.

[mhanif]

Hi @mhanif have you tried running just this test in isolation (no other tests) e.g. from within the saithrift-client container?

Yes, and it worked!

Note, there is a way to run gdb on the saithrift server, see https://github.com/Azure/DASH/blob/main/dash-pipeline/README-saithrift.md#debugging-saithrift-server-with-gdb. It would be interesting to see what state the server is in while the test is "hanging." Start GDB, run the test, then CTRL-C the server and issue the backtrace (bt) command.

Haven't tried debugging with GDB

Have you pushed your dev branch to a repo; can you provide the link? Furthermore, you could submit a PR (mark it as "draft") which would make your repo apparent and someone (me) could download it and try to recreate your scenario.

That is a great idea. I will push a "draft" PR for people to try and see if they can help figure out why we are not able to run this test case along with other test cases.

[vmytnykx]

Hi @mhanif, could you please provide more information what exactly you are are running to get this problem ?

• What test case are you running ?
• How do you execute it ?
• What environment are you using to run PTF ?
• Etc.

Once you help to recreate the issue, only then we can try to help. For now we have not seen such issue on our side. I think providing a link to your dev branch as @chrispsommers suggested and providing the instructions to recreate it would be helpful here.

[chrispsommers]

@mhanif One more thing, you don't actually have to do a PR for us to look at the issue, just give us your GitHub URL and branch and we can clone it to reproduce. A PR is only needed when you're ready to submit.

[mhanif]

Hi @vmytnykx @chrispsommers Please refer to my mhanif/DASH fork. I have submitted the new test case in the branch (test-vnet-v6). It is a new file (test_saithrift_vnet_v6.py) in vnet directory which introduces a class "TestSaiThrift_outbound_udpv6_pkt". Once you are in this branch and have built (make all) in the dash-pipeline, please (1) run make run-switch in one terminal and (2) run make run-saithrift-server in another one. Below are the steps run in the 3rd terminal which resulted in the new test case not running and instead seeing a hang:

$ make run-saithrift-client-bash
docker run -u root --network=host --rm -w /tests/ -it  \
-v /home/mhanif/sw/dash-test-vnet-v6/DASH/dash-pipeline/tests/:/tests-dev/ \
-w /tests-dev/saithrift \
local/dash-saithrift-client:latest \
/bin/bash
root@mhanif-VirtualBox:/tests-dev/saithrift# ls
README.md  ptf  pytest
root@mhanif-VirtualBox:/tests-dev/saithrift# cd ptf
root@mhanif-VirtualBox:/tests-dev/saithrift/ptf# ls
README.md  run-saithrift-ptftests.sh  thrift  vnet
root@mhanif-VirtualBox:/tests-dev/saithrift/ptf# cd vnet
root@mhanif-VirtualBox:/tests-dev/saithrift/ptf/vnet# ls
test_saithrift_vnet.py  test_saithrift_vnet_v6.py
root@mhanif-VirtualBox:/tests-dev/saithrift/ptf/vnet# cd ..
root@mhanif-VirtualBox:/tests-dev/saithrift/ptf# ls
README.md  run-saithrift-ptftests.sh  thrift  vnet
root@mhanif-VirtualBox:/tests-dev/saithrift/ptf# ./run-saithrift-ptftests.sh
/usr/local/lib/python3.8/dist-packages/ptf-0.9.3-py3.8.egg/EGG-INFO/scripts/ptf:19: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
  import imp
Using packet manipulation module: ptf.packet_scapy
test_thrift_session.TestSaiThriftSession ... TestSaiThriftSession OK
ok

----------------------------------------------------------------------
Ran 1 test in 0.004s

OK
test_thrift_session.TestSaiThriftSaiHelper ... TestSaiThriftSaiHelper OK
ok

----------------------------------------------------------------------
Ran 1 test in 0.003s

OK
test_saithrift_vnet.TestSaiThrift_outbound_udp_pkt ...

Sending packet with wrong vip...

 <Ether  dst=00:00:02:03:04:05 src=00:00:05:06:06:06 type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=172.16.1.1 dst=172.16.100.100 |<UDP  sport=11638 dport=4789 chksum=0x0 |<VXLAN  flags=Instance reserved1=0 vni=0x64 reserved2=0x0 |<Ether  dst=02:02:02:02:02:02 src=00:cc:cc:cc:cc:cc type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=10.1.1.10 dst=10.1.2.50 |<UDP  sport=1234 dport=80 |<Raw  load='\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !"#$%&\'()*+,-./0123456789' |>>>>>>>>

Verifying drop...

Sending packet with wrong dst CA IP to verify routing drop...

 <Ether  dst=00:00:02:03:04:05 src=00:00:05:06:06:06 type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=172.16.1.1 dst=172.16.1.100 |<UDP  sport=11638 dport=4789 chksum=0x0 |<VXLAN  flags=Instance reserved1=0 vni=0x64 reserved2=0x0 |<Ether  dst=02:02:02:02:02:02 src=00:cc:cc:cc:cc:cc type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=10.1.1.10 dst=10.200.2.50 |<UDP  sport=1234 dport=80 |<Raw  load='\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !"#$%&\'()*+,-./0123456789' |>>>>>>>>

Verifying drop...

Sending packet with wrong dst CA IP to verify mapping drop...

 <Ether  dst=00:00:02:03:04:05 src=00:00:05:06:06:06 type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=172.16.1.1 dst=172.16.1.100 |<UDP  sport=11638 dport=4789 chksum=0x0 |<VXLAN  flags=Instance reserved1=0 vni=0x64 reserved2=0x0 |<Ether  dst=02:02:02:02:02:02 src=00:cc:cc:cc:cc:cc type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=10.1.1.10 dst=10.1.211.211 |<UDP  sport=1234 dport=80 |<Raw  load='\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !"#$%&\'()*+,-./0123456789' |>>>>>>>>

Verifying drop...

Sending outbound packet...

 <Ether  dst=00:00:02:03:04:05 src=00:00:05:06:06:06 type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=172.16.1.1 dst=172.16.1.100 |<UDP  sport=11638 dport=4789 chksum=0x0 |<VXLAN  flags=Instance reserved1=0 vni=0x64 reserved2=0x0 |<Ether  dst=02:02:02:02:02:02 src=00:cc:cc:cc:cc:cc type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=10.1.1.10 dst=10.1.2.50 |<UDP  sport=1234 dport=80 |<Raw  load='\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !"#$%&\'()*+,-./0123456789' |>>>>>>>>

Verifying packet...
 <Ether  dst=00:00:00:00:00:00 src=00:00:00:00:00:00 type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp chksum=0x0 src=172.16.1.100 dst=172.16.1.20 |<UDP  sport=0 dport=4789 chksum=0x0 |<VXLAN  flags= reserved1=0 vni=0x64 reserved2=0x0 |<Ether  dst=00:dd:dd:dd:dd:dd src=00:cc:cc:cc:cc:cc type=IPv4 |<IP  ihl=None tos=0x0 id=1 flags= frag=0 ttl=64 proto=udp src=10.1.1.10 dst=10.1.2.50 |<UDP  sport=1234 dport=80 |<Raw  load='\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !"#$%&\'()*+,-./0123456789' |>>>>>>>>
test_sai_thrift_outbound_udp_pkt_test OK
ok

----------------------------------------------------------------------
Ran 1 test in 0.495s

OK
test_saithrift_vnet_v6.TestSaiThrift_outbound_udpv6_pkt ...

[chrispsommers]

@mhanif thanks, I'll take a look.

[chrispsommers]

I did some extensive debugging. No final conclusion yet but perhaps @marian-pritsak or @vmytnykx have some ideas?

Synopsis:
When you execute run-saithrift-ptftests.sh inside saithrift-client container, the first tests in ptf/vnet/test_saithrift_vnet.py pass. When second file ptf/vnet/test_saithrift_vnet_v6.py runs, it hangs in the first thrift call sai_thrift_create_vip_entry(), whcih is identical code as the Pv4 case. Debugging shows that the thrift message gets sent on the wire but the saiserver RPC server does not invoke the callback to libsai handler sai_create_vip_entry(). Therefore no P4Runtime messages are sent to the bmv2. If you break out of the PTF program (using ^C) then the P4Runtime message gets sent and the table entry is inserted, but the test was aborted so it's after the fact. You can also set a Pdb breakpoint before the sai_thrift_create_vip_entry() then step into it, but again you have to kill the process for the P4Runtime message to get sent.

Seems like a saithrift-server/P4Runtime concurrency issue - maybe some subtle blocking.

Note, If I construct a similar set of tests using Pytest, I can run the two tests back-to-back w/o hanging.

Also, if you separate run PTF tests for test_saithrift_vnet.py then test_saithrift_vnet_v6.py, both pass. So it might be a PTF environment-related issue. It might even disappear if the PTF framework is updated and libsai is enhanced to fix PLVision#29 to provide platform attributes.

Below I show some of the debugging steps I took. Use the synopsis above to interpret the parallel workflows below.

make run-switch console

chris@chris-z4:~/hanif-DASH/DASH/dash-pipeline$ make run-switch

This is how the end of the first test looks after table entries are removed. If just hangs until you kill PTF, then you get the final entry inserted.
...
[00:40:33.560] [bmv2] [D] [thread 16] Removed entry 1 from table 'dash_ingress.dash_acl_group|dash_acl'
[00:40:33.561] [bmv2] [D] [thread 17] Removed entry 0 from table 'dash_ingress.dash_acl_group|dash_acl'
[00:40:33.562] [bmv2] [D] [thread 16] Removed entry 0 from table 'dash_ingress.direction_lookup|dash_direction_lookup'
[00:40:33.563] [bmv2] [D] [thread 17] Removed entry 0 from table 'dash_ingress.vip|dash_vip'

After breaking out of PTF test:

[21:36:08.746] [bmv2] [D] [thread 16] Entry 16777216 added to table 'dash_ingress.vip|dash_vip'
[21:36:08.746] [bmv2] [D] [thread 16] Dumping entry 16777216
Match key:

• hdr.ipv4.dst_addr:VIP: EXACT ac1001c8
  Action entry: dash_ingress.accept -

GDB saithrift-server console

chris@chris-z4:~/hanif-DASH/DASH/dash-pipeline$ make run-saithrift-server-bash
dashuser@chris-z4:/SAI/rpc/usr/sbin$ gdb saiserver
(gdb) dir /meta
(gdb) b sai_create_vip_entry
Function "sai_create_vip_entry" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (sai_create_vip_entry) pending.
(gdb) r
Starting program: /SAI/rpc/usr/sbin/saiserver

[run all ptf tests]
...
Thread 5 "saiserver" hit Breakpoint 1, sai_create_vip_entry (vip_entry=0x7700000000, attr_count=21905, attr_list=0x0) at saidashvip.cpp:31
31 In const sai_attribute_t *attr_list) {
(gdb) c
Continuing.
GRPC call Write::INSERT OKtable_id: 38937816 match { field_id: 1 exact { value: "\254\020\001d" } } action { action { action_id: 26041632 } }
GRPC call Write::INSERT OKtable_id: 38960243 match { field_id: 1 exact { value: "\000\000d" } } action { action { action_id: 21912829 } }
GRPC call Write::INSERT OKtable_id: 45323240 match { field_id: 1 exact { value: "\000\001" } } action { action { action_id: 25655048 params { param_id: 1 value: "\000\000\000\000" } } }
GRPC call Write::INSERT OKtable_id: 45323240 match { field_id: 1 exact { value: "\000\002" } } action { action { action_id: 25655048 params { param_id: 1 value: "\000\000\000\000" } } }
GRPC call Write::INSERT OKtable_id: 34579306 match { field_id: 1 exact { value: "\000\003" } } action { action { action_id: 17187022 params { param_id: 1 value: "\000\000d" } } }
GRPC call Write::INSERT OKtable_id: 47336097 match { field_id: 1 exact { value: "\000\004" } } action { action { action_id: 27167550 params { param_id: 1 value: "\000\000'\020" } params { param_id: 2 value: "\000\001\206\240" } params { param_id: 3 value: "\000\001\206\240" } params { param_id: 4 value: "\001" } params { param_id: 5 value: "\254\020\001\001" } params { param_id: 6 value: "\000\000\t" } params { param_id: 7 value: "\000\003" } params { param_id: 8 value: "\000\000" } params { param_id: 9 value: "\000\000" } params { param_id: 10 value: "\000\000" } params { param_id: 11 value: "\000\000" } params { param_id: 12 value: "\000\000" } params { param_id: 13 value: "\000\000" } params { param_id: 14 value: "\000\000" } params { param_id: 15 value: "\000\000" } params { param_id: 16 value: "\000\000" } params { param_id: 17 value: "\000\000" } params { param_id: 18 value: "\000\000" } params { param_id: 19 value: "\000\000" } params { param_id: 20 value: "\000\000" } params { param_id: 21 value: "\000\000" } params { param_id: 22 value: "\000\000" } params { param_id: 23 value: "\000\000" } params { param_id: 24 value: "\000\000" } params { param_id: 25 value: "\000\000" } params { param_id: 26 value: "\000\000" } params { param_id: 27 value: "\000\000" } } }
GRPC call Write::INSERT OKtable_id: 38612462 match { field_id: 1 exact { value: "\000\314\314\314\314\314" } } action { action { action_id: 18228884 params { param_id: 1 value: "\000\004" } } }
GRPC call Write::INSERT OKtable_id: 42788937 match { field_id: 1 exact { value: "\000\004" } } match { field_id: 3 lpm { value: "\n\001\000\000" prefix_len: 112 } } match { field_id: 2 exact { value: "\000" } } action { action { action_id: 25364446 params { param_id: 1 value: "\000\003" } } }
GRPC call Write::INSERT OKtable_id: 48860231 match { field_id: 1 exact { value: "\000\003" } } match { field_id: 3 exact { value: "\n\001\0022" } } match { field_id: 2 exact { value: "\000" } } action { action { action_id: 25450412 params { param_id: 1 value: "\254\020\001\024" } params { param_id: 2 value: "\000\335\335\335\335\335" } params { param_id: 3 value: "\001" } } }
GRPC call Write::DELETE OKtable_id: 48860231 match { field_id: 1 exact { value: "\000\003" } } match { field_id: 3 exact { value: "\n\001\0022" } } match { field_id: 2 exact { value: "\000" } }
GRPC call Write::DELETE OKtable_id: 42788937 match { field_id: 1 exact { value: "\000\004" } } match { field_id: 3 lpm { value: "\n\001\000\000" prefix_len: 112 } } match { field_id: 2 exact { value: "\000" } }
GRPC call Write::DELETE OKtable_id: 38612462 match { field_id: 1 exact { value: "\000\314\314\314\314\314" } }
GRPC call Write::DELETE OKtable_id: 47336097 match { field_id: 1 exact { value: "\000\004" } } action { action { action_id: 27167550 params { param_id: 1 value: "\000\000'\020" } params { param_id: 2 value: "\000\001\206\240" } params { param_id: 3 value: "\000\001\206\240" } params { param_id: 4 value: "\001" } params { param_id: 5 value: "\254\020\001\001" } params { param_id: 6 value: "\000\000\t" } params { param_id: 7 value: "\000\003" } params { param_id: 8 value: "\000\000" } params { param_id: 9 value: "\000\000" } params { param_id: 10 value: "\000\000" } params { param_id: 11 value: "\000\000" } params { param_id: 12 value: "\000\000" } params { param_id: 13 value: "\000\000" } params { param_id: 14 value: "\000\000" } params { param_id: 15 value: "\000\000" } params { param_id: 16 value: "\000\000" } params { param_id: 17 value: "\000\000" } params { param_id: 18 value: "\000\000" } params { param_id: 19 value: "\000\000" } params { param_id: 20 value: "\000\000" } params { param_id: 21 value: "\000\000" } params { param_id: 22 value: "\000\000" } params { param_id: 23 value: "\000\000" } params { param_id: 24 value: "\000\000" } params { param_id: 25 value: "\000\000" } params { param_id: 26 value: "\000\000" } params { param_id: 27 value: "\000\000" } } }
GRPC call Write::DELETE OKtable_id: 34579306 match { field_id: 1 exact { value: "\000\003" } } action { action { action_id: 17187022 params { param_id: 1 value: "\000\000d" } } }
GRPC call Write::DELETE OKtable_id: 45323240 match { field_id: 1 exact { value: "\000\002" } } action { action { action_id: 25655048 params { param_id: 1 value: "\000\000\000\000" } } }
GRPC call Write::DELETE OKtable_id: 45323240 match { field_id: 1 exact { value: "\000\001" } } action { action { action_id: 25655048 params { param_id: 1 value: "\000\000\000\000" } } }
GRPC call Write::DELETE OKtable_id: 38960243 match { field_id: 1 exact { value: "\000\000d" } }
GRPC call Write::DELETE OKtable_id: 38937816 match { field_id: 1 exact { value: "\254\020\001d" } }

[...waiting as we hit Python breakpoint before next call to sai_thrift_create_vip_entry()]

Nothing happens, test hangs. THen ^C and quit out of PTF test and next gRPC message gets sent and the table entry is added:

Thread 5 "saiserver" hit Breakpoint 1, sai_create_vip_entry (vip_entry=0x7fc800000000, attr_count=21994, attr_list=0x55eae49ed500 <sai_thrift_ip_address_t_parse(sai::sai_thrift_ip_address_t const&, _sai_ip_address_t*)+64>)
at saidashvip.cpp:31
31 In const sai_attribute_t *attr_list) {
(gdb)
Continuing.
GRPC call Write::INSERT OKtable_id: 38937816 match { field_id: 1 exact { value: "\254\020\001\310" } } action { action { action_id: 26041632 } }

Thrift monitor console

chris@chris-z4:~/hanif-DASH/DASH/dash-pipeline$ sudo tcpdump -enX -i lo port 9092

This appears when first PTF test cretes vip entry, GDB breakpoint is hit right after:
13:45:26.984080 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 182: 127.0.0.1.51276 > 127.0.0.1.9092: Flags [P.], seq 1:117, ack 1, win 512, options [nop,nop,TS val 212276593 ecr 212276592], length 116
0x0000: 4500 00a8 2132 4000 4006 1b1c 7f00 0001 E...!2@.@.......
0x0010: 7f00 0001 c84c 2384 6d2e e67a a105 7f76 .....L#.m..z...v
0x0020: 8018 0200 fe9c 0000 0101 080a 0ca7 1571 ...............q
0x0030: 0ca7 1570 8001 0001 0000 001b 7361 695f ...p........sai_
0x0040: 7468 7269 6674 5f63 7265 6174 655f 7669 thrift_create_vi
0x0050: 705f 656e 7472 7900 0000 000c 0001 0a00 p_entry.........
0x0060: 0100 0000 0000 0000 050c 0002 0800 0100 ................
0x0070: 0000 000c 0002 0b00 0100 0000 0c31 3732 .............172
0x0080: 2e31 362e 312e 3130 3000 0000 0f00 020c .16.1.100.......
0x0090: 0000 0001 0800 0100 0000 000c 0002 0800 ................
0x00a0: 0800 0000 0000 0000 ........
13:45:26.984087 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 66: 127.0.0.1.9092 > 127.0.0.1.51276: Flags [.], ack 117, win 511, options [nop,nop,TS val 212276593 ecr 212276593], length 0
0x0000: 4500 0034 9a94 4000 4006 a22d 7f00 0001 E..4..@.@..-....
0x0010: 7f00 0001 2384 c84c a105 7f76 6d2e e6ee ....#..L...vm...
0x0020: 8010 01ff fe28 0000 0101 080a 0ca7 1571 .....(.........q
0x0030: 0ca7 1571 ...q

[continue GDB]

Here are thrift messages at end of vnet IPv4 test:

13:46:51.381910 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 106: 127.0.0.1.9092 > 127.0.0.1.51276: Flags [P.], seq 839:879, ack 2317, win 512, options [nop,nop,TS val 212360990 ecr 212360989], length 40
0x0000: 4500 005c 9ab3 4000 4006 a1e6 7f00 0001 E....@.@.......
0x0010: 7f00 0001 2384 c84c a105 82bc 6d2e ef86 ....#..L....m...
0x0020: 8018 0200 fe50 0000 0101 080a 0ca8 5f1e .....P.........
0x0030: 0ca8 5f1d 8001 0002 0000 001b 7361 695f ...........sai_
0x0040: 7468 7269 6674 5f72 656d 6f76 655f 7669 thrift_remove_vi
0x0050: 705f 656e 7472 7900 0000 0000 p_entry.....
13:46:51.383296 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 74: 127.0.0.1.51280 > 127.0.0.1.9092: Flags [S], seq 3940346627, win 65495, options [mss 65495,sackOK,TS val 212360992 ecr 0,nop,wscale 7], length 0
0x0000: 4500 003c 110b 4000 4006 2baf 7f00 0001 E..<..@.@.+.....
0x0010: 7f00 0001 c850 2384 eadc eb03 0000 0000 .....P#.........
0x0020: a002 ffd7 fe30 0000 0204 ffd7 0402 080a .....0..........
0x0030: 0ca8 5f20 0000 0000 0103 0307 ...........
13:46:51.383324 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 74: 127.0.0.1.9092 > 127.0.0.1.51280: Flags [S.], seq 1388168065, ack 3940346628, win 65483, options [mss 65495,sackOK,TS val 212360992 ecr 212360992,nop,wscale 7], length 0
0x0000: 4500 003c 0000 4000 4006 3cba 7f00 0001 E..<..@.@.<.....
0x0010: 7f00 0001 2384 c850 52bd c381 eadc eb04 ....#..PR.......
0x0020: a012 ffcb fe30 0000 0204 ffd7 0402 080a .....0..........
0x0030: 0ca8 5f20 0ca8 5f20 0103 0307 ..........
13:46:51.383348 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 66: 127.0.0.1.51280 > 127.0.0.1.9092: Flags [.], ack 1, win 512, options [nop,nop,TS val 212360992 ecr 212360992], length 0
0x0000: 4500 0034 110c 4000 4006 2bb6 7f00 0001 E..4..@.@.+.....
0x0010: 7f00 0001 c850 2384 eadc eb04 52bd c382 .....P#.....R...
0x0020: 8010 0200 fe28 0000 0101 080a 0ca8 5f20 .....(.........
0x0030: 0ca8 5f20 ...
13:46:51.424702 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 66: 127.0.0.1.51276 > 127.0.0.1.9092: Flags [.], ack 879, win 512, options [nop,nop,TS val 212361033 ecr 212360990], length 0
0x0000: 4500 0034 2152 4000 4006 1b70 7f00 0001 E..4!R@.@..p....
0x0010: 7f00 0001 c84c 2384 6d2e ef86 a105 82e4 .....L#.m.......
0x0020: 8010 0200 fe28 0000 0101 080a 0ca8 5f49 .....(........I
0x0030: 0ca8 5f1e ...
13:46:52.384718 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 74: 127.0.0.1.9092 > 127.0.0.1.51280: Flags [S.], seq 1388168065, ack 3940346628, win 65483, options [mss 65495,sackOK,TS val 212361993 ecr 212360992,nop,wscale 7], length 0
0x0000: 4500 003c 0000 4000 4006 3cba 7f00 0001 E..<..@.@.<.....
0x0010: 7f00 0001 2384 c850 52bd c381 eadc eb04 ....#..PR.......
0x0020: a012 ffcb fe30 0000 0204 ffd7 0402 080a .....0..........
0x0030: 0ca8 6309 0ca8 5f20 0103 0307 ..c........
13:46:52.384753 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 66: 127.0.0.1.51280 > 127.0.0.1.9092: Flags [.], ack 1, win 512, options [nop,nop,TS val 212361993 ecr 212360992], length 0
0x0000: 4500 0034 110d 4000 4006 2bb5 7f00 0001 E..4..@.@.+.....
0x0010: 7f00 0001 c850 2384 eadc eb04 52bd c382 .....P#.....R...
0x0020: 8010 0200 fe28 0000 0101 080a 0ca8 6309 .....(........c.
0x0030: 0ca8 5f20 .._.

These thrift messages appear when second test starts (e.g. I resume PDB via "c" command), the first SAI action is to create vip entry. However, breakpoint in the thrift server isn't hit and libsai with P4Runtime callbacks never invoked for sai_create_vip_entry():

13:49:53.279963 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 182: 127.0.0.1.51280 > 127.0.0.1.9092: Flags [P.], seq 1:117, ack 1, win 512, options [nop,nop,TS val 212542888 ecr 212360992], length 116
0x0000: 4500 00a8 110e 4000 4006 2b40 7f00 0001 E.....@.@.+@....
0x0010: 7f00 0001 c850 2384 eadc eb04 52bd c382 .....P#.....R...
0x0020: 8018 0200 fe9c 0000 0101 080a 0cab 25a8 ..............%.
0x0030: 0ca8 5f20 8001 0001 0000 001b 7361 695f ...........sai
0x0040: 7468 7269 6674 5f63 7265 6174 655f 7669 thrift_create_vi
0x0050: 705f 656e 7472 7900 0000 000c 0001 0a00 p_entry.........
0x0060: 0100 0000 0000 0000 050c 0002 0800 0100 ................
0x0070: 0000 000c 0002 0b00 0100 0000 0c31 3732 .............172
0x0080: 2e31 362e 312e 3230 3000 0000 0f00 020c .16.1.200.......
0x0090: 0000 0001 0800 0100 0000 000c 0002 0800 ................
0x00a0: 0800 0000 0000 0000 ........
13:49:53.279988 00:00:00:00:00:00 > 00:00:00:00:00:00, ethertype IPv4 (0x0800), length 66: 127.0.0.1.9092 > 127.0.0.1.51280: Flags [.], ack 117, win 511, options [nop,nop,TS val 212542888 ecr 212542888], length 0
0x0000: 4500 0034 8961 4000 4006 b360 7f00 0001 E..4.a@.@..`....
0x0010: 7f00 0001 2384 c850 52bd c382 eadc eb78 ....#..PR......x
0x0020: 8010 01ff fe28 0000 0101 080a 0cab 25a8 .....(........%.
0x0030: 0cab 25a8 ..%.

P4Runtime Console

chris@chris-z4:~/hanif-DASH/DASH/dash-pipeline$ sudo tcpdump -enX -i lo port 9559

PTF Console

Note - edit ptf test as follows:
Near top:
import pdb

in test-case:
class TestSaiThrift_outbound_udpv6_pkt(ThriftInterfaceDataPlane):
...
ADDED===> pdb.set_trace() <===
status = sai_thrift_create_vip_entry(self.client, self.vpe,
action=SAI_VIP_ENTRY_ACTION_ACCEPT)

chris@chris-z4:~/hanif-DASH/DASH/dash-pipeline$ make run-saithrift-client-bash
...
root@chris-z4:/tests-dev/saithrift# cd ptf
root@chris-z4:/tests-dev/saithrift/ptf# ./run-saithrift-ptftests.sh

test_saithrift_vnet.TestSaiThrift_outbound_udpv6_pkt ... > /tests-dev/saithrift/ptf/vnet/test_saithrift_vnet.py(318)setUp()
-> status = (self.client, self.vpe,

(Pdb) c

[thrift message gets sent for sai_thrift_create_vip_entry() but libsai never calls sai_create_vip_entry()

^C one or two times, then Quit. P4Runtime message finally gets sent.

[aputriax]

Hi @chrispsommers and @mhanif,

The issue is in the test tearDown() method. You call super in the setUp() that initializes self.transport and acquire socket. But you do not call the same method in the tearDown() and the socket is not released. The next test tries to use the same socket and hangs.

Fix:
All you need to add a call super(self.__class__, self).tearDown() or super(TestSaiThrift_outbound_udp_pkt, self).tearDown() after all cleanup functions in your test class tearDown. Also you might need to add this call to the failure_teardown. The socket will be properly closed and next test won't stack.

P.S.: I suggest moving VNET configure steps to a test function and call it in the runTest() so setUp won't fail and you won't need to have two teardown methods.

[chrispsommers]

Thanks @aputriax! You were right, I tried super.tearDown() and indeed it works now. I'll give provide @mhanif with the proper changes. This was my error some months ago when I wrote the first test. Thanks for the experienced eye!

[chrispsommers]

Hi @mhanif I've submitted mhanif#1 to your fork to fix this problem. Please let me know if this works. Thanks for reporting this, and thanks to @aputriax for the advice on a solution.

[mhanif]

Hi @chrispsommers @aputriax, thanks a lot for finding the root cause and fixing the issue. Much appreciated.

@chrispsommers, I will merge the changes you have submitted with the PR to my fork and will test and verify. Upon validation, I will submit the changes (PR) to the DASH repo. Thanks!