Intermittent failure on AuTest (double)

[masaori335]

AuTest (double) is smoking. I saw some failures with unrelated changes.

https://ci.trafficserver.apache.org/view/github/job/autest-github/15874/console
https://ci.trafficserver.apache.org/view/github/job/autest-github/15876/console
https://ci.trafficserver.apache.org/view/github/job/autest-github/15889/console

 Test: double: Failed
    File: double.test.py
    Directory: /var/jenkins/workspace/autest-github/src/tests/gold_tests/continuations
   Starting Test double : No issues found - Passed
      Reason: Started!
   Process: ts: Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/15876/install/bin' to '/var/tmp/ausb-7765.15876/double/ts/bin' - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/config - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/config with uid: nobody gid: nobody - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/config with uid: nobody gid: nogroup - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/src/tests/gold_tests/autest-site/min_cfg/ip_allow.yaml' to directory '/var/tmp/ausb-7765.15876/double/ts/config' as 'ip_allow.yaml'' - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/src/tests/gold_tests/autest-site/min_cfg/readme.txt' to directory '/var/tmp/ausb-7765.15876/double/ts/config' as 'readme.txt'' - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/src/tests/gold_tests/autest-site/min_cfg/storage.config' to directory '/var/tmp/ausb-7765.15876/double/ts/config' as 'storage.config'' - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/15876/install/etc/trafficserver/body_factory' to '/var/tmp/ausb-7765.15876/double/ts/config/body_factory' - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/cache - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/15876/install/libexec/trafficserver' to '/var/tmp/ausb-7765.15876/double/ts/plugin' - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/log - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/log with uid: nobody gid: nobody - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/log with uid: nobody gid: nogroup - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/runtime - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/runtime with uid: nobody gid: nobody - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/runtime with uid: nobody gid: nogroup - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/config/snapshots - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/ssl - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/ssl with uid: nobody gid: nobody - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/ssl with uid: nobody gid: nogroup - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/ts/storage - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/storage with uid: nobody gid: nobody - Passed
     Setting up : On /var/tmp/ausb-7765.15876/double/ts/storage with uid: nobody gid: nogroup - Passed
     Setting up : recycling port - Passed
     Setting up : recycling port - Passed
     Setting up : recycling port - Passed
     Setting up : recycling port - Passed
     Setting up : Copying '/var/jenkins/workspace/autest-github/src/tests/tools/plugins/.libs/continuations_verify.so' to '/var/tmp/ausb-7765.15876/double/ts/plugin' - Passed
     Test : Checking that ReturnCode == 2 - Passed
        Reason: Returned Value: 2 == 2
     Time-Out : Process finishes within expected time - Passed
        Reason: Returned value: 69.81501722335815 < 600.0
     file /var/tmp/ausb-7765.15876/double/ts/log/diags.log : diags.log should not contain errors - Passed
        Reason: Contents of /var/tmp/ausb-7765.15876/double/ts/log/diags.log excludes expression
     file /var/tmp/ausb-7765.15876/double/ts/log/diags.log : diags.log should not contain errors - Passed
        Reason: Contents of /var/tmp/ausb-7765.15876/double/ts/log/diags.log excludes expression
     file /var/tmp/ausb-7765.15876/double/ts/log/diags.log : diags.log should not contain a warning about an unrecognized configuration - Passed
        Reason: Contents of /var/tmp/ausb-7765.15876/double/ts/log/diags.log excludes expression
     Appending File /var/tmp/ausb-7765.15876/double/ts/config/records.config : Writing config file records.config - Passed
        Reason: Success
     Appending File /var/tmp/ausb-7765.15876/double/ts/config/remap.config : Appended file /var/tmp/ausb-7765.15876/double/ts/config/remap.config - Passed
        Reason: Success
     Appending File /var/tmp/ausb-7765.15876/double/ts/config/plugin.config : Appended file /var/tmp/ausb-7765.15876/double/ts/config/plugin.config - Passed
        Reason: Success
   Process: server: Passed
     Setting up : recycling port - Passed
     Setting up : Making Directory /var/tmp/ausb-7765.15876/double/server - Passed
     Test : Checking that any test passes - Passed
        Reason: One or more tests passed
     
       Test : Checking that ReturnCode == None - Failed
          Reason: Returned Value 0 != None
       
     
       Test : Checking that ReturnCode == 0 - Passed
          Reason: Returned Value: 0 == 0
       
     Time-Out : Process finishes within expected time - Passed
        Reason: Returned value: 69.01157569885254 < 600.0
   Run: 0-tr: Passed
     Process: cmdline-0: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
     Process: cmdline-1: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
     Process: cmdline-2: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
     Process: cmdline-3: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
     Process: cmdline-4: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.7505598068237305 < 600.0
     Process: cmdline-5: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.741208791732788 < 600.0
     Process: cmdline-6: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.7325730323791504 < 600.0
     Process: cmdline-7: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.723782777786255 < 600.0
     Process: cmdline-8: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.232367992401123 < 600.0
     Process: cmdline-9: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.7020814418792725 < 600.0
     Process: cmdline-10: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.213714838027954 < 600.0
     Process: cmdline-11: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6862549781799316 < 600.0
     Process: cmdline-12: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.200254201889038 < 600.0
     Process: cmdline-13: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6716248989105225 < 600.0
     Process: cmdline-14: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.185737609863281 < 600.0
     Process: cmdline-15: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.655787706375122 < 600.0
     Process: cmdline-16: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.17113471031189 < 600.0
     Process: cmdline-17: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.640181064605713 < 600.0
     Process: cmdline-18: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.15545392036438 < 600.0
     Process: cmdline-19: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6238503456115723 < 600.0
     Process: cmdline-20: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.140813589096069 < 600.0
     Process: cmdline-21: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 4.132378339767456 < 600.0
     Process: cmdline-22: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6994762420654297 < 600.0
     Process: cmdline-23: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6906256675720215 < 600.0
     Process: cmdline-24: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.682701349258423 < 600.0
     Process: cmdline-25: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6688570976257324 < 600.0
     Process: cmdline-26: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6604905128479004 < 600.0
     Process: cmdline-27: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6525325775146484 < 600.0
     Process: cmdline-28: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.637913703918457 < 600.0
     Process: cmdline-29: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6264986991882324 < 600.0
     Process: cmdline-30: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.615211248397827 < 600.0
     Process: cmdline-31: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6040611267089844 < 600.0
     Process: cmdline-32: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6941428184509277 < 600.0
     Process: cmdline-33: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6831843852996826 < 600.0
     Process: cmdline-34: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.673107624053955 < 600.0
     Process: cmdline-35: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6638307571411133 < 600.0
     Process: cmdline-36: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.652064561843872 < 600.0
     Process: cmdline-37: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.633286476135254 < 600.0
     Process: cmdline-38: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.620851755142212 < 600.0
     Process: cmdline-39: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6090285778045654 < 600.0
     Process: cmdline-40: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6994457244873047 < 600.0
     Process: cmdline-41: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.688936710357666 < 600.0
     Process: cmdline-42: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.678330898284912 < 600.0
     Process: cmdline-43: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6678574085235596 < 600.0
     Process: cmdline-44: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6575303077697754 < 600.0
     Process: cmdline-45: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6468281745910645 < 600.0
     Process: cmdline-46: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.634878396987915 < 600.0
     Process: cmdline-47: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.623868942260742 < 600.0
     Process: cmdline-48: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.612854480743408 < 600.0
     Process: cmdline-49: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6015424728393555 < 600.0
     Process: cmdline-50: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.691465139389038 < 600.0
     Process: cmdline-51: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.6769354343414307 < 600.0
     Process: cmdline-52: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.661311149597168 < 600.0
     Process: cmdline-53: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Failed
            Reason: Returned Value 52 != 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 52 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.646991014480591 < 600.0
     Process: Default: Passed
       Test : Checking that any test passes - Passed
          Reason: One or more tests passed
       
         Test : Checking that ReturnCode == 0 - Passed
            Reason: Returned Value: 0 == 0
         
       
         Test : Checking that ReturnCode == 2 - Failed
            Reason: Returned Value 0 != 2
         
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 3.626943349838257 < 600.0
   Run: Curl Done: Failed
     Test : Checking that True == _isRunningAfter - Passed
        Reason: Returned Value: True == _isRunningAfter
     Starting TestRun 1-tr : No Issues found - Passed
        Reason: Started!
     Process: Default: Failed
       Test : Checking that ReturnCode == 0 - Failed
          Reason: Returned Value 1 != 0
       Time-Out : Process finishes within expected time - Passed
          Reason: Returned value: 60.43250012397766 < 600.0
   Run: Check Ssn: Failed
     Test : Checking that True == _isRunningAfter - Passed
        Reason: Returned Value: True == _isRunningAfter
     Starting TestRun 2-tr : No Issues found - Passed
        Reason: Started!
     Process: Default: Failed
       Test : Checking that ReturnCode == 0 - Passed
          Reason: Returned Value: 0 == 0
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should verify contents - Passed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt contained expression
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should be nonzero - Passed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt excludes expression
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should be nonzero - Passed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt excludes expression
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should be nonzero - Passed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt excludes expression
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should be nonzero - Passed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt excludes expression
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should be the number of transactions we made - Failed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt did not contains expression: "continuations_verify.txn.close.1 55"
       file /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt : should be the number of transactions we made - Failed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/2-tr-Default/stream.stdout.txt did not contains expression: "continuations_verify.txn.close.2 55"
   Run: Check Txn: Passed
     Process: Default: Passed
       Test : Checking that ReturnCode == 0 - Passed
          Reason: Returned Value: 0 == 0
       file /var/tmp/ausb-7765.15876/double/_output/3-tr-Default/stream.stdout.txt : should verify contents - Passed
          Reason: Contents of /var/tmp/ausb-7765.15876/double/_output/3-tr-Default/stream.stdout.txt contained expression

