Timeout about jenkinsflow

[lhupfeldt]

Hi Aleksey,

That looks strange as it seems to have timed out before the 70 seconds
specified. I will try to reproduce it. In the mean time please try raising
the timeouts. But why are the jobs running for so long if all they do is
uname?

Venlig hilsen,
Lars
Den 14/05/2013 03.39 skrev "Aleksey Maksimov" [email protected]:

Hi!

In my Jenkins 1.484 I created 3 simple jobs: flow-1, flow-2 and flow-3.
Each job does 'uname -a'.

I created simple flow:

with serial(api, timeout=70, job_name_prefix='ADMIN-', report_interval=3) as ctrl1:
    ctrl1.invoke('flow-1')

    with ctrl1.parallel(timeout=20, report_interval=3) as ctrl2:
        ctrl2.invoke('flow-2')
        ctrl2.invoke('flow-3')

    ctrl1.invoke('flow-1')

And this happened:

Started by user 1459847
[EnvInject] - Loading node environment variables.
Building on master in workspace /shared/opt/jenkins-home/jobs/ADMIN-python-test/workspace
[workspace] $ /home/sabredev/virtualenv/jenkins/bin/python /tmp/shiningpanda1946216512484119647.py
['/tmp', '/home/sabredev/virtualenv/jenkins/lib/python2.7/site-packages/setuptools-0.6c11-py2.7.egg', '/home/sabredev/virtualenv/jenkins/lib/python2.7/site-packages/pip-1.3.1-py2.7.egg', '/home/sabredev/virtualenv/jenkins/lib/python27.zip', '/home/sabredev/virtualenv/jenkins/lib/python2.7', '/home/sabredev/virtualenv/jenkins/lib/python2.7/plat-linux2', '/home/sabredev/virtualenv/jenkins/lib/python2.7/lib-tk', '/home/sabredev/virtualenv/jenkins/lib/python2.7/lib-old', '/home/sabredev/virtualenv/jenkins/lib/python2.7/lib-dynload', '/usr/local/scbpkg/lib/python2.7', '/usr/local/scbpkg/lib/python2.7/plat-linux2', '/usr/local/scbpkg/lib/python2.7/lib-tk', '/home/sabredev/virtualenv/jenkins/lib/python2.7/site-packages', '/home/sabredev/src']
== Legend ==
Serial builds: []
Parallel builds: ()
Invoking (w/x,y/z): w=current invocation in current flow scope, x=max in scope, y=total number of invocations, z=total max invocations
Elapsed time: 'after: x/y': x=time spent during current run of job, y=time elapsed since start of outermost flow

Queuing jobs for serial run: [
Queuing job: ADMIN-flow-1 'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #2
Queuing jobs for parallel run: (
Queuing job: ADMIN-flow-2 'ADMIN-flow-2' Status IDLE - latest build: ADMIN-flow-2 #1
Queuing job: ADMIN-flow-3 'ADMIN-flow-3' Status IDLE - latest build: ADMIN-flow-3 #1
)

Queuing job: ADMIN-flow-1 'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #2
]

Invoking (1/1,1/1): ['ADMIN-flow-1', ('ADMIN-flow-2', 'ADMIN-flow-3'), 'ADMIN-flow-1']

Invoking (1/1,1/1): http://sabrebuild1.uk.standardchartered.com:8080/job/ADMIN-flow-1 - /build
'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #2
'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #3
SUCCESS: 'ADMIN-flow-1' - build: http://sabrebuild1.uk.standardchartered.com:8080/job/ADMIN-flow-1/3/testReport/api/python/ after: 23.850s/23.850s
Invoking (1/1,1/1): ('ADMIN-flow-2', 'ADMIN-flow-3')

Invoking (1/1,1/1): http://sabrebuild1.uk.standardchartered.com:8080/job/ADMIN-flow-2 - /build
'ADMIN-flow-2' Status IDLE - latest build: ADMIN-flow-2 #2
SUCCESS: 'ADMIN-flow-2' - build: http://sabrebuild1.uk.standardchartered.com:8080/job/ADMIN-flow-2/2/testReport/api/python/ after: 17.901s/44.250s

Invoking (1/1,1/1): http://sabrebuild1.uk.standardchartered.com:8080/job/ADMIN-flow-3 - /build
'ADMIN-flow-3' Status IDLE - latest build: ADMIN-flow-3 #1
Traceback (most recent call last):
File "/tmp/shiningpanda1946216512484119647.py", line 41, in
main()
File "/tmp/shiningpanda1946216512484119647.py", line 38, in main
ctrl1.invoke('flow-1')
File "/home/sabredev/src/jenkinsflow/jobcontrol.py", line 413, in exit
self.wait_for_jobs()
File "/home/sabredev/src/jenkinsflow/jobcontrol.py", line 383, in wait_for_jobs
last_report_time = self._check(start_time, last_report_time)
File "/home/sabredev/src/jenkinsflow/jobcontrol.py", line 331, in _check
last_report_time = job._check(start_time, last_report_time)
File "/home/sabredev/src/jenkinsflow/jobcontrol.py", line 263, in _check
self._check_timeout(start_time)
File "/home/sabredev/src/jenkinsflow/jobcontrol.py", line 229, in _check_timeout
raise FlowTimeoutException("Timeout after:" + self._time_msg(start_time) + unfinished_msg)
jenkinsflow.jobcontrol.FlowTimeoutException: Timeout after:after: 36.751s/63.099sUnfinished jobs:('ADMIN-flow-2', 'ADMIN-flow-3')
Build step 'Custom Python Builder' marked build as failure
[BFA] Scanning build for known causes...

[BFA] Done. 0s
Notifying upstream projects of job completion
Finished: FAILURE

Shall I increase timeout in this call?

with serial(api, timeout=70, job_name_prefix='ADMIN-', report_interval=3) as ctrl1:

Thanks!

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/4
.

[lhupfeldt]

Hi, I got home from work and took another look at your problem. It seems your inner parallel flow, with a 20 second timeout is actually the one timing out. I could not reproduce this with such high timeouts, but by lowering the inner timeout to 5 seconds, I got the following:

== Legend ==
Serial builds: []
Parallel builds: ()
Invoking (w/x,y/z): w=current invocation in current flow scope, x=max in scope, y=total number of invocations, z=total max invocations
Elapsed time: 'after: x/y': x=time spent during current run of job, y=time elapsed since start of outermost flow
Queuing jobs for serial run: [
   Queuing job: ADMIN-flow-1 'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #3
   Queuing jobs for parallel run: (
      Queuing job: ADMIN-flow-2 'ADMIN-flow-2' Status IDLE - latest build: ADMIN-flow-2 #2
      Queuing job: ADMIN-flow-3 'ADMIN-flow-3' Status IDLE - latest build: ADMIN-flow-3 #2
   )
   Queuing job: ADMIN-flow-1 'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #3
]
Invoking (1/1,1/1): ['ADMIN-flow-1', ('ADMIN-flow-2', 'ADMIN-flow-3'), 'ADMIN-flow-1']
Invoking (1/1,1/1): http://localhost:8080/job/ADMIN-flow-1 - /build
'ADMIN-flow-1' Status QUEUED - latest build: ADMIN-flow-1 #3
'ADMIN-flow-1' Status IDLE - latest build: ADMIN-flow-1 #4
SUCCESS: 'ADMIN-flow-1' - build:  http://localhost:8080/job/ADMIN-flow-1/4/testReport/api/python/ after: 5.232s/5.232s
Invoking (1/1,1/1): ('ADMIN-flow-2', 'ADMIN-flow-3')
Invoking (1/1,1/1): http://localhost:8080/job/ADMIN-flow-2 - /build
Invoking (1/1,1/1): http://localhost:8080/job/ADMIN-flow-3 - /build
'ADMIN-flow-2' Status QUEUED - latest build: ADMIN-flow-2 #2
'ADMIN-flow-2' Status QUEUED - latest build: ADMIN-flow-2 #2
Traceback (most recent call last):
  File "./aleksey.py", line 53, in 
    main()
  File "./aleksey.py", line 51, in main
    ctrl1.invoke('flow-1')
  File "./../../jenkinsflow/jobcontrol.py", line 413, in __exit__
    self.wait_for_jobs()
  File "./../../jenkinsflow/jobcontrol.py", line 383, in wait_for_jobs
    last_report_time = self._check(start_time, last_report_time)
  File "./../../jenkinsflow/jobcontrol.py", line 331, in _check
    last_report_time = job._check(start_time, last_report_time)
  File "./../../jenkinsflow/jobcontrol.py", line 263, in _check
    self._check_timeout(start_time)
  File "./../../jenkinsflow/jobcontrol.py", line 229, in _check_timeout
    raise FlowTimeoutException("Timeout after:" + self._time_msg(start_time) + unfinished_msg)
jenkinsflow.jobcontrol.FlowTimeoutException: Timeout after:after: 5.383s/11.122sUnfinished jobs:('ADMIN-flow-2', 'ADMIN-flow-3')

This is as expected, the inner flow timed out just after 5 seconds.

I noticed in your example that flow-2 and three did not start in parallel. Have you got enough executors? It also seems that your jenkins is not performing well. My Jenkins finished the flow in 12 seconds.

[lechat]

It may be a case of quite old Jenkins version that we're using here. I will try to run this on latest Jenkins.