verify_packet() fails in PTF 0.10.0 but passes in 0.9.1 with STP BPDU packet #223
Description
When using verify_packet() in PTF 0.10.0 to validate a received STP BPDU packet sent from the DUT—where the expected packet is generated using a custom create_stp_bpdu_pkt() function—the test fails despite the packet being captured and returned by dataplane.poll(). Notably, the same test passes in PTF 0.9.1.
def create_stp_bpdu_pkt(src_mac, root_mac, rootid, bridgeid, port_id=0x8000, message_age=0, cost=0):
p_stp = STP(
bpdutype=0x00,
bpduflags=0x00,
portid=port_id,
rootmac=root_mac,
bridgemac=src_mac,
rootid=rootid,
bridgeid=bridgeid,
age=message_age,
pathcost=cost
)
packet = Dot3(dst="01:80:c2:00:00:00", src=src_mac, len=38)/LLC()/p_stp
return fill_up_payload(packet)
def fill_up_payload(packet, packet_len = None):
payload_length = packet_len or 64-4-len(packet) # 4 bytes FCS
if payload_length > 0:
payload = b'\x00' * payload_length
packet /= payload
return packet
----
import ptf.testutils as testutils
from ptf.mask import Mask
dut_pkt = create_stp_bpdu_pkt(src_mac, root_mac, rootid, bridgeid, port_id=0x8000+port_id, cost=0)
pkt_expected = Mask(dut_pkt)
pkt_expected.set_do_not_care_scapy(scapy.layers.l2.STP, 'bpduflags')
pkt_expected.set_ignore_extra_bytes()
ptfadapter.dataplane.flush()
time.sleep(5)
testutils.verify_packet(ptfadapter, pkt_expected, test_port)
In PTF 0.10.0, calling verify_packet() fails even though dataplane.poll() returns PollSuccess and the expected packet bytes match.
Log snippet from test run:
11:38:33 testutils.verify_packet L3249 WARNING| [testutils][verify_packet] Checking for pkt on device 0, port 1, timeout 2
11:38:33 testutils.verify_packet L3250 WARNING| [testutils][verify_packet] pkt:
packet status: OK
packet:
0000 01 80 C2 00 00 00 68 21 5F 7B 06 46 00 26 42 42 ......h!_{.F.&BB
0010 03 00 00 00 00 00 80 00 68 21 5F 7B 06 46 00 00 ........h!_{.F..
0020 00 00 80 00 68 21 5F 7B 06 46 80 05 00 00 14 00 ....h!_{.F......
0030 02 00 0F 00 00 00 00 00 00 00 00 00 ............
packet's mask:
0000 FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
0010 FF FF FF FF FF 00 FF FF FF FF FF FF FF FF FF FF ................
0020 FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF ................
0030 FF FF FF FF FF FF FF FF FF FF FF FF ............
11:38:33 testutils.dp_poll L3222 WARNING| ----------
11:38:33 testutils.dp_poll L3223 WARNING| [testutils][dp_poll] port_number: 1, timeout: 2, exp_pkt: None
11:38:33 testutils.dp_poll L3224 WARNING| [testutils][dp_poll] FILTERS: []
11:38:33 dataplane.poll L0925 WARNING| [dataplane][poll] port_number: 1, timeout: 2, exp_pkt: None, filters: []
11:38:33 dataplane.grab L0957 WARNING| [dataplane][poll] Checking packet from device 0 port 1
11:38:33 dataplane.grab L0963 WARNING| [dataplane][poll] not exp_pkt
11:38:33 dataplane.grab L0967 WARNING| [dataplane][poll] return DataPlane.PollSuccess
11:38:33 dataplane.poll L0991 WARNING| [dataplane][poll] return ret: PollSuccess(device=0, port=1, packet=b'\x01\x80\xc2\x00\x00\x00h!_{\x06F\x00&BB\x03\x00\x00\x00\x00\x01\x80\x00h!_{\x06F\x00\x00\x00\x00\x80\x00h!_{\x06F\x80\x05\x00\x00\x14\x00\x02\x00\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00', time=1748835509.8583827)
11:38:33 testutils.dp_poll L3232 WARNING| [testutils][dp_poll] result: PollSuccess(device=0, port=1, packet=b'\x01\x80\xc2\x00\x00\x00h!_{\x06F\x00&BB\x03\x00\x00\x00\x00\x01\x80\x00h!_{\x06F\x00\x00\x00\x00\x80\x00h!_{\x06F\x80\x05\x00\x00\x14\x00\x02\x00\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00', time=1748835509.8583827)
11:38:33 testutils.dp_poll L3222 WARNING| ----------
11:38:33 testutils.dp_poll L3223 WARNING| [testutils][dp_poll] port_number: 1, timeout: 1.9959828853607178, exp_pkt: None
11:38:33 testutils.dp_poll L3224 WARNING| [testutils][dp_poll] FILTERS: []
11:38:33 dataplane.poll L0925 WARNING| [dataplane][poll] port_number: 1, timeout: 1.9959828853607178, exp_pkt: None, filters: []
11:38:33 dataplane.grab L0957 WARNING| [dataplane][poll] Checking packet from device 0 port 1
11:38:33 dataplane.grab L0963 WARNING| [dataplane][poll] not exp_pkt
11:38:33 dataplane.grab L0967 WARNING| [dataplane][poll] return DataPlane.PollSuccess
11:38:33 dataplane.poll L0991 WARNING| [dataplane][poll] return ret: PollSuccess(device=0, port=1, packet=b'\x01\x80\xc2\x00\x00\x00h!_{\x06F\x00&BB\x03\x00\x00\x00\x00\x01\x80\x00h!_{\x06F\x00\x00\x00\x00\x80\x00h!_{\x06F\x80\x05\x00\x00\x14\x00\x02\x00\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00', time=1748835511.9353285)
11:38:33 testutils.dp_poll L3232 WARNING| [testutils][dp_poll] result: PollSuccess(device=0, port=1, packet=b'\x01\x80\xc2\x00\x00\x00h!_{\x06F\x00&BB\x03\x00\x00\x00\x00\x01\x80\x00h!_{\x06F\x00\x00\x00\x00\x80\x00h!_{\x06F\x80\x05\x00\x00\x14\x00\x02\x00\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00', time=1748835511.9353285)
11:38:33 testutils.dp_poll L3222 WARNING| ----------
11:38:33 testutils.dp_poll L3223 WARNING| [testutils][dp_poll] port_number: 1, timeout: 1.9927496910095215, exp_pkt: None
11:38:33 testutils.dp_poll L3224 WARNING| [testutils][dp_poll] FILTERS: []
11:38:33 dataplane.poll L0925 WARNING| [dataplane][poll] port_number: 1, timeout: 1.9927496910095215, exp_pkt: None, filters: []
11:38:33 dataplane.grab L0972 WARNING| [dataplane][poll] Did not find packet
11:38:33 dataplane.grab L0972 WARNING| [dataplane][poll] Did not find packet
11:38:34 dataplane.grab L0957 WARNING| [dataplane][poll] Checking packet from device 0 port 1
11:38:34 dataplane.grab L0963 WARNING| [dataplane][poll] not exp_pkt
11:38:34 dataplane.grab L0967 WARNING| [dataplane][poll] return DataPlane.PollSuccess
11:38:34 dataplane.poll L0991 WARNING| [dataplane][poll] return ret: PollSuccess(device=0, port=1, packet=b'\x01\x80\xc2\x00\x00\x00h!_{\x06F\x00&BB\x03\x00\x00\x00\x00\x01\x80\x00h!_{\x06F\x00\x00\x00\x00\x80\x00h!_{\x06F\x80\x05\x00\x00\x14\x00\x02\x00\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00', time=1748835514.0424163)
11:38:34 testutils.dp_poll L3232 WARNING| [testutils][dp_poll] result: PollSuccess(device=0, port=1, packet=b'\x01\x80\xc2\x00\x00\x00h!_{\x06F\x00&BB\x03\x00\x00\x00\x00\x01\x80\x00h!_{\x06F\x00\x00\x00\x00\x80\x00h!_{\x06F\x80\x05\x00\x00\x14\x00\x02\x00\x0f\x00\x00\x00\x00\x00\x00\x00\x00\x00', time=1748835514.0424163)
11:38:34 testutils.dp_poll L3222 WARNING| ----------
11:38:34 testutils.dp_poll L3223 WARNING| [testutils][dp_poll] port_number: 1, timeout: 1.7366371154785156, exp_pkt: None
11:38:34 testutils.dp_poll L3224 WARNING| [testutils][dp_poll] FILTERS: []
11:38:34 dataplane.poll L0925 WARNING| [dataplane][poll] port_number: 1, timeout: 1.7366371154785156, exp_pkt: None, filters: []
11:38:34 dataplane.grab L0972 WARNING| [dataplane][poll] Did not find packet
11:38:35 dataplane.grab L0972 WARNING| [dataplane][poll] Did not find packet
11:38:35 dataplane.poll L0980 WARNING| [dataplane][poll] poll timeout, no packet from device 0 port 1
11:38:35 dataplane.poll L0986 WARNING| [dataplane][poll] return PollFailure
11:38:35 testutils.dp_poll L3232 WARNING| [testutils][dp_poll] result: PollFailure(device=None, port=None, packet=None, time=None)
11:38:35 testutils.verify_packet L3254 WARNING| [testutils][verify_packet] result: PollFailure(device=None, port=None, packet=None, time=None)
The raw packet bytes printed during debug match the expected content. This behavior does not happen in PTF 0.9.1 — the test passes as expected there.