[bneradt]

Just got bit by this myself. I'll look into this.

[bneradt]

I haven't been able to reproduce this locally yet. I tried running the double test in a loop by itself and it hasn't crashed after over 10 runs.

Looking at the sandbox, it looks like the various issues are due to ATS tripping on an HttpSM.cc assertion:

https://ci.trafficserver.apache.org/autest/ausb-7939.15874/double/_output/double-ts/stream.all.txt

[E. Mgmt] log ==> [TrafficManager] using root directory '/var/tmp/ausb-7939.15874/double/ts'
[Jun 14 12:27:45.949] traffic_server DIAG: (continuations_verify.init) initializing plugin
[Jun 14 12:27:46.022] [ET_NET 1] DIAG: (continuations_verify.hook) order_1 event 60012
[Jun 14 12:27:46.022] [ET_NET 1] DIAG: (continuations_verify.hook) order_2 event 60012
[Jun 14 12:27:46.024] [ET_NET 1] DIAG: (continuations_verify.hook) order_1 event 60014
[Jun 14 12:27:46.024] [ET_NET 1] DIAG: (continuations_verify.hook) order_2 event 60014
[Jun 14 12:27:46.025] [ET_NET 3] DIAG: (continuations_verify.hook) order_1 event 60012
[Jun 14 12:27:46.025] [ET_NET 3] DIAG: (continuations_verify.hook) order_2 event 60012
[Jun 14 12:27:46.025] [ET_NET 3] DIAG: (continuations_verify.hook) order_1 event 60014
[Jun 14 12:27:46.025] [ET_NET 3] DIAG: (continuations_verify.hook) order_2 event 60014
Fatal: HttpSM.cc:1612: failed assertion `false`
Traffic Server 10.0.0 Jun 14 2021 12:21:59 docker-gd-1
traffic_server: using root directory '/var/tmp/ausb-7939.15874/double/ts'
[Jun 14 12:27:46.028] traffic_crashlo NOTE: crashlog started, target=7356, debug=false syslog=true, uid=989 euid=989
[Jun 14 12:27:46.028] traffic_crashlo WARNING: failed to initialize management API: [5] Error establishing socket connection.
[Jun 14 12:27:46.028] traffic_crashlo NOTE: logging to 0x6f6d60
[Jun 14 12:27:46.029] traffic_crashlo ERROR: wrote crash log to /var/tmp/ausb-7939.15874/double/ts/log/crash-2021-06-14-122746.log
traffic_server: received signal 6 (Aborted)
traffic_server - STACK TRACE: 
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_Z19crash_logger_invokeiP9siginfo_tPv+0xc3)[0x786e44]
/lib64/libpthread.so.0(+0xf630)[0x2ab9050fb630]
/lib64/libc.so.6(gsignal+0x37)[0x2ab905d61387]
/lib64/libc.so.6(abort+0x148)[0x2ab905d62a78]
/var/jenkins/workspace/autest-github/15874/install/lib/libtscore.so.10(_Z11ink_warningPKcz+0x0)[0x2ab90398ad24]
/var/jenkins/workspace/autest-github/15874/install/lib/libtscore.so.10(_Z17ats_base64_encodePKhmPcmPm+0x0)[0x2ab90398692e]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN6HttpSM17state_api_calloutEiPv+0xcea)[0x82cbce]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN6HttpSM12main_handlerEiPv+0x42b)[0x832eab]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN12Continuation11handleEventEiPv+0xc9)[0x78d0a9]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server[0xad3724]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server[0xad3fbc]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server[0xad467c]
[Jun 14 12:27:46.034] [ET_NET 2] DIAG: (continuations_verify.hook) order_1 event 60012
[Jun 14 12:27:46.034] [ET_NET 2] DIAG: (continuations_verify.hook) order_2 event 60012
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN18UnixNetVConnection11net_read_ioEP10NetHandlerP7EThread+0x2b)[0xad6f91]
[Jun 14 12:27:46.035] [ET_NET 2] DIAG: (continuations_verify.hook) order_1 event 60014
[Jun 14 12:27:46.035] [ET_NET 2] DIAG: (continuations_verify.hook) order_2 event 60014
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN10NetHandler18process_ready_listEv+0xb6)[0xac8460]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN10NetHandler15waitForActivityEl+0x427)[0xac8a89]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN7EThread15execute_regularEv+0x3ff)[0xb3808d]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server(_ZN7EThread7executeEv+0x107)[0xb3828f]
/var/tmp/ausb-7939.15874/double/ts/bin/traffic_server[0xb36a14]
/lib64/libpthread.so.0(+0x7ea5)[0x2ab9050f3ea5]
/lib64/libc.so.6(clone+0x6d)[0x2ab905e298dd]

