One puppet run divided to two puppet runs

[Marcin Spoczynski]

I have puppet run on 2 host 

On the first one looks like this

Oct 14 12:28:21 node1 puppet-agent[3447]: (/File[/etc/yum/pluginconf.d/versionlock.list.packages]/content) content changed '{md5}8f8bac772793e3e4d83fc04c94f28ccb' to '{md5}12bae94916fc072e808415ddfc3f1583'

Oct 14 12:28:21 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__litp_3a_3aversionlock__node1/Litp::Versionlock[node1]/Exec[update_version_lock]) Triggered 'refresh' from 1 events

Oct 14 12:28:27 node1 yum[4094]: Updated: EXTR-lsbwrapper7-2.0.0-1.noarch

Oct 14 12:28:28 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper7/Package[EXTR-lsbwrapper7]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:29 node1 yum[4099]: Installed: EXTR-lsbwrapper1-2.0.0-1.noarch

Oct 14 12:28:30 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper1/Package[EXTR-lsbwrapper1]/ensure) ensure changed '3.0.0-1' to '2.0.0-1'

Oct 14 12:28:31 node1 yum[4104]: Updated: EXTR-lsbwrapper10-2.0.0-1.noarch

Oct 14 12:28:32 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper10/Package[EXTR-lsbwrapper10]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:33 node1 yum[4113]: Updated: EXTR-lsbwrapper6-2.0.0-1.noarch

Oct 14 12:28:35 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper6/Package[EXTR-lsbwrapper6]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:36 node1 yum[4122]: Updated: EXTR-lsbwrapper5-2.0.0-1.noarch

Oct 14 12:28:37 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper5/Package[EXTR-lsbwrapper5]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:38 node1 yum[4127]: Updated: EXTR-lsbwrapper9-2.0.0-1.noarch

Oct 14 12:28:39 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper9/Package[EXTR-lsbwrapper9]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:41 node1 yum[4132]: Updated: EXTR-lsbwrapper3-2.0.0-1.noarch

Oct 14 12:28:42 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper3/Package[EXTR-lsbwrapper3]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:43 node1 yum[4141]: Updated: EXTR-lsbwrapper2-2.0.0-1.noarch

Oct 14 12:28:44 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper2/Package[EXTR-lsbwrapper2]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:46 node1 yum[4152]: Updated: EXTR-lsbwrapper23-2.0.0-1.noarch

Oct 14 12:28:47 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper23/Package[EXTR-lsbwrapper23]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct 14 12:28:49 node1 yum[4192]: Updated: EXTR-lsbwrapper28-2.0.0-1.noarch

Oct 14 12:28:50 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper28/Package[EXTR-lsbwrapper28]/ensure) ensure changed '1.0.0-1' to '0:2.0.0-1'

Oct 14 12:28:51 node1 yum[4196]: Updated: EXTR-lsbwrapper8-3.0.0-1.noarch

Oct 14 12:28:52 node1 puppet-agent[3447]: (/Stage[main]/Task_node1__package___45_58_54_52_2dlsbwrapper8/Package[EXTR-lsbwrapper8]/ensure) ensure changed '1.0.0-1' to '0:3.0.0-1'

Oct 14 12:28:57 node1 puppet-agent[3447]: Finished catalog run in 38.19 seconds

But on the second looks different.

Oct  8 19:57:41 node2 puppet-agent[18912]: (/File[/etc/yum/pluginconf.d/versionlock.list.packages]/content) content changed '{md5}d6bf761413af4da2976579ed255bd226' to '{md5}dfd2461643c6e4663ae5dae1a5a991ef'

Oct  8 19:57:41 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__litp_3a_3aversionlock__node2/Litp::Versionlock[node2]/Exec[update_version_lock]) Triggered 'refresh' from 1 events

