Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Timeout #4

Closed
lechat opened this issue May 14, 2013 · 3 comments
Closed

Timeout #4

lechat opened this issue May 14, 2013 · 3 comments

Comments

@lechat
Copy link
Collaborator

lechat commented May 14, 2013

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 <module>
    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!
@lhupfeldt
Copy link
Owner

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" notifications@github.com:

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
Copy link
Owner

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
Copy link
Collaborator Author

lechat commented May 15, 2013

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@lechat @lhupfeldt