Note in particular:

Fatal: HttpSM.cc:1612: failed assertion `false`

That's the default case in a switch:
https://github.com/apache/trafficserver/blob/4e14f48345cc77130fb44d55e29485e8fc8fd0d5/proxy/http/HttpSM.cc#L1611-#L1614

[bneradt]

I managed to reproduce the problem on my fifteenth iteration of the test. That's rare enough that it might be hard to do a git bisect on our recent commits to see what has introduced this. I'll make an attempt.

[bneradt]

Summary:

It looks like #7849 introduced the flakiness into the double.test.py test.

---

Process

I used git bisect to find the commit which introduced the flakiness, with each bisect run running the double.test.py AuTest 30 times. If it passed all thirty, then the bisect iteration was considered a success. Using this method, git bisect found this to be the commit that introduced the flakey behavior in double.test.py:

f839a74aadd3f4956d133be7fefbe4194b3be8bb is the first bad commit
commit f839a74aadd3f4956d133be7fefbe4194b3be8bb
Author: Susan Hinrichs <shinrich@verizonmedia.com>
Date:   Thu Jun 3 08:25:52 2021 -0500

    Make HttpSM server reference a Transaction instead of a Session (#7849)

To verify this result manually, I built the parent of this commit (01d2150) and ran the double test 50 times and it passed each time. I then re-checked out f839a74, rebuilt, and ran the test in a loop and it failed on the third iteration.

Reproduction

This can be reproduced using our CI's centos:8 docker container like so:

docker pull controller.trafficserver.org/ats/centos:8
docker run \
    --name reproduce_double_test_flakiness \
    --init \
    --cap-add=SYS_PTRACE \
    -d \
    -t \
    controller.trafficserver.org/ats/centos:8

docker exec -it reproduce_double_test_flakiness /bin/bash

# From within the container now.
cd /var/tmp
git clone https://github.com/apache/trafficserver.git
cd trafficserver
source /opt/rh/gcc-toolset-9/enable

autoreconf -fi
./configure \
    --prefix /var/tmp/trafficserver_build \
    --with-openssl=/opt/openssl-quic \
    --enable-experimental-plugins \
    --enable-example-plugins \
    --enable-werror \
    --enable-debug \
    --enable-wccp
make -j4
make install

# Now run the tests 50 times and make sure it succeeds all of the iterations.
cd tests
for i in {1..50}; do ./autest.sh --sandbox /tmp/sb --ats-bin /var/tmp/trafficserver_build/bin/ --clean=none -f double || break ; done

# If it fails, you'll see the standard AuTest error output.

[bneradt]

In case it's helpful, I reproduced this with http debug tag logging. Here is the debug output leading up to the assertion:

+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 15
HTTP/1.1 200 OK^M
Connection: close^M
Content-Length: 0^M
Date: Wed, 16 Jun 2021 23:05:39 GMT^M 
^M
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 15
HTTP/1.1 200 OK^M
Content-Length: 0^M
Date: Wed, 16 Jun 2021 23:05:39 GMT^M 
Age: 0^M
Connection: keep-alive^M
Server: ATS/10.0.0^M
^M
[Jun 16 23:05:39.178] [ET_NET 2] DEBUG: <HttpSM.cc:7387 (call_transact_and_set_next_state)> (http) [15] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ
[Jun 16 23:05:39.178] [ET_NET 2] DEBUG: <HttpSM.cc:8162 (is_redirect_required)> (http_redirect) is_redirect_required 0
[Jun 16 23:05:39.178] [ET_NET 2] DEBUG: <HttpSM.cc:6756 (setup_server_transfer)> (http) Setup Server Transfer
[Jun 16 23:05:39.178] [ET_NET 2] DEBUG: <HttpTunnel.cc:596 (add_producer)> (http_tunnel) [15] adding producer 'http server'
[Jun 16 23:05:39.178] [ET_NET 2] DEBUG: <HttpTunnel.cc:651 (add_consumer)> (http_tunnel) [15] adding consumer 'user agent'
[Jun 16 23:05:39.178] [ET_NET 2] DEBUG: <HttpSM.cc:6006 (perform_cache_write_action)> (http) [15] perform_cache_write_action CACHE_DO_NO_ACTION
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpTunnel.cc:698 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpTunnel.cc:975 (producer_run)> (http_tunnel) [15] [tunnel_run] producer already done
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpTunnel.cc:1104 (producer_handler)> (http_tunnel) [15] producer_handler [http server HTTP_TUNNEL_EVENT_PRECOMPLETE]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpTunnel.cc:1147 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 2302, state: 0
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:3049 (tunnel_handler_server)> (http) [15] [&HttpSM::tunnel_handler_server, HTTP_TUNNEL_EVENT_PRECOMPLETE]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <Http1ServerSession.cc:121 (do_io_close)> (http_ss) [31] session close: nevtc 0x14ca0001f840
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpTunnel.cc:1310 (consumer_handler)> (http_tunnel) [15] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:3328 (tunnel_handler_ua)> (http) [15] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:2708 (main_handler)> (http) [15] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:2998 (tunnel_handler)> (http) [15] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:8328 (clear)> (http_redirect) [PostDataBuffers::clear]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:2708 (main_handler)> (http) [15] [HttpSM::main_handler, VC_EVENT_EOS/TS_EVENT_VCONN_EOS]
[Jun 16 23:05:39.179] [ET_NET 2] DEBUG: <HttpSM.cc:1468 (state_api_callout)> (http) [15] [&HttpSM::state_api_callout, VC_EVENT_EOS/TS_EVENT_VCONN_EOS]
Fatal: HttpSM.cc:1612: failed assertion `false`

The entire output for the failed test is attached as: stream.all.txt