Jira (PUP-7136) Enable the tracing of lookup calls on a per-node basis

11 views
Skip to first unread message

Charlie Sharpsteen (JIRA)

unread,
Jan 26, 2017, 2:47:03 PM1/26/17
to puppe...@googlegroups.com
Charlie Sharpsteen updated an issue
 
Puppet / New Feature PUP-7136
Enable the tracing of lookup calls on a per-node basis
Change By: Charlie Sharpsteen
Summary: Allow Enable the tracing of  lookup calls  to be traced  on a per-node basis
Add Comment Add Comment
 
This message was sent by Atlassian JIRA (v6.4.14#64029-sha1:ae256fe)
Atlassian logo

Charlie Sharpsteen (JIRA)

unread,
Jan 26, 2017, 2:49:11 PM1/26/17
to puppe...@googlegroups.com
Charlie Sharpsteen updated an issue
Currently, one of the best tools for debugging a hiera() or lookup() call that isn't quite turning out right is to enable DEBUG level logging on the puppet server in order to get a trace of the files that were consulted when looking for a particular value:

{noformat}
2017-01-26 18:25:56,037 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking up profile::rabbitmq::cluster_nodes in YAML backend
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source nodes/test.cert
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/nodes/test.cert.yaml, skipping
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source st02/rabbitmq
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/st02/rabbitmq.yaml, skipping
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source st02
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/st02.yaml, skipping
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source role/rabbitmq
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/role/rabbitmq.yaml, skipping
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source common
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/common.yaml, skipping
2017-01-26 18:25:56,044 ERROR [qtp137565235-68] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find data item profile::rabbitmq::cluster_nodes in any Hiera data file and no default supplied at /etc/puppetlabs/code/environments/st02/site/profile/manifests/rabbitmq/cluster.pp:2:30 on node test.cert
{noformat}

This information can be compared against the configured hierarchy to deduce which values were in scope at the time that the lookup ran.

There are however several downsides to this approach:

  - Boosting the logs to DEBUG level requires manual edits to config files and a puppet server restart.

  - DEBUG level output is generated for all agents, which absolutely kills the signal to noise  ration  ratio  of the logs.

  - After debugging, the log level boost must be reverted via more manual edits and another restart.

As a puppet operator, I would like the ability to enable lookup tracing on a per-agent basis so that I can quickly debug misbehaving lookups running on the server without disturbing the rest of my installation.

Charlie Sharpsteen (JIRA)

unread,
Jan 26, 2017, 2:50:02 PM1/26/17
to puppe...@googlegroups.com
Charlie Sharpsteen updated an issue
Currently, one of the best tools for debugging a hiera() or lookup() call that isn't quite turning out right is to enable DEBUG level logging on the puppet server in order to get a trace of the files that were consulted when looking for a particular value:

{noformat}
2017-01-26 18:25:56,037 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking up profile::rabbitmq::cluster_nodes in YAML backend
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source nodes/test.cert
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/nodes/test.cert.yaml, skipping
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source st02/rabbitmq
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/st02/rabbitmq.yaml, skipping
2017-01-26 18:25:56,038 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source st02
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/st02.yaml, skipping
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source role/rabbitmq
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/role/rabbitmq.yaml, skipping
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Looking for data source common
2017-01-26 18:25:56,039 DEBUG [qtp137565235-68] [puppetserver] Puppet hiera(): Cannot find datafile hieradata/common.yaml, skipping
2017-01-26 18:25:56,044 ERROR [qtp137565235-68] [puppetserver] Puppet Evaluation Error: Error while evaluating a Function Call, Could not find data item profile::rabbitmq::cluster_nodes in any Hiera data file and no default supplied at /etc/puppetlabs/code/environments/st02/site/profile/manifests/rabbitmq/cluster.pp:2:30 on node test.cert
{noformat}

This information can be compared against the configured hierarchy to deduce which values were in scope at the time that the lookup ran.

There are however several downsides to this approach:

  - Boosting the logs to DEBUG level requires manual edits to config files and a puppet server restart.

  - DEBUG level output is generated for all agents, which absolutely kills the signal to noise ratio of the logs.


  - After debugging, the log level boost must be reverted via more manual edits and another restart.

As a puppet operator, I would like the ability to  temporarily  enable lookup tracing  on a per-  for individual agent  basis  runs  so that I can quickly debug misbehaving lookups running on the server without  disturbing the rest of my installation  disruptions such as configuration edits or service restarts .

Henrik Lindberg (JIRA)

unread,
Jan 27, 2017, 6:28:03 AM1/27/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Fix Version/s: PUP 5.0.0

Henrik Lindberg (JIRA)

unread,
Jan 27, 2017, 6:28:25 AM1/27/17
to puppe...@googlegroups.com
Henrik Lindberg commented on New Feature PUP-7136
 
Re: Enable the tracing of lookup calls on a per-node basis

I think the doing explain when profiling is on is a very good idea. In hiera 5 each backend is a function call, and you would want those profiled as well. This is best done in the context of the explanation as it would otherwise be difficult to understand why the data functions were called, and what to attribute cost to.

John Duarte (JIRA)

unread,
Feb 22, 2017, 11:23:12 AM2/22/17
to puppe...@googlegroups.com
John Duarte updated an issue
 
Change By: John Duarte
Team: Puppet Developer Experience

Henrik Lindberg (JIRA)

unread,
Feb 22, 2017, 6:26:02 PM2/22/17
to puppe...@googlegroups.com
 
Re: Enable the tracing of lookup calls on a per-node basis

Charlie Sharpsteen I suspect that the explains will be quite costly and that they will indeed skew the result as parameters getting their value from APL will show up as being a lot more expensive than those that do not. Maybe we should add a new option to the HTTP request for "--explain" behaviour? Currently we only have explanations of lookups, but I can imagine additional things being explained over time.

If we do that, --explain would be changed to be a setting (it is currently speicific to the lookup CLI), and then handled akin to the --profile setting in the indirector/http to make it relay from agent to server.

Charlie Sharpsteen (JIRA)

unread,
Mar 15, 2017, 7:40:02 PM3/15/17
to puppe...@googlegroups.com

If there is a noticeable performance hit, then we probably want to split explanations out to a separate parameter. The key feature is still the ability to enable explanations from the agent side by passing an additional flag to puppet agent -t and have the results show up on the server without twiddling any configuration bits on either side.

Henrik Lindberg (JIRA)

unread,
Mar 16, 2017, 8:29:02 AM3/16/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
 

Agree with Charlie Sharpsteen, we need a separate flag and --explain seems to be a good choice.
Change By: Henrik Lindberg
Story Points: 3
Sprint: PDE 2017-04-05

Henrik Lindberg (JIRA)

unread,
Apr 5, 2017, 4:28:06 PM4/5/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05 , PDE 2017-04-19

Eric Sorenson (JIRA)

unread,
Apr 20, 2017, 8:19:02 PM4/20/17
to puppe...@googlegroups.com
Eric Sorenson updated an issue
Change By: Eric Sorenson
Fix Version/s: PUP 5.0.0

Henrik Lindberg (JIRA)

unread,
Apr 25, 2017, 5:14:05 AM4/25/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05, PDE 2017-04-19 , PDE 2017-05-03

Henrik Lindberg (JIRA)

unread,
Apr 25, 2017, 5:16:02 AM4/25/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05, PDE 2017-04-19, PDE 2017-05- 03 17

Henrik Lindberg (JIRA)

unread,
Apr 25, 2017, 5:20:02 AM4/25/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Fix Version/s: PUP 5.y

Henrik Lindberg (JIRA)

unread,
May 2, 2017, 10:28:12 AM5/2/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05, PDE 2017-04-19, PDE 2017-05- 17 31

Branan Riley (JIRA)

unread,
May 16, 2017, 5:37:05 PM5/16/17
to puppe...@googlegroups.com
Branan Riley updated an issue
Change By: Branan Riley
Labels: triaged

Henrik Lindberg (JIRA)

unread,
May 31, 2017, 8:12:06 AM5/31/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05, PDE 2017-04-19 , PDE 2017-06-07

Henrik Lindberg (JIRA)

unread,
May 31, 2017, 8:12:06 AM5/31/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE  Triage, PDE  2017-04-05, PDE 2017-04-19

Henrik Lindberg (JIRA)

unread,
May 31, 2017, 9:01:15 AM5/31/17
to puppe...@googlegroups.com

Henrik Lindberg (JIRA)

unread,
May 31, 2017, 9:01:18 AM5/31/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05,  Forge - To Accept,  PDE 2017-04-19

Henrik Lindberg (JIRA)

unread,
May 31, 2017, 9:09:04 AM5/31/17
to puppe...@googlegroups.com
Henrik Lindberg updated an issue
Change By: Henrik Lindberg
Sprint: PDE 2017-04-05,  Forge - To Accept,  PDE 2017-04-19 , Language Triage

David McTavish (Jira)

unread,
Dec 6, 2021, 12:19:02 PM12/6/21
to puppe...@googlegroups.com
David McTavish updated an issue
Change By: David McTavish
Labels: final_triage nice-to-have
This message was sent by Atlassian Jira (v8.13.2#813002-sha1:c495a97)
Atlassian logo

David McTavish (Jira)

unread,
Dec 6, 2021, 1:39:02 PM12/6/21
to puppe...@googlegroups.com
David McTavish updated an issue
Change By: David McTavish
Priority: Normal Low

Nick Walker (Jira)

unread,
Dec 22, 2021, 1:47:02 PM12/22/21
to puppe...@googlegroups.com
Nick Walker commented on New Feature PUP-7136
 
Re: Enable the tracing of lookup calls on a per-node basis

chuck has anything changed with this in the past 4-5 years?
This message was sent by Atlassian Jira (v8.20.2#820002-sha1:829506d)
Atlassian logo

Charlie Sharpsteen (Jira)

unread,
Feb 22, 2022, 2:16:01 PM2/22/22
to puppe...@googlegroups.com

Re-opening. "Why is my node not finding the Hiera data I expect?" is still a very common and time-consuming troubleshooting query.

Charlie Sharpsteen (Jira)

unread,
Feb 22, 2022, 2:26:01 PM2/22/22
to puppe...@googlegroups.com
Charlie Sharpsteen assigned an issue to Charlie Sharpsteen
 
Change By: Charlie Sharpsteen
Assignee: Charlie Sharpsteen

Charlie Sharpsteen (Jira)

unread,
Feb 22, 2022, 2:26:02 PM2/22/22
to puppe...@googlegroups.com
 
Re: Enable the tracing of lookup calls on a per-node basis

The ability to set the a per-request log_level on the /v4/catalog API might resolve this by making it easy to get the explain logs for just one node — I'll look into it.

Molly Waggett (Jira)

unread,
Feb 22, 2022, 3:10:01 PM2/22/22
to puppe...@googlegroups.com
Molly Waggett updated an issue
 
Change By: Molly Waggett
Team: Froyo Phoenix

Molly Waggett (Jira)

unread,
Feb 22, 2022, 3:10:02 PM2/22/22
to puppe...@googlegroups.com
Molly Waggett updated an issue
Change By: Molly Waggett
Labels: final_triage nice-to-have

Charlie Sharpsteen (Jira)

unread,
Feb 22, 2022, 3:42:02 PM2/22/22
to puppe...@googlegroups.com
 
Re: Enable the tracing of lookup calls on a per-node basis

Alright, Hiera lookups can indeed be explained on a per-node basis via the log_level support added to /puppet/v4/catalog in SERVER-2520:

# curl -ksS \
 
  -H "Content-Type: application/json" \
 
  --cert $(puppet config print hostcert) \
 
  --key $(puppet config print hostprivkey) \
 
  https://localhost:8140/puppet/v4/catalog \
 
  --data-binary @- <<EOF \
 
    | jq -r '.logs[]|.message|select(.|test("^Lookup of"))'
 
{"certname": "$(puppet config print certname)",
 
 "persistence": {"facts": false,
 
                 "catalog": false},
 
 "environment": "production",
 
 "options": {"capture_logs": true,
 
             "log_level": "debug"}}
 
EOF
 
Lookup of 'puppet_enterprise::postgres_version_override'
 
  Searching for "lookup_options"
 
    Global Data Provider (hiera configuration version 5)
 
      Using configuration "/etc/puppetlabs/puppet/hiera.yaml"
 
      Hierarchy entry "Classifier Configuration Data"
 
        No such key: "lookup_options"
 
    Environment Data Provider (hiera configuration version 5)
 
      Using configuration "/etc/puppetlabs/code/environments/production/hiera.yaml"
 
      Hierarchy entry "Yaml backend"
 
        Merge strategy hash
 
          Path "/etc/puppetlabs/code/environments/production/data/nodes/clspe-928bbc-0.us-west1-c.c.customer-support-scratchpad.internal.yaml"
 
            Original path: "nodes/%{trusted.certname}.yaml"
 
            Path not found
 
          Path "/etc/puppetlabs/code/environments/production/data/common.yaml"
 
            Original path: "common.yaml"
 
            No such key: "lookup_options"
 
    Module "puppet_enterprise" Data Provider (hiera configuration version 5)
 
...

Reply all
Reply to author
Forward
0 new messages