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

Long delay from github webhook to polling when polling threads all busy

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Component/s: git-plugin, github-plugin
    • Labels:
      None
    • Environment:
      jenkins 2.107.3
      git-plugin 3.9.0
      github-plugin 1.29.0
      github API 1.90
    • Similar Issues:

      Description

      I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

       

      Started on Oct 16, 2018 2:46:44 PM
      Started by event from 43.148.32.90 ? https://<jenkins>/github-webhook/ on Mon Oct 15 21:19:54 BST 2018
      [poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)
      {{ > git --version # timeout=30}}
      using GIT_SSH to set credentials <creds>
      {{ > git ls-remote -h <repo> # timeout=30}}
      Found 345 remote heads on <git_url>
      [poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835
      Done. Took 3 sec
      No changes

       

      I have checked that github is sending the webhook notifications and these get a http 200 response code.

      The Jenkins Log reports the PushEvents are being received and that my build job is being "Poked" but polling is not being run for the job.

       

      Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse
      {{Payload }}

      ...
      Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent
      Received PushEvent for https://<github>/<user>/<repo> from <ip> ⇒ https://<jenkins>/github-webhook/
      Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run
      Considering to poke my_build
      Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run
      Poked my_build

       

      The agent that my_build runs on is not permanently busy.

      Any idea what is going on here? How can I debug this further?

      We have a lot of jobs (~1000) and possibly a lot (10s) of jobs polling SCMs but I can't imagine this would take 17 1/2 hours...

        Attachments

          Activity

          rg Russell Gallop created issue -
          rg Russell Gallop made changes -
          Field Original Value New Value
          Description I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

           

          {{Started on Oct 16, 2018 2:46:44 PM}}
          {{Started by event from 43.148.32.90 ? https://&lt;jenkins&gt;/github-webhook/ on Mon Oct 15 21:19:54 BST 2018}}
          {{[poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)}}
          {{ > git --version # timeout=30}}
          {{using GIT_SSH to set credentials <creds>}}
          {{ > git ls-remote -h <repo> # timeout=30}}
          {{Found 345 remote heads on <git_url>}}
          {{[poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835}}
          {{Done. Took 3 sec}}
          {{No changes}}

           

          I have checked that github is sending the webhook notifications and these get a http 200 response code.

          The Jenkins Log reports the PushEvents are being received and that my build is being "Poked".

           

          {{Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse}}
          {{Payload }}

          {{...}}
          {{Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent}}
          {{Received PushEvent for https://&lt;github&gt;/&lt;user&gt;/&lt;repo> from <ip> ⇒ https://&lt;jenkins&gt;/github-webhook/}}
          {{Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
          {{Considering to poke my_build}}
          {{Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
          {{Poked my_build}}

           

          The agent that my_build runs on is not permanently busy.

          Any idea what is going on here? How can I debug this further?
          I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

           

          {{Started on Oct 16, 2018 2:46:44 PM}}
           {{Started by event from 43.148.32.90 ? https://&lt;jenkins&gt;/github-webhook/ on Mon Oct 15 21:19:54 BST 2018}}
           {{[poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)}}
           \{{ > git --version # timeout=30}}
           {{using GIT_SSH to set credentials <creds>}}
           \{{ > git ls-remote -h <repo> # timeout=30}}
           {{Found 345 remote heads on <git_url>}}
           {{[poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835}}
           {{Done. Took 3 sec}}
           {{No changes}}

           

          I have checked that github is sending the webhook notifications and these get a http 200 response code.

          The Jenkins Log reports the PushEvents are being received and that my build job is being "Poked" but polling is not being run for the job.

           

          {{Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse}}
           \{{Payload }}

          {{...}}
           {{Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent}}
           {{Received PushEvent for https://&lt;github&gt;/&lt;user&gt;/&lt;repo> from <ip> ⇒ https://&lt;jenkins&gt;/github-webhook/}}
           {{Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Considering to poke my_build}}
           {{Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Poked my_build}}

           

          The agent that my_build runs on is not permanently busy.

          Any idea what is going on here? How can I debug this further?
          rg Russell Gallop made changes -
          Description I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

           

          {{Started on Oct 16, 2018 2:46:44 PM}}
           {{Started by event from 43.148.32.90 ? https://&lt;jenkins&gt;/github-webhook/ on Mon Oct 15 21:19:54 BST 2018}}
           {{[poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)}}
           \{{ > git --version # timeout=30}}
           {{using GIT_SSH to set credentials <creds>}}
           \{{ > git ls-remote -h <repo> # timeout=30}}
           {{Found 345 remote heads on <git_url>}}
           {{[poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835}}
           {{Done. Took 3 sec}}
           {{No changes}}

           

          I have checked that github is sending the webhook notifications and these get a http 200 response code.

          The Jenkins Log reports the PushEvents are being received and that my build job is being "Poked" but polling is not being run for the job.

           

          {{Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse}}
           \{{Payload }}

          {{...}}
           {{Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent}}
           {{Received PushEvent for https://&lt;github&gt;/&lt;user&gt;/&lt;repo> from <ip> ⇒ https://&lt;jenkins&gt;/github-webhook/}}
           {{Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Considering to poke my_build}}
           {{Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Poked my_build}}

           

          The agent that my_build runs on is not permanently busy.

          Any idea what is going on here? How can I debug this further?
          I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

           

          {{Started on Oct 16, 2018 2:46:44 PM}}
           {{Started by event from 43.148.32.90 ? https://&lt;jenkins&gt;/github-webhook/ on Mon Oct 15 21:19:54 BST 2018}}
           {{[poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)}}
           \{{ > git --version # timeout=30}}
           {{using GIT_SSH to set credentials <creds>}}
           \{{ > git ls-remote -h <repo> # timeout=30}}
           {{Found 345 remote heads on <git_url>}}
           {{[poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835}}
           {{Done. Took 3 sec}}
           {{No changes}}

           

          I have checked that github is sending the webhook notifications and these get a http 200 response code.

          The Jenkins Log reports the PushEvents are being received and that my build job is being "Poked" but polling is not being run for the job.

           

          {{Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse}}
           \{{Payload }}

          {{...}}
           {{Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent}}
           {{Received PushEvent for https://&lt;github&gt;/&lt;user&gt;/&lt;repo> from <ip> ⇒ https://&lt;jenkins&gt;/github-webhook/}}
           {{Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Considering to poke my_build}}
           {{Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Poked my_build}}

           

          The agent that my_build runs on is not permanently busy.

          Any idea what is going on here? How can I debug this further?

          We have a lot of jobs and possibly a lot of SCM polls happening. How can I see a log of these or examine the queue of SCM polls waiting?
          rg Russell Gallop made changes -
          Description I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

           

          {{Started on Oct 16, 2018 2:46:44 PM}}
           {{Started by event from 43.148.32.90 ? https://&lt;jenkins&gt;/github-webhook/ on Mon Oct 15 21:19:54 BST 2018}}
           {{[poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)}}
           \{{ > git --version # timeout=30}}
           {{using GIT_SSH to set credentials <creds>}}
           \{{ > git ls-remote -h <repo> # timeout=30}}
           {{Found 345 remote heads on <git_url>}}
           {{[poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835}}
           {{Done. Took 3 sec}}
           {{No changes}}

           

          I have checked that github is sending the webhook notifications and these get a http 200 response code.

          The Jenkins Log reports the PushEvents are being received and that my build job is being "Poked" but polling is not being run for the job.

           

          {{Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse}}
           \{{Payload }}

          {{...}}
           {{Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent}}
           {{Received PushEvent for https://&lt;github&gt;/&lt;user&gt;/&lt;repo> from <ip> ⇒ https://&lt;jenkins&gt;/github-webhook/}}
           {{Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Considering to poke my_build}}
           {{Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Poked my_build}}

           

          The agent that my_build runs on is not permanently busy.

          Any idea what is going on here? How can I debug this further?

          We have a lot of jobs and possibly a lot of SCM polls happening. How can I see a log of these or examine the queue of SCM polls waiting?
          I am seeing some long delays between github webhook events and jobs polling for changes (e.g. from GitHub Hook Log). Note the almost 17 1/2 hour gap between the event being received and the polling being performed.

           

          {{Started on Oct 16, 2018 2:46:44 PM}}
           {{Started by event from 43.148.32.90 ? https://&lt;jenkins&gt;/github-webhook/ on Mon Oct 15 21:19:54 BST 2018}}
           {{[poll] Last Built Revision: Revision c7013e0bb447b77bf13e719201ce2acb44b073af (refs/remotes/origin/<branch>)}}
           \{{ > git --version # timeout=30}}
           {{using GIT_SSH to set credentials <creds>}}
           \{{ > git ls-remote -h <repo> # timeout=30}}
           {{Found 345 remote heads on <git_url>}}
           {{[poll] Latest remote head revision on refs/heads/<branch> is: c7013e0bb447b77bf13e719201ce2acb44b073af - already built by 34835}}
           {{Done. Took 3 sec}}
           {{No changes}}

           

          I have checked that github is sending the webhook notifications and these get a http 200 response code.

          The Jenkins Log reports the PushEvents are being received and that my build job is being "Poked" but polling is not being run for the job.

           

          {{Oct 16, 2018 3:29:50 PM FINEST org.jenkinsci.plugins.github.webhook.GHEventPayload$PayloadHandler parse}}
           \{{Payload }}

          {{...}}
           {{Oct 16, 2018 3:29:50 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber onEvent}}
           {{Received PushEvent for https://&lt;github&gt;/&lt;user&gt;/&lt;repo> from <ip> ⇒ https://&lt;jenkins&gt;/github-webhook/}}
           {{Oct 16, 2018 3:29:51 PM FINE org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Considering to poke my_build}}
           {{Oct 16, 2018 3:29:51 PM INFO org.jenkinsci.plugins.github.webhook.subscriber.DefaultPushGHEventSubscriber$1 run}}
           {{Poked my_build}}

           

          The agent that my_build runs on is not permanently busy.

          Any idea what is going on here? How can I debug this further?

          We have a lot of jobs (~1000) and possibly a lot (10s) of jobs polling SCMs but I can't imagine this would take 17 1/2 hours...
          markewaite Mark Waite made changes -
          Assignee Mark Waite [ markewaite ]
          markewaite Mark Waite made changes -
          Summary Long delay from github webhook to polling Long delay from github webhook to polling when polling threads all busy
          rg Russell Gallop made changes -
          Component/s p4-plugin [ 19224 ]
          p4paul Paul Allen made changes -
          Component/s p4-plugin [ 19224 ]

            People

            • Assignee:
              Unassigned
              Reporter:
              rg Russell Gallop
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: