Assigning to akeshet@ since I've looked into this and have no idea what's happening. It seems that someone with more knowledge of autotest needs to figure this out.

+deputies +test_that developers

For more info see mzhou thread titled "More than one test scheduled."

-> ayatane who is both the deputy, and also made some changes in suite determination logic which are my first guess as to the cause of this.

I guess this is due to multiple control files which define same NAME existing under  ~/trunk/src/third_party/autotest/files/, although these control files are not in the same directory as enterprise_CFM_Sanity.py.
And they are under directory with random name which is not same as testname.

I fixed the issue by removing all above control files under other dir. 

Looks like this piece of codes (  suite.py: 894) retrieve all control files under  ~/trunk/src/third_party/autotest/files/. 

    retriever = _get_cf_retriever(cf_getter,
                                  forgiving_parser=forgiving_parser,
                                  run_prod_code=run_prod_code,
                                  test_args=test_args)
    tests = retriever.retrieve_for_suite(suite_name)

I am not sure whether it is better to only retrieve control file under directory with name as testname?

If we don't give autotest_dir, what is default value? 
I tried not giving it, however test_that.py fails. 
If I give complete path to enterprise_CFM_Sanity.py it also fails. 
Pls see log below:

(cr) ((f584aba61...)) mzhuo@minzhuo2 ~/trunk/src/scripts $ test_that  --board=guado  100.123.171.253 enterprise_Bluestreak_Sanity
INFO:root:Identity added: /tmp/test_that_results_O0ontn/testing_rsa (/tmp/test_that_results_O0ontn/testing_rsa)
/build/guado/ does not exist. Have you run setup_board?


(cr) ((f584aba61...)) mzhuo@minzhuo2 ~/trunk/src/scripts $ test_that --autotest_dir ~/trunk/src/third_party/autotest/files/server/site_tests/enterprise_Bluestreak_Sanity --board=guado  100.123.171.253 enterprise_Bluestreak_Sanity
INFO:root:Identity added: /tmp/test_that_results_tZhm5U/testing_rsa (/tmp/test_that_results_tZhm5U/testing_rsa)
10:09:45 INFO | Skipping quickmerge step.
10:09:45 INFO | Re-running test_that script in /home/mzhuo/trunk/src/third_party/autotest/files/server/site_tests/enterprise_Bluestreak_Sanity copy of autotest.
Traceback (most recent call last):
  File "/mnt/host/source/src/third_party/autotest/files/site_utils/test_that.py", line 347, in <module>
    sys.exit(main(sys.argv[1:]))
  File "/mnt/host/source/src/third_party/autotest/files/site_utils/test_that.py", line 343, in main
    return _main_for_local_run(argv, arguments)
  File "/mnt/host/source/src/third_party/autotest/files/site_utils/test_that.py", line 288, in _main_for_local_run
    arguments, autotest_path, argv)
  File "/mnt/host/source/src/third_party/autotest/files/site_utils/test_that.py", line 218, in perform_bootstrap_into_autotest_root
    script_command)
autotest_lib.site_utils.test_runner_utils.TestThatRunError: Unable to bootstrap to autotest root, /home/mzhuo/trunk/src/third_party/autotest/files/server/site_tests/enterprise_Bluestreak_Sanity/site_utils/test_that.py not found.
(cr) ((f584aba61...)) mzhuo@minzhuo2 ~/trunk/src/scripts $ 

Re #5

>I guess this is due to multiple control files which define same NAME

Yeah, that would do it.

>I am not sure whether it is better to only retrieve control file under directory with name as testname?

I don't think this change is necessary.  There are cases where directories contain control files with different names, like graphics_Drm.  It should be the test writer's responsibility to name their tests correctly.

>If we don't give autotest_dir, what is default value? 

/build/*/usr/local/build/autotest (check the test_that.py code)

Marking fixed since the "power_Consumption test is run twice" issue is fixed and there is no followup actions.

OP was complaining about power_Consumption, but #5 about enterprise_CFM_Sanity.

I merely suspected they were related, not sure they are.

Is it verified that the same multiple-control-file scenario is responsible for OP's problem?

dbasehore, can you post a link to the autotest job where this occurred?  I cannot reproduce it.

I was reproducing this locally.

Assigning back to ayatane@

Can you elaborate on how you reproduce this, or fish out an occurence in autotest lab? That will make it a lot easier to debug.

Run the test locally.

in a fresh stumpy build, arbitrarily chosen.

(cr) ((7f721ec...)) akeshet@akeshet ~/trunk/src/scripts $ test_that --board=stumpy foo power_Consumption
INFO:root:Identity added: /tmp/test_that_results_zhCWwl/testing_rsa (/tmp/test_that_results_zhCWwl/testing_rsa)
19:59:55 INFO | Running autotest_quickmerge step.
19:59:55 INFO | quickmerge| 19:59:55: INFO: RunCommand: sudo -- /usr/bin/python2 /mnt/host/source/chromite/bin/autotest_quickmerge '--board=stumpy'
19:59:56 INFO | quickmerge| 19:59:56: INFO: RunCommand: rsync -a --no-p '--chmod=ugo=rwX' -u -i '--exclude=**.pyc' '--exclude=**.pyo' '--exclude=** -> *' '--include-from=/mnt/host/source/chromite/scripts/autotest-quickmerge-includepatterns' '--exclude=*' /mnt/host/source/src/third_party/autotest/files/ /build/stumpy/usr/local/build/autotest/
19:59:56 INFO | quickmerge| 19:59:56: INFO: Updating portage database.
19:59:56 INFO | quickmerge| 19:59:56: INFO: RunCommand: rsync -a --no-p '--chmod=ugo=rwX' -u -i '--exclude=**.pyc' '--exclude=**.pyo' '--exclude=** -> *' '--include-from=/mnt/host/source/chromite/scripts/autotest-quickmerge-includepatterns' '--exclude=*' // /build/stumpy/usr/local/build/autotest/
19:59:56 INFO | quickmerge| 19:59:56: INFO: Updating portage database.
19:59:57 INFO | quickmerge| 19:59:57: INFO: RunCommand: rsync -a --no-p '--chmod=ugo=rwX' -u -i '--exclude=**.pyc' '--exclude=**.pyo' '--exclude=** -> *' '--include-from=/mnt/host/source/chromite/scripts/autotest-quickmerge-includepatterns' '--exclude=*' /mnt/host/source/src/third_party/autotest-private/ /build/stumpy/usr/local/build/autotest/
19:59:57 INFO | quickmerge| 19:59:57: INFO: Updating portage database.
19:59:57 INFO | quickmerge| 19:59:57: INFO: RunCommand: touch /build/stumpy/usr/local/build/autotest/.quickmerge_sentinel
19:59:57 INFO | quickmerge| 19:59:57: INFO: Quickmerge complete. Created or modified 0 files.
19:59:57 INFO | Re-running test_that script in /build/stumpy/usr/local/build/autotest copy of autotest.
INFO:root:Identity added: /tmp/test_that_results_wO7SMb/testing_rsa (/tmp/test_that_results_wO7SMb/testing_rsa)
19:59:58 INFO | Began logging to /tmp/test_that_results_wO7SMb
Adding labels [u'cros-version:ad_hoc_build', u'board:stumpy'] to host foo
21:59:58 INFO | Fetching suite for job named power_Consumption...
22:00:01 INFO | Scheduling suite for job named power_Consumption...
22:00:01 INFO | ... scheduled 1 job(s).

[snip]

scheduled 1 job.

(does not reproduce, or insufficient repro instructions, WontFix)

I have an R61 ToT run on veyron_minnie that reproduces this. It doesn't run multiple control files. As I stated when the bug was filed, the run_once method is run twice. You can verify that this is happening by searching for the string "Test groups to run: backlight, download, webpages, video, speedometer, backchannel, sound, lowlevel" in the logs.

Sounds like a bug in the test or in the control file. I invite you to debug it, or provide a link to logs with errant behavior. Does not, on its face, sound like an infra issue.

It looks like the run_once method is getting called twice due to the profile_only being set to false/None. This seems to only be in the client/common_lib code which is maintained by the Infra team. The run_once function is called once from _call_run_once_with_retry and another time through run_once_profiling.

This seems to stem from adding a profiler. Is this the intended default behavior? It seems that the set_only method can be used to change this.

Some git archaeology suggests to me that there have been no substantive profiler changes in several years. Last time they were touched, it was by llozano and cmtice on toolchain.

Hi, this bug has not been updated recently. Please acknowledge the bug and provide status within two weeks (6/22/2018), or the bug will be closed. Thank you.

Wonder if this might be related to autotest_quickmerge looks for control files?

I'd previously found that emacs backup files (ending in ~) were parsed and as such if the testname matched it would queue the job another time for that.

In any case, just tested via,

test_that --fast --autotest_dir ../third_party/autotest/files $IP power_Consumption

and saw only 1 job queued.

11:20:25 INFO | ... scheduled 1 job(s).

Going to close for now.