New issue
Advanced search Search tips

Issue 708049 link

Starred by 1 user

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux
Pri: 3
Type: Bug



Sign in to add a comment

infra.libs.git2.test.repo_test.TestRepo.testFastForwardWithTimeoutOk flake

Project Member Reported by dsansome@chromium.org, Apr 4 2017

Issue description

https://luci-logdog.appspot.com/v/?s=chromium%2Fbb%2Fchromium.infra%2Finfra-continuous-precise-64%2F6525%2F%2B%2Frecipes%2Fsteps%2Fcipd_-_test_packages_integrity%2F0%2Fstdout

======================================================================
ERROR: infra.libs.git2.test.repo_test.TestRepo.testFastForwardWithTimeoutOk (/tmp/tmpGcRN4ecipd_test/infra_python/infra/libs/git2/test/repo_test.expected/TestRepo.testFastForwardWithTimeoutOk.json)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/expect_tests/pipeline.py", line 397, in process_test
    subresult = subtest.run()
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/expect_tests/type_definitions.py", line 240, in run
    return self.func_call(context=context)
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/expect_tests/type_definitions.py", line 155, in __call__
    return f.func(*f.args, **f.kwargs)
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/expect_tests/unittest_helper.py", line 47, in _RunTestCaseSingle
    test_instance.tearDown()
  File "/tmp/tmpGcRN4ecipd_test/infra_python/infra/libs/git2/test/test_util.py", line 53, in tearDown
    super(TestBasis, self).tearDown()
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/testing_support/git/unittest_helpers.py", line 49, in tearDown
    super(GitRepoTestBase, self).tearDown()
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/testing_support/auto_stub.py", line 76, in tearDown
    super(TestCase, self).tearDown()
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/testing_support/thread_watcher.py", line 69, in tearDown
    ThreadWatcherMixIn.tearDown(self)
  File "/tmp/tmpGcRN4ecipd_test/infra_python/.cipd/pkgs/0/d678f9de2915aa446ed065ec380ee4e61a19a515/ENV/lib/python2.7/site-packages/testing_support/thread_watcher.py", line 41, in tearDown
    len(new_threads), details))
  File "/usr/lib/python2.7/unittest/case.py", line 408, in fail
    raise self.failureException(msg)
AssertionError: Found 1 running thread(s) after the test.

Thread <_Timer(Thread-7, started 140447092324096)> stacktrace:
  File "/usr/lib/python2.7/threading.py", line 528, in __bootstrap
    raise
  File "/usr/lib/python2.7/threading.py", line 605, in __bootstrap_inner
    pass
  File "/usr/lib/python2.7/threading.py", line 760, in run
    self.finished.set()
  File "/usr/lib/python2.7/threading.py", line 406, in wait
    self.__cond.release()
  File "/usr/lib/python2.7/threading.py", line 262, in wait
    _sleep(delay)


==== captured logging output ====
LOG:
INFO: making repos dir: /tmp/tmpZFsFtu.expect_tests_temp/tmppy_8QM.git_test/repos
DEBUG: initializing Repo('/tmp/tmpZFsFtu.expect_tests_temp/git_repoGqifiJbase/tmpEBU2XI') -> '/tmp/tmpZFsFtu.expect_tests_temp/tmppy_8QM.git_test/repos/-tmp-tmpzfsftu.expect_tests_temp-git_repogqifijbase-tmpebu2xi'
DEBUG: Running ('git', 'init', '--bare', 'tmp9uTv5Y')
DEBUG: Running ('git', 'remote', 'add', '--mirror=fetch', 'origin', '/tmp/tmpZFsFtu.expect_tests_temp/git_repoGqifiJbase/tmpEBU2XI')
DEBUG: Running ('git', 'fetch')
DEBUG: Miss a5963996cb3f6e49a1b5630933c5ef4590dac009
DEBUG: Running ('git', 'cat-file', 'commit', 'a5963996cb3f6e49a1b5630933c5ef4590dac009')
INFO: Running ('git', 'push', 'origin', 'a5963996cb3f6e49a1b5630933c5ef4590dac009:refs/heads/branch_O')
DEBUG: Running ('git', 'rev-parse', 'refs/heads/branch_O')
DEBUG: Hit a5963996cb3f6e49a1b5630933c5ef4590dac009
DEBUG: Running ('git', 'rev-parse', 'refs/heads/branch_O')
DEBUG: Hit a5963996cb3f6e49a1b5630933c5ef4590dac009
DEBUG: Running ('git', 'merge-base', '--is-ancestor', 'a5963996cb3f6e49a1b5630933c5ef4590dac009', 'a5963996cb3f6e49a1b5630933c5ef4590dac009')
DEBUG: Running ('git', 'update-ref', 'refs/heads/branch_O', 'a5963996cb3f6e49a1b5630933c5ef4590dac009')
DEBUG: Running ('git', 'rev-parse', 'refs/heads/branch_O')
DEBUG: Hit a5963996cb3f6e49a1b5630933c5ef4590dac009