Oct  8 19:57:45 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper1/Package[EXTR-lsbwrapper1]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:57:48 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper3/Package[EXTR-lsbwrapper3]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:57:51 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper5/Package[EXTR-lsbwrapper5]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:57:54 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper2/Package[EXTR-lsbwrapper2]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:57:57 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper6/Package[EXTR-lsbwrapper6]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:58:00 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper7/Package[EXTR-lsbwrapper7]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:58:04 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper23/Package[EXTR-lsbwrapper23]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:58:07 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper4/Package[EXTR-lsbwrapper4]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:58:12 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper8/Package[EXTR-lsbwrapper8]/ensure) ensure changed '1.0.0-1' to '0:3.0.0-1'

Oct  8 19:58:15 node2 puppet-agent[18912]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}cf91bdba62cbaa5149af42b81febbbf4' to '{md5}994da216388be7020bade56907c701ed'

Oct  8 19:58:19 node2 puppet-agent[18912]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:58:22 node2 puppet-agent[18912]: Finished catalog run in 47.16 seconds

Oct  8 19:58:57 node2 puppet-agent[20580]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper28/Package[EXTR-lsbwrapper28]/ensure) ensure changed '1.0.0-1' to '0:2.0.0-1'

Oct  8 19:58:58 node2 puppet-agent[20580]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}994da216388be7020bade56907c701ed' to '{md5}d8c1cb23e367c830bc34a564d49e8353'

Oct  8 19:59:03 node2 puppet-agent[20580]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:59:05 node2 puppet-agent[20580]: Finished catalog run in 16.30 seconds

I'm just curious about some puppet internals, 

If I have another puppet run in the same time in this case,

Oct  8 19:58:15 node2 puppet-agent[18912]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}cf91bdba62cbaa5149af42b81febbbf4' to '{md5}994da216388be7020bade56907c701ed'

Oct  8 19:58:19 node2 puppet-agent[18912]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:58:22 node2 puppet-agent[18912]: Finished catalog run in 47.16 seconds

is the previous puppet run will be divided to more puppet runs to save a time ? or this puppet behavior is caused by some other issues ?

Thanks. 

This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. If you have received this email in error please notify the system manager. This message contains confidential information and is intended only for the individual named. If you are not the named addressee you should not disseminate, distribute or copy this e-mail.

[jcbollinger]

I'm uncertain which differences between the two logs you find significant.  They do appear to have been recorded at different log levels -- that explains why one has "Updated:" entries and the other does not.  The various packages are managed in different order in the two runs, but Puppet resource ordering is not guaranteed to be consistent (subject to several caveats).  The two runs show somewhat different sets of resources being updated, but even if the nodes receive identical catalogs, which resources are updated will vary depending on which resources need to be updated.

Anyway, you cannot parallelize catalog runs.  The agent employs a lock file to ensure that you do not do so.  This is because multiple concurrent runs can conflict with each other.  Even if Puppet wanted to parallelize internally -- and in principle it could do so to some extent -- it is far trickier than just arbitrarily splitting resources among threads.  Moreover, the gain achievable that way is unclear, but likely to be variable and small, as most of the time-consuming operations the agent performs are I/O bound.

[Marcin Spoczynski]

Thanks for the answer, but the main question is why puppet need to have 2 puppet runs instead of one in the 2 nd example?  

On Wednesday, 15 October 2014 14:11:48 UTC+1, jcbollinger wrote:

I'm uncertain which differences between the two logs you find significant.  They do appear to have been recorded at different log levels -- that explains why one has "Updated:" entries and the other does not.  The various packages are managed in different order in the two runs, but Puppet resource ordering is not guaranteed to be consistent (subject to several caveats).  The two runs show somewhat different sets of resources being updated, but even if the nodes receive identical catalogs, which resources are updated will vary depending on which resources need to be updated.

Anyway, you cannot parallelize catalog runs.  The agent employs a lock file to ensure that you do not do so.  This is because multiple concurrent runs can conflict with each other.  Even if Puppet wanted to parallelize internally -- and in principle it could do so to some extent -- it is far trickier than just arbitrarily splitting resources among threads.  Moreover, the gain achievable that way is unclear, but likely to be variable and small, as most of the time-consuming operations the agent performs are I/O bound.

[jcbollinger]

On Wednesday, October 15, 2014 10:53:33 AM UTC-5, Marcin Spoczynski wrote:

Thanks for the answer, but the main question is why puppet need to have 2 puppet runs instead of one in the 2 nd example?  

It is impossible to answer that question definitively from the data provided.  The relevant manifests would be helpful, as would log output that has not had relevant information edited out.

Nevertheless, I observe that two different agent processes are logging results in the second case, with only a short interval between their entries.  It follows that the agent service was restarted in between.  In all likelihood, therefore, the catalog applied to the second machine either explicitly refreshed the puppet agent service before all other resources had been applied, or else implicitly triggered the daemon to restart by updating its config file.

I cannot speak directly to why only the second machine required the agent to be restarted.  I can offer only the rather unhelpful answer that either its initial state or its catalog or both differed from the first machine's.


John

[artur.da...@ammeon.com]

I believe what Marcin is asking is how it would be possible to make puppet only run once a.k.a. if puppet is already running make the second run wait.

Is there some kind of option/flag that can enable a global lock that would prevent a second run of puppet not start if puppet is already running?

[jcbollinger]

On Friday, October 17, 2014 6:05:35 AM UTC-5, artur.da...@ammeon.com wrote:

I believe what Marcin is asking is how it would be possible to make puppet only run once a.k.a. if puppet is already running make the second run wait.

Is there some kind of option/flag that can enable a global lock that would prevent a second run of puppet not start if puppet is already running?

As I wrote in my first response, different agent runs do not proceed in parallel on the same machine.  Puppet uses a lock file to actively prevents it from happening.  Marcin's log excerpts do not suggest otherwise.

If you are determined to do so then you can defeat Puppet's protections in this area, but that's not what's happening in the case we're considering.


John

[artur.da...@ammeon.com]

The issue that i don't fully understand is why the puppet run seems to finish:

Oct  8 19:58:07 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper4/Package[EXTR-lsbwrapper4]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:58:12 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper8/Package[EXTR-lsbwrapper8]/ensure) ensure changed '1.0.0-1' to '0:3.0.0-1'

Oct  8 19:58:15 node2 puppet-agent[18912]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}cf91bdba62cbaa5149af42b81febbbf4' to '{md5}994da216388be7020bade56907c701ed'

Oct  8 19:58:19 node2 puppet-agent[18912]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:58:22 node2 puppet-agent[18912]: Finished catalog run in 47.16 seconds

Yet after that the puppet seems to continue where it left off:

Oct  8 19:58:57 node2 puppet-agent[20580]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper28/Package[EXTR-lsbwrapper28]/ensure) ensure changed '1.0.0-1' to '0:2.0.0-1'

Oct  8 19:58:58 node2 puppet-agent[20580]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}994da216388be7020bade56907c701ed' to '{md5}d8c1cb23e367c830bc34a564d49e8353'

Oct  8 19:59:03 node2 puppet-agent[20580]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:59:05 node2 puppet-agent[20580]: Finished catalog run in 16.30 seconds

Not sure about this but my understanding is that a catalog run should be sequential if there is a global lock in place?

This looks like a bug IMO. Is there any tracking done of this?

[Wil Cooley]

On Oct 20, 2014 6:46 AM, <artur.da...@ammeon.com> wrote:
>
> The issue that i don't fully understand is why the puppet run seems to finish:
>
> Oct  8 19:58:07 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper4/Package[EXTR-lsbwrapper4]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'
> Oct  8 19:58:12 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper8/Package[EXTR-lsbwrapper8]/ensure) ensure changed '1.0.0-1' to '0:3.0.0-1'
> Oct  8 19:58:15 node2 puppet-agent[18912]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}cf91bdba62cbaa5149af42b81febbbf4' to '{md5}994da216388be7020bade56907c701ed'
> Oct  8 19:58:19 node2 puppet-agent[18912]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'
> Oct  8 19:58:22 node2 puppet-agent[18912]: Finished catalog run in 47.16 seconds
>
> Yet after that the puppet seems to continue where it left off:
>
> Oct  8 19:58:57 node2 puppet-agent[20580]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper28/Package[EXTR-lsbwrapper28]/ensure) ensure changed '1.0.0-1' to '0:2.0.0-1'
> Oct  8 19:58:58 node2 puppet-agent[20580]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}994da216388be7020bade56907c701ed' to '{md5}d8c1cb23e367c830bc34a564d49e8353'
> Oct  8 19:59:03 node2 puppet-agent[20580]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'
> Oct  8 19:59:05 node2 puppet-agent[20580]: Finished catalog run in 16.30 seconds
>
> Not sure about this but my understanding is that a catalog run should be sequential if there is a global lock in place?
>

Yes, the catalog application is sequential but I see nothing to suggest otherwise in these logs (I could be missing it, reading on my phone).

What I see is: The File facts.yaml is changed from cf9* to 994* in the first run, then 994* to d8c* in the second. The Packages lsbwrapper4 & lsbwrapper8 are installed in the first run, lsbwrapper28 in the second.

Without seeing the manifests, we cannot know why these happen in two runs instead of one, but the facts.yaml changing is probably a clue.

> This looks like a bug IMO. Is there any tracking done of this?

What is the antecedent of your final "this"? Bugs (there's Jira for that) or catalog runs (logs and reports for that) or something else?

Wil

[jcbollinger]

On Monday, October 20, 2014 8:46:42 AM UTC-5, artur.da...@ammeon.com wrote:

The issue that i don't fully understand is why the puppet run seems to finish:

Oct  8 19:58:07 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper4/Package[EXTR-lsbwrapper4]/ensure) ensure changed '1.0.0-1' to '2.0.0-1'

Oct  8 19:58:12 node2 puppet-agent[18912]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper8/Package[EXTR-lsbwrapper8]/ensure) ensure changed '1.0.0-1' to '0:3.0.0-1'

Oct  8 19:58:15 node2 puppet-agent[18912]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}cf91bdba62cbaa5149af42b81febbbf4' to '{md5}994da216388be7020bade56907c701ed'

Oct  8 19:58:19 node2 puppet-agent[18912]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:58:22 node2 puppet-agent[18912]: Finished catalog run in 47.16 seconds

Yet after that the puppet seems to continue where it left off:

Oct  8 19:58:57 node2 puppet-agent[20580]: (/Stage[main]/Task_node2__package___45_58_54_52_2dlsbwrapper28/Package[EXTR-lsbwrapper28]/ensure) ensure changed '1.0.0-1' to '0:2.0.0-1'

[...]

Note that the PID of the puppet-agent process changes, and that there is a 35-second gap in the log.  I conclude that the agent was restarted in the gap, but the relevant log output was edited out, up to and including that describing a new catalog request being issued.  This is what I was referring to earlier when I complained about preferring "log output that has not had relevant information edited out."  Likely the restart was mediated by Puppet itself, as I described above.

 

Oct  8 19:58:58 node2 puppet-agent[20580]: (/File[/etc/mcollective/facts.yaml]/content) content changed '{md5}994da216388be7020bade56907c701ed' to '{md5}d8c1cb23e367c830bc34a564d49e8353'

Oct  8 19:59:03 node2 puppet-agent[20580]: (/File[maincf]/seltype) seltype changed 'etc_runtime_t' to 'etc_t'

Oct  8 19:59:05 node2 puppet-agent[20580]: Finished catalog run in 16.30 seconds

Not sure about this but my understanding is that a catalog run should be sequential if there is a global lock in place?

What about that makes you think there were concurrent catalog runs?  I see a bunch of log entries from one process, followed by a bunch of log entries from a different process.  How is that anything but sequential?


John