filter_body autest fails in CI sometimes: request not blocked #12875
Description
There seems to be a race condition with the filter_body plugin when blocking requests because the autest fails in CI sometimes.
See:
https://ci.trafficserver.apache.org/job/Github_Builds/job/autest/34842/console
Test: filter_body: Failed
File: filter_body.test.py
Directory: /home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/pluginTest/filter_body
Starting Test filter_body : No issues found - Passed
Reason: Started!
Run: Verify filter_body plugin for request/response body content filtering: Failed
Setting up : Copying 'filter_body.replay.yaml' to '/tmp/sandbox/filter_body' - Passed
Starting TestRun 0-tr : No Issues found - Passed
Reason: Started!
Process: server: Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/.git/proxy-verifier-v2.12.0/linux-amd64' to '/tmp/sandbox/filter_body/server/bin' - Passed
Setting up : recycling port: 61881, queue size: 973 - Passed
Setting up : recycling port: 61882, queue size: 972 - Passed
Setting up : recycling port: 61883, queue size: 971 - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/../../tools/proxy-verifier/ssl/server.pem' to '/tmp/sandbox/filter_body/server/server.pem' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/../../tools/proxy-verifier/ssl/ca.pem' to '/tmp/sandbox/filter_body/server/ca.pem' - Passed
Setting up : Copying 'filter_body.replay.yaml' to '/tmp/sandbox/filter_body/server/filter_body.replay.yaml' - Passed
Test : Checking that ReturnCode == 0 - Passed
Reason: Returned Value: 0 == 0
Time-Out : Process finishes within expected time - Passed
Reason: Returned value: 5.0678746700286865 < 600.0
file /tmp/sandbox/filter_body/_output/0-tr-server/stream.stdout.txt : There should be no Proxy Verifier violation errors. - Passed
Reason: Contents of /tmp/sandbox/filter_body/_output/0-tr-server/stream.stdout.txt excludes expression
Process: Default: Failed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/.git/proxy-verifier-v2.12.0/linux-amd64' to '/tmp/sandbox/filter_body/client/bin' - Passed
Setting up : Copying 'filter_body.replay.yaml' to '/tmp/sandbox/filter_body/client/filter_body.replay.yaml' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/../../tools/proxy-verifier/ssl/client.pem' to '/tmp/sandbox/filter_body/client/client.pem' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/../../tools/proxy-verifier/ssl/ca.pem' to '/tmp/sandbox/filter_body/client/ca.pem' - Passed
Test : Checking that ReturnCode == 1 - Passed
Reason: Returned Value: 1 == 1
Time-Out : Process finishes within expected time - Passed
Reason: Returned value: 5.028980016708374 < 600.0
file /tmp/sandbox/filter_body/_output/0-tr-Default/stream.stdout.txt : There should be no Proxy Verifier violation errors. - Failed
Reason: Contents of /tmp/sandbox/filter_body/_output/0-tr-Default/stream.stdout.txt contains expression: "Violation|Invalid status"
Details:
[ERROR]: HTTP/1 Status Violation: expected 502 got 200, key: request-block-test : 57
Process: ts: Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts - Passed
Setting up : Copying '/tmp/ats/bin' to '/tmp/sandbox/filter_body/ts/bin' - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/config - Passed
Setting up : On /tmp/sandbox/filter_body/ts/config with uid: nobody gid: nobody - Passed
Setting up : On /tmp/sandbox/filter_body/ts/config with uid: nobody gid: nogroup - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/min_cfg/ip_allow.yaml' to directory '/tmp/sandbox/filter_body/ts/config' as 'ip_allow.yaml'' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/min_cfg/storage.config' to directory '/tmp/sandbox/filter_body/ts/config' as 'storage.config'' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/min_cfg/readme.txt' to directory '/tmp/sandbox/filter_body/ts/config' as 'readme.txt'' - Passed
Setting up : Copying '/tmp/ats/etc/trafficserver/body_factory' to '/tmp/sandbox/filter_body/ts/config/body_factory' - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/cache - Passed
Setting up : Copying '/tmp/ats/libexec/trafficserver' to '/tmp/sandbox/filter_body/ts/plugin' - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/log - Passed
Setting up : On /tmp/sandbox/filter_body/ts/log with uid: nobody gid: nobody - Passed
Setting up : On /tmp/sandbox/filter_body/ts/log with uid: nobody gid: nogroup - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/runtime - Passed
Setting up : On /tmp/sandbox/filter_body/ts/runtime with uid: nobody gid: nobody - Passed
Setting up : On /tmp/sandbox/filter_body/ts/runtime with uid: nobody gid: nogroup - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/ssl - Passed
Setting up : On /tmp/sandbox/filter_body/ts/ssl with uid: nobody gid: nobody - Passed
Setting up : On /tmp/sandbox/filter_body/ts/ssl with uid: nobody gid: nogroup - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/storage - Passed
Setting up : On /tmp/sandbox/filter_body/ts/storage with uid: nobody gid: nobody - Passed
Setting up : On /tmp/sandbox/filter_body/ts/storage with uid: nobody gid: nogroup - Passed
Setting up : recycling port: 61884, queue size: 970 - Passed
Setting up : recycling port: 61885, queue size: 969 - Passed
Setting up : recycling port: 61886, queue size: 968 - Passed
Setting up : recycling port: 61887, queue size: 967 - Passed
Setting up : Making Directory /tmp/sandbox/filter_body/ts/config/config - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/pluginTest/filter_body/config' to '/tmp/sandbox/filter_body/ts/config/config' - Passed
Test : Checking that ReturnCode == 0 - Passed
Reason: Returned Value: 0 == 0
Time-Out : Process finishes within expected time - Passed
Reason: Returned value: 6.02971339225769 < 600.0
file /tmp/sandbox/filter_body/ts/log/diags.log : Verify request log rule matched - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/diags.log contained expression
file /tmp/sandbox/filter_body/ts/log/diags.log : Verify request block rule matched - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/diags.log contained expression
file /tmp/sandbox/filter_body/ts/log/diags.log : Verify request header rule matched - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/diags.log contained expression
file /tmp/sandbox/filter_body/ts/log/diags.log : Verify response log rule matched - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/diags.log contained expression
file /tmp/sandbox/filter_body/ts/log/diags.log : Verify response header rule matched - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/diags.log contained expression
file /tmp/sandbox/filter_body/ts/log/diags.log : Verify response block rule matched - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/diags.log contained expression
file /tmp/sandbox/filter_body/ts/log/traffic.out : Verify request blocking action was taken - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/traffic.out contained expression
file /tmp/sandbox/filter_body/ts/log/traffic.out : Verify header was added for request - Passed
Reason: Contents of /tmp/sandbox/filter_body/ts/log/traffic.out contained expression
Appending File /tmp/sandbox/filter_body/ts/config/records.yaml : Writing config file records.yaml - Passed
Reason: Success
Appending File /tmp/sandbox/filter_body/ts/config/runroot.yaml : Appended file /tmp/sandbox/filter_body/ts/config/runroot.yaml - Passed
Reason: Success
Appending File /tmp/sandbox/filter_body/ts/config/remap.config : Appended file /tmp/sandbox/filter_body/ts/config/remap.config - Passed
Reason: Success
Most relevantly:
Process: Default: Failed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/.git/proxy-verifier-v2.12.0/linux-amd64' to '/tmp/sandbox/filter_body/client/bin' - Passed
Setting up : Copying 'filter_body.replay.yaml' to '/tmp/sandbox/filter_body/client/filter_body.replay.yaml' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/../../tools/proxy-verifier/ssl/client.pem' to '/tmp/sandbox/filter_body/client/client.pem' - Passed
Setting up : Copying '/home/jenkins/workspace/Github_Builds/autest/src/tests/gold_tests/autest-site/../../tools/proxy-verifier/ssl/ca.pem' to '/tmp/sandbox/filter_body/client/ca.pem' - Passed
Test : Checking that ReturnCode == 1 - Passed
Reason: Returned Value: 1 == 1
Time-Out : Process finishes within expected time - Passed
Reason: Returned value: 5.028980016708374 < 600.0
file /tmp/sandbox/filter_body/_output/0-tr-Default/stream.stdout.txt : There should be no Proxy Verifier violation errors. - Failed
Reason: Contents of /tmp/sandbox/filter_body/_output/0-tr-Default/stream.stdout.txt contains expression: "Violation|Invalid status"
Details:
[ERROR]: HTTP/1 Status Violation: expected 502 got 200, key: request-block-test : 57
So that request was supposed to be blocked, but instead it went through and received a 200 OK response.
Attaching the autest sandbox, in case that's helpful.