STDOUT:
1969-12-31 08:25:45PM (): line2
1969-12-31 08:25:45PM (): line1
timestamp_kind: END
event_source {
  host_name: "vm25-m1.golo.chromium.org"
  service_name: "buildbot/master/chromium.infra"
}
build_event {
  type: STEP
  host_name: "vm25-m1"
  build_name: "infra-continuous-precise-64"
  build_number: 5
  build_scheduling_time_ms: 1434665160000
  step_name: "cipd - test packages integrity"
  step_number: 9
}

Generating /tmp/tmpZFsFtu.expect_tests_temp/new-tool-test-WnYY2F/whatever_tool...
Done.

STDERR:
WARNING: Querying for all resources under a service, this may take a long time...
NOTE: All times are in local system time (-7 hour(s)).
Still working... (Job ID: SomeID)
usage: expect_tests [-h] [--list-all-states] [--builder-filter BUILDER_FILTER]
                    [--drain-timeout SECONDS] [--enable-gclient-sync]
                    [--emergency-file EMERGENCY_FILE] [--hostname HOSTNAME]
                    [--prod] [--loop] [--loop-sleep-secs LOOP_SLEEP_SECS]
                    [--connection-timeout CONNECTION_TIMEOUT] [--duration SEC]
                    [--max-errors COUNT] [--max_errors COUNT]
                    [--logs-quiet | --logs-warning | --logs-verbose | --logs-debug]
                    [--logs-black-list REGEX]
                    [--logs-directory LOGS_DIRECTORY]
                    [--logs-program-name LOGS_PROGRAM_NAME]
                    [--logs-debug-file]
                    [--ts-mon-config-file TS_MON_CONFIG_FILE]
                    [--ts-mon-endpoint TS_MON_ENDPOINT]
                    [--ts-mon-credentials TS_MON_CREDENTIALS]
                    [--ts-mon-ca-certs TS_MON_CA_CERTS]
                    [--ts-mon-flush {manual,auto}]
                    [--ts-mon-flush-interval-secs TS_MON_FLUSH_INTERVAL_SECS]
                    [--ts-mon-autogen-hostname]
                    [--ts-mon-target-type {device,task}]
                    [--ts-mon-device-hostname TS_MON_DEVICE_HOSTNAME]
                    [--ts-mon-device-region TS_MON_DEVICE_REGION]
                    [--ts-mon-device-role TS_MON_DEVICE_ROLE]
                    [--ts-mon-device-network TS_MON_DEVICE_NETWORK]
                    [--ts-mon-task-service-name TS_MON_TASK_SERVICE_NAME]
                    [--ts-mon-task-job-name TS_MON_TASK_JOB_NAME]
                    [--ts-mon-task-region TS_MON_TASK_REGION]
                    [--ts-mon-task-hostname TS_MON_TASK_HOSTNAME]
                    [--ts-mon-task-number TS_MON_TASK_NUMBER]
                    [--ts-mon-metric-name-prefix TS_MON_METRIC_NAME_PREFIX]
                    [--ts-mon-use-new-proto]
                    [directory] [{drained,offline,quitquitquit,running}]
                    [transition_time_utc]
expect_tests: error: A master directory must be specified.
 
Cc: aga...@chromium.org tandrii@chromium.org
Hm, I haven't looked at any of this code in more than year. agable/tandrii do you know who's working in this area of the codebase (e.g. 'infra') recently?
https://chromium.googlesource.com/infra/infra/+log/master/infra/libs/git2

Basically hasn't been touched in a year and a half, and back then it was still mostly you. *shrug*
It looks like this code+test was added in 9c0ff7ab653cd2aa21d93fb97816c2903d92067c. It has to do with threads and timeouts... I suspect it's inherently racy.

How often is this flaking?

It would probably be better to rewrite it to use http.lowSpeedTime+http.lowSpeedLimit instead of a thread.

Comment 4 by iannu...@google.com, May 10 2017

Owner: iannu...@google.com
bulk reassign to my google account
Owner: iannucci@chromium.org
reassign to my chromium.org account! I was holding it wrong, apparently.
Owner: iannu...@google.com

Sign in to add a comment