Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-52432

Pipeline's timeout takes twice the timeout to terminate HubotApprove

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Minor
    • Resolution: Fixed
    • Component/s: hubot-steps-plugin
    • Labels:
      None
    • Environment:
      Jenkins ver. 2.89.4
      Hubot Pipeline Steps 2.0.0
    • Similar Issues:

      Description

      If using hubotApprove inside timeout() in Jenkins (scripted) pipeline effective time it takes to terminate approve request seems to double;

      Example code:
      timestamps {
        timeout(time:15, unit:'SECONDS') {
          env.HUBOT_URL = Constants.HUBOT_URL
          hubotApprove message: "test message",
          room: '#jenkins-devel', submitter: 'mjuuti',
          failOnError: 'true'
         }
      }

      Console output:

      00:00:01.397 Timeout set to expire in 15 sec
      [Pipeline] {
      [Pipeline] hubotApprove
      00:00:01.409 Hubot: ROOM - #jenkins-devel - Approval Message - test message
      00:00:01.568 Hubot: Successful. Code: 200
      00:00:01.571 test message
      00:00:01.572 Proceed  or Abort
      00:00:16.397 Cancelling nested steps due to timeout
      00:00:31.397 Body did not finish within grace period; terminating with extreme prejudice

      e.g. 15 second timeout went off at 16 seconds but process was script body was forcibly terminated only after 15 seconds after that (2x timeout, tested with different values).

      This probably is bug in timeout plugin https://issues.jenkins-ci.org/browse/JENKINS-40839

      But I suppose on improvement side in this plugin try/catch could check first if catch org.jenkinsci.plugins.workflow.steps.FlowInterruptedException (or probably any standard 'abort' exception) has been thrown and then terminate immediately.

      My domain knowledge is minimal at best and Java isn't strong with this one either but I suppose https://github.com/jenkinsci/hubot-steps-plugin/blob/master/src/main/java/org/thoughtslive/jenkins/plugins/hubot/service/HubotService.java#L57 might be the culprit by catching all exceptions and not throwing?

      This happens with both failOnError as 'true' or 'false'

        Attachments

          Activity

          Hide
          nrayapati Naresh Rayapati added a comment - - edited

          Markus Juuti Thanks for reporting, my initial guess is that this is a problem within this plugin but probably not the place where you are pointing at. I will look into this shortly.

          Show
          nrayapati Naresh Rayapati added a comment - - edited Markus Juuti Thanks for reporting, my initial guess is that this is a problem within this plugin but probably not the place where you are pointing at. I will look into this shortly.
          Hide
          nrayapati Naresh Rayapati added a comment -

          Found it and made a pull request: https://github.com/jenkinsci/hubot-steps-plugin/pull/14

          It was a small change in there, will release it soon. Thanks for reporting again.

          Show
          nrayapati Naresh Rayapati added a comment - Found it and made a pull request: https://github.com/jenkinsci/hubot-steps-plugin/pull/14 It was a small change in there, will release it soon. Thanks for reporting again.
          Hide
          nrayapati Naresh Rayapati added a comment -

          Tested this on my local machine:

          Before Fix:

          [Pipeline] timestamps
          [Pipeline] {
          [Pipeline] timeout
          02:35:24 Timeout set to expire after 15 sec without activity
          [Pipeline] {
          [Pipeline] hubotApprove
          02:35:25 Hubot: ROOM - thoughtslive - Approval Message - approve?
          02:35:26 Hubot: Successful. Code: 200
          02:35:26 approve?
          02:35:26 Proceed or Abort
          02:35:41 Cancelling nested steps due to timeout
          02:35:56 Body did not finish within grace period; terminating with extreme prejudice
          [Pipeline] }
          [Pipeline] // timeout
          [Pipeline] }
          [Pipeline] // timestamps
          [Pipeline] End of Pipeline
          

          After Fix:

          [Pipeline] timestamps
          [Pipeline] {
          [Pipeline] timeout
          02:39:26 Timeout set to expire after 15 sec without activity
          [Pipeline] {
          [Pipeline] hubotApprove
          02:39:27 Hubot: ROOM - thoughtslive - Approval Message - approve?
          02:39:27 Hubot: Successful. Code: 200
          02:39:27 approve?
          02:39:27 Proceed or Abort
          02:39:42 Cancelling nested steps due to timeout
          [Pipeline] }
          [Pipeline] // timeout
          [Pipeline] }
          [Pipeline] // timestamps
          [Pipeline] End of Pipeline
          
          Show
          nrayapati Naresh Rayapati added a comment - Tested this on my local machine: Before Fix : [Pipeline] timestamps [Pipeline] { [Pipeline] timeout 02:35:24 Timeout set to expire after 15 sec without activity [Pipeline] { [Pipeline] hubotApprove 02:35:25 Hubot: ROOM - thoughtslive - Approval Message - approve? 02:35:26 Hubot: Successful. Code: 200 02:35:26 approve? 02:35:26 Proceed or Abort 02:35:41 Cancelling nested steps due to timeout 02:35:56 Body did not finish within grace period; terminating with extreme prejudice [Pipeline] } [Pipeline] // timeout [Pipeline] } [Pipeline] // timestamps [Pipeline] End of Pipeline After Fix : [Pipeline] timestamps [Pipeline] { [Pipeline] timeout 02:39:26 Timeout set to expire after 15 sec without activity [Pipeline] { [Pipeline] hubotApprove 02:39:27 Hubot: ROOM - thoughtslive - Approval Message - approve? 02:39:27 Hubot: Successful. Code: 200 02:39:27 approve? 02:39:27 Proceed or Abort 02:39:42 Cancelling nested steps due to timeout [Pipeline] } [Pipeline] // timeout [Pipeline] } [Pipeline] // timestamps [Pipeline] End of Pipeline
          Hide
          nrayapati Naresh Rayapati added a comment -

          Code merged to master and released 2.0.1, it should soon (Probably in another 2-4 hours?) be available in update center.

          Thank you!.

          Show
          nrayapati Naresh Rayapati added a comment - Code merged to master and released 2.0.1, it should soon (Probably in another 2-4 hours?) be available in update center. Thank you!.
          Hide
          nrayapati Naresh Rayapati added a comment -

          Tested released version by manually installing it from repo: https://repo.jenkins-ci.org/public/org/jenkins-ci/plugins/hubot-steps/2.0.1/.

          Note: Tested with both failOnError true and false, same behavior, looks good to me.

          Closing this task, please don't hesitate to reopen or create a new one if the issue is not resolved in any case. Thanks again.

          Code:

          timestamps {
            timeout(time:15, unit:'SECONDS') {
              hubotApprove room: 'thoughtslive', message:"approve?"
            }
          }
          

          Output:

          Started by user anonymous
          Running in Durability level: MAX_SURVIVABILITY
          [Pipeline] timestamps
          [Pipeline] {
          [Pipeline] timeout
          03:15:34 Timeout set to expire in 15 sec
          [Pipeline] {
          [Pipeline] hubotApprove
          03:15:34 Hubot: ROOM - thoughtslive - Approval Message - approve?
          03:15:35 Hubot: Successful. Code: 200
          03:15:35 approve?
          03:15:35 Proceed or Abort
          03:15:49 Cancelling nested steps due to timeout
          [Pipeline] }
          [Pipeline] // timeout
          [Pipeline] }
          [Pipeline] // timestamps
          [Pipeline] End of Pipeline
          Timeout has been exceeded
          Finished: ABORTED
          
          Show
          nrayapati Naresh Rayapati added a comment - Tested released version by manually installing it from repo: https://repo.jenkins-ci.org/public/org/jenkins-ci/plugins/hubot-steps/2.0.1/ . Note: Tested with both failOnError true and false , same behavior, looks good to me. Closing this task, please don't hesitate to reopen or create a new one if the issue is not resolved in any case. Thanks again. Code: timestamps { timeout(time:15, unit: 'SECONDS' ) { hubotApprove room: 'thoughtslive' , message: "approve?" } } Output: Started by user anonymous Running in Durability level: MAX_SURVIVABILITY [Pipeline] timestamps [Pipeline] { [Pipeline] timeout 03:15:34 Timeout set to expire in 15 sec [Pipeline] { [Pipeline] hubotApprove 03:15:34 Hubot: ROOM - thoughtslive - Approval Message - approve? 03:15:35 Hubot: Successful. Code: 200 03:15:35 approve? 03:15:35 Proceed or Abort 03:15:49 Cancelling nested steps due to timeout [Pipeline] } [Pipeline] // timeout [Pipeline] } [Pipeline] // timestamps [Pipeline] End of Pipeline Timeout has been exceeded Finished: ABORTED
          Hide
          varesh varesh kumar added a comment -

          @Naresh Rayapati can you help me on ,   hobot approval script and coffee script for approve process ? 

          Show
          varesh varesh kumar added a comment - @ Naresh Rayapati can you help me on ,   hobot approval script and coffee script for approve process ? 

            People

            Assignee:
            nrayapati Naresh Rayapati
            Reporter:
            mjuuti Markus Juuti
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: