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

Periodic Update Occurs Too Frequently

    Details

    • Similar Issues:
    • Released As:
      saml-1.0.8

      Description

      The periodic update of IDP Metadata appears to run every 10 seconds, regardless of the value specified in the period field. 

       

      I'm not a developer, but if I understood the logic correctly, the class variable scheduleedOnce will be initialised as false each time the UpdateMetadataFromURLPeriodicWork class is instantiated. This will cause getRecurrencePeriod to always return 10 seconds, which is consistent with what we see in our logs (pasted below). 

       

      Sep 10, 2018 4:50:21 AM INFO hudson.model.AsyncAperiodicWork$1 runStarted Update IdP Metadata from URL PeriodicWork
      Sep 10, 2018 4:50:21 AM INFO org.opensaml.core.config.InitializationService initializeInitializing OpenSAML using the Java Services API
      Sep 10, 2018 4:50:21 AM INFO hudson.model.AsyncAperiodicWork$1 runFinished Update IdP Metadata from URL PeriodicWork. 480 ms
      Sep 10, 2018 4:50:31 AM INFO hudson.model.AsyncAperiodicWork$1 runStarted Update IdP Metadata from URL PeriodicWork
      Sep 10, 2018 4:50:31 AM INFO org.opensaml.core.config.InitializationService initializeInitializing OpenSAML using the Java Services API
      Sep 10, 2018 4:50:31 AM INFO hudson.model.AsyncAperiodicWork$1 runFinished Update IdP Metadata from URL PeriodicWork. 310 ms
      Sep 10, 2018 4:50:41 AM INFO hudson.model.AsyncAperiodicWork$1 runStarted Update IdP Metadata from URL PeriodicWork
      Sep 10, 2018 4:50:41 AM INFO org.opensaml.core.config.InitializationService initializeInitializing OpenSAML using the Java Services API
      Sep 10, 2018 4:50:41 AM INFO hudson.model.AsyncAperiodicWork$1 runFinished Update IdP Metadata from URL PeriodicWork. 297 ms
      

      The refresh period is set to 60 minutes.

        Attachments

          Issue Links

            Activity

            Hide
            jonb_at_arq jonathan bridgstock added a comment -

            Hi,

            here's the results:

            11:15
            Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce
            Period: 3600000
            ScheduleedOnce: true
            11:35
            Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce
            Period: 3600000
            ScheduleedOnce: true
            11:39
            Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce
            Period: 3600000
            ScheduleedOnce: true
            11:41
            Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce
            Period: 3600000
            ScheduleedOnce: true
            11:43
            Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce
            Period: 3600000
            ScheduleedOnce: true
             

             

            Show
            jonb_at_arq jonathan bridgstock added a comment - Hi, here's the results: 11:15 Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce Period: 3600000 ScheduleedOnce: true 11:35 Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce Period: 3600000 ScheduleedOnce: true 11:39 Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce Period: 3600000 ScheduleedOnce: true 11:41 Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce Period: 3600000 ScheduleedOnce: true 11:43 Obj: org.jenkinsci.plugins.saml.UpdateMetadataFromURLPeriodicWork@498930ce Period: 3600000 ScheduleedOnce: true    
            Hide
            ifernandezcalvo Ivan Fernandez Calvo added a comment -

            The object is always the same, the variable ScheduleedOnce, so the returned period is correct 60 minutes.

            Taing a look to the documentations getRecurrencePeriod is called on each execution, so the schedule time should correct, but is not.
            https://javadoc.jenkins.io/hudson/model/AperiodicWork.html#getRecurrencePeriod--

            the code confirms that this is the behaviour
            https://github.com/jenkinsci/jenkins/blob/master/core/src/main/java/hudson/model/AperiodicWork.java#L89-L93

            So I do not have a logic explanation about what happens on your Jenkins instance, but lets check if we can fix it. I want to force the Periodic work to change the configuration and see if something different happens, Could you set the refresh period to 0, this should disable the download of the metadata but the periodic work will be executed every 10 minutes, then check the logs to see if the behaviour changes, after that, set the refresh period again to 60 minutes, finally check the logs.

            Show
            ifernandezcalvo Ivan Fernandez Calvo added a comment - The object is always the same, the variable ScheduleedOnce, so the returned period is correct 60 minutes. Taing a look to the documentations getRecurrencePeriod is called on each execution, so the schedule time should correct, but is not. https://javadoc.jenkins.io/hudson/model/AperiodicWork.html#getRecurrencePeriod-- the code confirms that this is the behaviour https://github.com/jenkinsci/jenkins/blob/master/core/src/main/java/hudson/model/AperiodicWork.java#L89-L93 So I do not have a logic explanation about what happens on your Jenkins instance, but lets check if we can fix it. I want to force the Periodic work to change the configuration and see if something different happens, Could you set the refresh period to 0, this should disable the download of the metadata but the periodic work will be executed every 10 minutes, then check the logs to see if the behaviour changes, after that, set the refresh period again to 60 minutes, finally check the logs.
            Hide
            jonb_at_arq jonathan bridgstock added a comment -

            Interesting results.  I set it to 0, then validated ut url, save and apply.  As expected, the updates went to 10 minutes.

            Sep 24, 2018 3:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 3:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 95 ms
            Sep 24, 2018 3:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 3:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 93 ms
            Sep 24, 2018 3:45:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 3:45:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 89 ms
            Sep 24, 2018 3:55:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 3:55:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 92 ms
            Sep 24, 2018 4:05:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:05:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 100 ms
            Sep 24, 2018 4:15:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:15:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 96 ms
            Sep 24, 2018 4:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 104 ms
            Sep 24, 2018 4:26:31 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 96 ms
            

            I then changed the period back to 60, hit validate, then save and apply.  The updates started running every 10 seconds.

            Sep 24, 2018 4:45:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:45:11 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:45:11 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 966 ms
            Sep 24, 2018 4:45:20 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:45:20 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:45:20 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 294 ms
            Sep 24, 2018 4:45:30 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:45:30 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:45:30 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 289 ms
            Sep 24, 2018 4:45:40 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:45:40 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:45:40 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 275 ms
            Sep 24, 2018 4:45:50 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:45:50 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:45:50 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 309 ms
            Sep 24, 2018 4:46:00 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:46:00 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:46:00 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 421 ms
            Sep 24, 2018 4:46:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:46:10 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:46:10 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 298 ms
            Sep 24, 2018 4:46:20 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:46:20 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:46:20 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 301 ms
            Sep 24, 2018 4:46:30 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:46:30 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:46:30 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 415 ms
            Sep 24, 2018 4:46:40 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            Sep 24, 2018 4:46:40 AM INFO org.opensaml.core.config.InitializationService initialize
            Initializing OpenSAML using the Java Services API
            Sep 24, 2018 4:46:40 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Finished Update IdP Metadata from URL PeriodicWork. 293 ms
            Sep 24, 2018 4:46:50 AM INFO hudson.model.AsyncAperiodicWork$1 run
            Started Update IdP Metadata from URL PeriodicWork
            
            Show
            jonb_at_arq jonathan bridgstock added a comment - Interesting results.  I set it to 0, then validated ut url, save and apply.  As expected, the updates went to 10 minutes. Sep 24, 2018 3:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 3:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 95 ms Sep 24, 2018 3:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 3:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 93 ms Sep 24, 2018 3:45:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 3:45:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 89 ms Sep 24, 2018 3:55:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 3:55:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 92 ms Sep 24, 2018 4:05:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:05:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 100 ms Sep 24, 2018 4:15:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:15:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 96 ms Sep 24, 2018 4:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:25:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 104 ms Sep 24, 2018 4:26:31 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:35:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 96 ms I then changed the period back to 60, hit validate, then save and apply.  The updates started running every 10 seconds. Sep 24, 2018 4:45:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:45:11 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:45:11 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 966 ms Sep 24, 2018 4:45:20 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:45:20 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:45:20 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 294 ms Sep 24, 2018 4:45:30 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:45:30 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:45:30 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 289 ms Sep 24, 2018 4:45:40 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:45:40 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:45:40 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 275 ms Sep 24, 2018 4:45:50 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:45:50 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:45:50 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 309 ms Sep 24, 2018 4:46:00 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:46:00 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:46:00 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 421 ms Sep 24, 2018 4:46:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:46:10 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:46:10 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 298 ms Sep 24, 2018 4:46:20 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:46:20 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:46:20 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 301 ms Sep 24, 2018 4:46:30 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:46:30 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:46:30 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 415 ms Sep 24, 2018 4:46:40 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork Sep 24, 2018 4:46:40 AM INFO org.opensaml.core.config.InitializationService initialize Initializing OpenSAML using the Java Services API Sep 24, 2018 4:46:40 AM INFO hudson.model.AsyncAperiodicWork$1 run Finished Update IdP Metadata from URL PeriodicWork. 293 ms Sep 24, 2018 4:46:50 AM INFO hudson.model.AsyncAperiodicWork$1 run Started Update IdP Metadata from URL PeriodicWork
            Hide
            ifernandezcalvo Ivan Fernandez Calvo added a comment -

            It is weird, and I dunno why it works different on your Jenkins instance. There is a better approach to set the time to the first launch to use the getInitialDelay method, so I changed the logic a little to use this method and make configurable the initial delay. I will release a new version today.

            Show
            ifernandezcalvo Ivan Fernandez Calvo added a comment - It is weird, and I dunno why it works different on your Jenkins instance. There is a better approach to set the time to the first launch to use the getInitialDelay method, so I changed the logic a little to use this method and make configurable the initial delay. I will release a new version today.
            Hide
            ifernandezcalvo Ivan Fernandez Calvo added a comment -

            I release a new version, let me know if it resolve the issue, I hope so.

            Show
            ifernandezcalvo Ivan Fernandez Calvo added a comment - I release a new version, let me know if it resolve the issue, I hope so.

              People

              • Assignee:
                ifernandezcalvo Ivan Fernandez Calvo
                Reporter:
                michaelward Michael Ward
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: