Unexpected error messages

Question

Unexpected error messages

Closed this issue 11 years ago · 23 comments

Using the Basic_Printer in your example documentation, I got the following errors during the first catalog application:

info: Retrieving plugin
info: Loading facts in /etc/puppet/modules/mosen-cups-1.0.0/lib/facter/printers.rb
Could not retrieve printers: No such file or directory - LANG=C /usr/bin/lpstat -p
info: Caching catalog for puppet.example.com
info: Applying configuration version '1346861178'
err: Could not prefetch printer provider 'cups': Execution of '/usr/bin/lpstat -v' returned 1: lpstat: No destinations added.

notice: /Stage[main]/Example::puppet/Printer[Basic_Printer]/ensure: created
notice: Finished catalog run in 6.93 seconds

If I rerun "puppet agent --test" again, things change slightly:

info: Retrieving plugin
info: Loading facts in /etc/puppet/modules/mosen-cups-1.0.0/lib/facter/printers.rb
Could not retrieve printers: No such file or directory - LANG=C /usr/bin/lpstat -p
info: Caching catalog for puppet.example.com
info: Applying configuration version '1346864465'
err: /Stage[main]/Example::puppet/Printer[Basic_Printer]: Could not evaluate: undefined method `captures' for "Basic_Printer":String
notice: Finished catalog run in 8.14 seconds

The print queue did get created on the first shot, but are these errors to be expected?

Answer 1 · 2012-09-06T01:05:00.000Z

Hey there,
This looks like a combination of things. The first thing i can spot is that
the localisation fix that was suggested to me in fact causes issues with some other systems.
You can see this when it tries to run the LANG=C /usr/bin/lpstat -p command. The LANG part doesn't seem to be interpreted in the same way. This might be due to my assumption of the shell used by the provider.

What i will do is commit a new head with the locale fix taken out, then proceed with a language agnostic way of detecting queue status. This should get you up and running. Alternatively you can try to locate the LANG=C in the code and delete it if you're short on time.

Also, let me check to see whether a bug has reappeared. I've been told by one person that an empty printer list will cause the first part to fail. This had been fixed but I'll need to make sure it didn't come back.

Answer 2 · 2012-09-06T08:26:19.000Z

Ok, there were several issues I had to clear up. I've just successfully tested a rewrite with a few different printer definitions. Please pull down the latest revision and let me know how that goes - but not if it's going to critically important agents.

Answer 3 · 2012-09-06T13:46:18.000Z

Okay, I've got some feedback for you. The first run looks great now:

$ sudo -i puppet agent --test
info: Retrieving plugin
info: Loading facts in printers
info: Loading facts in printers
info: Caching catalog for myhost.example.com
info: Applying configuration version '1346938811'
notice: /Stage[main]/Example::Myhost/Printer[Basic_Printer]/ensure: created
notice: Finished catalog run in 7.29 seconds

However, subsequent runs not so much:

$ sudo -i puppet agent --test 
info: Retrieving plugin
info: Loading facts in printers
info: Loading facts in printers
info: Caching catalog for myhost.example.com
info: Applying configuration version '1346938811'
notice: /Stage[main]/Example::Myhost/Printer[Basic_Printer]/model: defined 'model' as 'raw'
err: /Stage[main]/Example::Myhost/Printer[Basic_Printer]: Could not evaluate: too few arguments
notice: Finished catalog run in 6.52 seconds

Answer 4 · 2012-09-10T23:15:24.000Z

Sorry, back from vacation...
Can i get a debug version of that second run, in case the lpadmin command displayed has something interesting.
In the mean time I'll create that Basic_Printer here, and see if i can replicate it.

Answer 5 · 2012-09-10T23:24:01.000Z

No need to apologize for a vacation! =)

The test rig is at the office so debug is about 9h in the future.

mosen notifications@github.com wrote:

Sorry, back from vacation...
Can i get a debug version of that second run, in case the lpadmin
command displayed has something interesting.
In the mean time I'll create that Basic_Printer here, and see if i can
replicate it.

Reply to this email directly or view it on GitHub:
#6 (comment)

Sent from my Android phone with K-9 Mail. Please excuse my brevity.

Answer 6 · 2012-09-11T00:49:45.000Z

Ok well I can reproduce this: It throws an error whenever a single property changes. Best guess is that it cannot create/execute the command to modify that one property because i've malformed it somehow. Looking into it now!

Answer 7 · 2012-09-11T01:06:04.000Z

The problem was a simple syntax error in the handling of printer options. I've changed how options are handled and pushed up a new revision. Give it a try when you have time!

Answer 8 · 2012-09-11T18:56:54.000Z

Works much better now. I did get a message once that I've not seen again:

/var/lib/puppet/lib/puppet/provider/printer/cups.rb:38: warning: already initialized constant Cups_Options

This occurred via "sudo puppet agent -t" whereas I usually do "sudo -i puppet agent -t" because in the past puppet has often complained when running from my home dir. It didn't this time or in any other attempts to reproduce the above, so I doubt it has anything to do with the error. Regardless, I was unable to get this error message again. I'll keep an eye out for it to see if I can recognize any pattern.

Answer 9 · 2012-09-12T01:23:06.000Z

I have seen issues similar to that, when a plugin is loaded several times. It's something i really have to ask the puppet guys RE what the best way of putting constants into a plugin is.

Answer 10 · 2012-09-12T13:18:06.000Z

It is strange that it seems non-deterministic. Offhand, do you know why all the facts (and I presume plugins as a whole) get loaded twice? I see it with your module as well as my own:

info: Retrieving plugin
info: Loading facts in plant_number
info: Loading facts in printers
info: Loading facts in selinux_simple
info: Loading facts in plant_number
info: Loading facts in printers
info: Loading facts in selinux_simple
info: Caching catalog for myhost.example.com
info: Applying configuration version '1347455471'
notice: /Stage[main]/Example::Myhost/Printer[dell]/accept: accept changed 'false' to 'true'
notice: Finished catalog run in 10.20 seconds

Answer 11 · 2012-09-12T17:16:14.000Z

Even with v1.1.1, I am still seeing the following from most, if not all, puppet runs after the initial printer set up. The strangest part though is that this appears to only happen via catalog applications from the daemon. If I manually run puppet agent -t it's all clean.

/Stage[main]/Example::Myhost/Printer[dell]/model (notice): defined 'model' as 'foomatic:Dell-3100cn-pxlcolor.ppd'
/Stage[main]/Example::Myhost/Printer[dell] (err): Could not evaluate: too few arguments
/Stage[main]/Example::Myhost/Printer[TESTJF]/model (notice): defined 'model' as 'raw'
/Stage[main]/Example::Myhost/Printer[TESTJF] (err): Could not evaluate: too few arguments

Answer 12 · 2012-09-12T23:28:15.000Z

That's... perplexing. Most runs I do when testing are manually invoked. I'll give the daemon a shot but i might have to spin up a linux VM first. I think i've had that error before and it was a parsing error.

Answer 13 · 2012-09-13T12:36:13.000Z

Perplexing indeed. I usually test the same way and figured I was good to go until the tagmail starting appearing. I suppose it's possible that this is SELinux. I checked the logs and saw no AVCs, but I know the policy is capable of hushing some special cases -- a "feature" that has burned me before. I'll turn off SELinux for a few hours and see if that makes any diff.

Answer 14 · 2012-09-13T18:01:26.000Z

Disabling SELinux did not seem to have any effect.

Answer 15 · 2012-09-13T23:40:46.000Z

It's more likely that the result of lpstat -l -p fails to parse in some way. Haven't got a VM running yet.

Answer 16 · 2012-09-17T14:25:47.000Z

Just to make sure we're in sync, I should still expect the "Could not evaluate: too few arguments" messages with v1.2.1, because you don't have a VM set up yet, right?

Answer 17 · 2012-09-18T07:27:03.000Z

yep. I cannot replicate it on this machine but haven't had time to set up a VM yet.

Answer 18 · 2012-09-25T00:25:52.000Z

I set up a CentOS 6 VM with puppet, and a manifest with some raw queues. I didn't get the same kind of parsing error that you are having. Is there a specific platform i can test on (sorry if you've stated this before)?.

Answer 19 · 2012-09-25T00:34:05.000Z

Not certain if I'd stated, but this was on Fedora 16. I'll try 17 and 18 tomorrow.

mosen notifications@github.com wrote:

I set up a CentOS 6 VM with puppet, and a manifest with some raw
queues. I didn't get the same kind of parsing error that you are
having. Is there a specific platform i can test on (sorry if you've
stated this before)?.

Reply to this email directly or view it on GitHub:
#6 (comment)

Sent from my Android phone with K-9 Mail. Please excuse my brevity.

Answer 20 · 2012-09-25T01:04:12.000Z

building a Fedora 16 VM now.

Answer 21 · 2012-09-25T05:36:17.000Z

Still no errors like that in Fedora 16 VM. So what I suspect is that I cannot parse one of your queues for some reason. Could you try deleting all of the queues and re-adding one at a time.. but doing 2 puppet runs per queue. One to add, and one to parse the already added queue. This way, I can find out which option or parameter causes the parsing to break.

Answer 22 · 2012-09-26T19:06:54.000Z

Still no errors like that in Fedora 16 VM. So what I suspect is that I
cannot parse one of your queues for some reason. Could you try deleting
all of the queues and re-adding one at a time.. but doing 2 puppet runs
per queue. One to add, and one to parse the already added queue. This way,
I can find out which option or parameter causes the parsing to break.

Did you remember to just allow the daemon to try and apply the catalog?
If I run puppet interactively, I don't see the error messages:

$  sudo -i puppet agent -t
info: Retrieving plugin
info: Loading facts in printers
info: Loading facts in printers
info: Caching catalog for myhost.example.com
info: Applying configuration version '1348683623'
notice: /Stage[main]/Example::Myhost/Printer[dell]/ensure: created
notice: Finished catalog run in 23.61 seconds
$  sudo -i puppet agent -t
info: Retrieving plugin
info: Loading facts in printers
info: Loading facts in printers
info: Caching catalog for myhost.example.com
info: Applying configuration version '1348683623'
notice: Finished catalog run in 7.38 seconds

Whereas, if I just wait 15-30 minutes longer for the puppet daemon to come
around and do (purportedly, the exact same) things on its own, I see (via
tagmail):

2012-09-26 14:50:23 -0400 /Stage[main]/Example::Myhost/Printer[dell]/model
(notice): defined 'model' as 'foomatic:Dell-3100cn-pxlcolor.ppd'
2012-09-26 14:50:23 -0400 /Stage[main]/Example::Myhost/Printer[dell]
(err): Could not evaluate: too few arguments

In this case, the errors appeared on the 3rd run (overall and first by the
daemon since the queue was destroyed), but will continue indefinetly from
each daemon run, but never from manual runs.

For the record, this is the printer resource I have in my node's class:

    printer { 'dell':
        accept          => true,
        description     => 'color laser printer',
        enabled         => true,
        ensure          => present,
        location        => 'office of John Florian',
        model           => 'foomatic:Dell-3100cn-pxlcolor.ppd',
        shared          => false,
        uri             => 'socket://10.1.193.23:9100',
    }

Answer 23 · 2012-09-26T23:16:08.000Z

Hi there,
Sorry I somehow mixed up what you said earlier and interpreted that as running puppet apply vs puppet agent. Let me apply the same parameters in daemon mode and see what i get.