Skipping because provider prefetch failed #9532

andryua · 2024-12-16T13:41:18Z

Describe the Bug

After update puppet agent to 8.10.0 i have errors wit chocolatey provider (8.7.0 - working)

Steps to Reproduce

Steps to reproduce the behavior:
in powershell or cmd running command
puppet agent -t

Environment

Version 8.10.0
Platform Windows 10 or 11

Output:

Debug: Prefetching windows resources for chocolateyfeature
Debug: Gathering features from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: Could not prefetch chocolateyfeature provider 'windows': Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Warning: /Stage[main]/Windows::Chocolatey/Chocolateyfeature[allowEmptyChecksums]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateyfeature[allowEmptyChecksums]: Resource is being skipped, unscheduling all events
Debug: Prefetching windows resources for chocolateyconfig
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: Could not prefetch chocolateyconfig provider 'windows': Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Warning: /Stage[main]/Windows::Chocolatey/Chocolateyconfig[cachelocation]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateyconfig[cachelocation]: Resource is being skipped, unscheduling all events
Debug: Prefetching windows resources for chocolateysource
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Warning: /Stage[main]/Windows::Chocolatey/Chocolateysource[chocolatey]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateysource[chocolatey]: Resource is being skipped, unscheduling all events
Warning: /Stage[main]/Windows::Chocolatey/Chocolateysource[stable]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateysource[stable]: Resource is being skipped, unscheduling all events
Warning: /Stage[main]/Windows::Chocolatey/Chocolateysource[testing]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateysource[testing]: Resource is being skipped, unscheduling all events
Debug: Class[Windows::Chocolatey]: Resource is being skipped, unscheduling all events

The text was updated successfully, but these errors were encountered:

mhashizume · 2024-12-17T21:31:28Z

Thank you for reporting this @andryua , I saw you also opened an issue in the Chocolatey module. We will chat with the modules team and see if we can determine where the issue lies.

andryua · 2024-12-31T11:41:35Z

Hi! Can you help me? I using chocolatey 0.15 or 1.31 not latest version. And one more - we configuring chocolatey by puppet and after update to 8.8.1 - puppet agent always rerewrited config.xml (chocolatey config file). now we using 8.7.0 - that version working ok.

andryua · 2024-12-31T11:42:47Z

if i update to chocolatey lates version - error still exist on puppet agent 8.10.0

andryua · 2025-01-06T10:07:36Z

puppet-chocolatey breaks chocolatey.config when modified

Debug: Prefetching windows resources for chocolateysource
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Debug: Loaded source '{:name=>"chocolatey", :location=>"https://community.chocolatey.org/api/v2/", :ensure=>:present, :priority=>"0", :bypass_proxy=>false, :admin_only=>false, :allow_self_se
Notice: /Stage[main]/Windows::Chocolatey/Chocolateysource[chocolatey]/ensure: ensure changed 'present' to 'disabled'
Debug: Executing: '[redacted]'
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: /Stage[main]/Windows::Chocolatey/Chocolateysource[chocolatey]: Could not evaluate: Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: /Stage[main]/Windows::Chocolatey/Chocolateysource[stable]: Could not evaluate: Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: /Stage[main]/Windows::Chocolatey/Chocolateysource[testing]: Could not evaluate: Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Debug: Prefetching windows resources for chocolateyfeature
Debug: Gathering features from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: Could not prefetch chocolateyfeature provider 'windows': Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Warning: /Stage[main]/Windows::Chocolatey/Chocolateyfeature[allowEmptyChecksums]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateyfeature[allowEmptyChecksums]: Resource is being skipped, unscheduling all events
Debug: Prefetching windows resources for chocolateyconfig
Debug: Gathering sources from 'C:\ProgramData\chocolatey\config\chocolatey.config'.
Error: Could not prefetch chocolateyconfig provider 'windows': Malformed XML: Content at the start of the document (got 'Γê⌐ΓòùΓöÉ')
Line: 1
Position: 47
Last 80 unconsumed characters:
<?xml version="1.0" encoding="utf-8"?>
Warning: /Stage[main]/Windows::Chocolatey/Chocolateyconfig[cachelocation]: Skipping because provider prefetch failed
Debug: /Stage[main]/Windows::Chocolatey/Chocolateyconfig[cachelocation]: Resource is being skipped, unscheduling all events
Debug: Class[Windows::Chocolatey]: Resource is being skipped, unscheduling all events

andryua · 2025-01-06T12:55:47Z

after investigation - problem in REXML. Last working version is - 3.3.2. Newest version - puppet agent sending errors. (puppet agent 8.9.0 upgrated to rexml - 3.3.6)

joshcooper · 2025-01-06T23:54:05Z

@andryua Thanks, could you provide a minimal XML reproduction that triggers the bug?

andryua · 2025-01-07T07:09:08Z

this is config file (i renamed it into txt)
chocolatey.txt

i validated it on online xml validators - everything is ok

andryua · 2025-01-07T10:03:18Z

new investigation result - after check UTF-8 parameter - everything work fine (without errors), if unckecked - not good. But I can't use this parameter :(

joshcooper · 2025-01-07T16:36:31Z

The problematic config contains a byte order mark (BOM) maybe there was a regression in rexml with respect to stripping the BOM out?

❯ od -tc ~/Downloads/chocolatey.txt | head -1
0000000 357 273 277   <   ?   x   m   l       v   e   r   s   i   o   n

❯ od -t x1 ~/Downloads/chocolatey.txt | head -1
0000000 ef bb bf 3c 3f 78 6d 6c 20 76 65 72 73 69 6f 6e

andryua · 2025-01-08T11:34:41Z

Maybe. I don't know. So, what do You recommend me?

andryua · 2025-01-08T13:07:47Z

Chocolatey support answered:


The problematic config contains a byte order mark (BOM) maybe there was a regression in rexml with respect to stripping the BOM out?

This appears to be an upstream issue in REXML, which needs to be fixed there.

I don't think that there is realistically anything that we (Chocolatey) can do here, sorry!```

gep13 · 2025-01-08T13:38:59Z

👋 Chocolatey Team Memer here. Just to expand further on this...

@andryua said...
Chocolatey support answered:

This was being discussed in our Discord channel here:

https://discord.com/channels/778552361454141460/897088817293574154/1326489091021471789

The encoding of the chocolatey.config file is UTF-8-BOM (as can be seen here), and it has been for at least 11 years (April 16, 2014 which is the date of the last commit that I can easily see in the repository).

So nothing has changed with the encoding on this configuration file from a Chocolatey perspective in that time.

I tend to agree with this comment from @joshcooper:

maybe there was a regression in rexml with respect to stripping the BOM out?

If there is anything that we can do to help, please let me know.

andryua · 2025-01-10T08:05:47Z

Hi! Maybe, I found how to resolve this issue:
puppetlabs-chocolatey using (all files in this subdirectories - https://github.com/puppetlabs/puppetlabs-chocolatey/tree/main/lib/puppet/provider):
config = REXML::Document.new File.read(choco_config)
its a problem, because that function open file in one string with BOM symbols, but if using this
config = REXML::Document.new File.open(choco_config)
it will be using UTF8 with BOM too (like chocolatey.config using) and puppet dont sent errors anymore (i tested by myself)
and one more thing - enabling UTF8 WorlWide support in windows 10/11 is not necessarily

andryua · 2025-01-10T10:57:41Z

or

    config = nil
    File.open(choco_config) do |file|
        content = file.read
        config = REXML::Document.new(content)
    end

against

config = REXML::Document.new File.read(choco_config)

github-actions · 2025-01-14T17:32:57Z

Migrated issue to PUP-12090

joshcooper · 2025-01-14T17:35:02Z

ruby/rexml#231

joshcooper · 2025-01-15T01:00:00Z

Hi @andryua I was not able to reproduce the problem using puppet-agent 8.10.0 and rexml 3.3.6 with the chocolatey config you provided. Both File.read and File.open worked as expected for me:

C:\ProgramData\PuppetLabs>puppet --version
8.10.0

C:\ProgramData\PuppetLabs>"c:\Program Files\Puppet Labs\Puppet\puppet\bin\ruby.exe" --version
ruby 3.2.5 (2024-07-26 revision 31d0f1a2e7) [x64-mingw32]

C:\ProgramData\PuppetLabs>"c:\Program Files\Puppet Labs\Puppet\puppet\bin\gem.bat" which rexml
c:/Program Files/Puppet Labs/Puppet/puppet/lib/ruby/gems/3.2.0/gems/rexml-3.3.6/lib/rexml.rb

C:\ProgramData\PuppetLabs>chcp
Active code page: 437

C:\ProgramData\PuppetLabs>type rex.rb
require 'rexml'

choco_config = 'chocolatey.txt'
config = REXML::Document.new File.read(choco_config)
puts "File.read"
puts config.elements.to_a('//add').first

File.open(choco_config) do |file|
  content = file.read
  config = REXML::Document.new(content)
  puts "File.open"
  puts config.elements.to_a('//add').first
end

C:\ProgramData\PuppetLabs>"c:\Program Files\Puppet Labs\Puppet\puppet\bin\ruby.exe" rex.rb
File.read
<add description='Cache location if not TEMP folder. Replaces `$env:TEMP` value for choco.exe process. It is highly recommended this be set to make Chocolatey more deterministic in cleanup.' key='cacheLocation' value='C:\ProgramData\chocolatey\cache'/>
File.open
<add description='Cache location if not TEMP folder. Replaces `$env:TEMP` value for choco.exe process. It is highly recommended this be set to make Chocolatey more deterministic in cleanup.' key='cacheLocation' value='C:\ProgramData\chocolatey\cache'/>

I tried changing the active code page to 1251, but get the same result:

C:\ProgramData\PuppetLabs>chcp 1251
Active code page: 1251

C:\ProgramData\PuppetLabs>"c:\Program Files\Puppet Labs\Puppet\puppet\bin\ruby.exe" rex.rb
File.read
<add description='Cache location if not TEMP folder. Replaces `$env:TEMP` value for choco.exe process. It is highly recommended this be set to make Chocolatey more deterministic in cleanup.' key='cacheLocation' value='C:\ProgramData\chocolatey\cache'/>
File.open
<add description='Cache location if not TEMP folder. Replaces `$env:TEMP` value for choco.exe process. It is highly recommended this be set to make Chocolatey more deterministic in cleanup.' key='cacheLocation' value='C:\ProgramData\chocolatey\cache'/>

Are you sure you're running ruby from the puppet-agent package? Are you setting any environment variables like RUBY_OPTS that might change the Encoding.default_external?

Could you try the following?

C:\ProgramData\PuppetLabs>"c:\Program Files\Puppet Labs\Puppet\puppet\bin\ruby.exe" -e "puts File.read('chocolatey.txt', encoding: 'bom|utf-8')"
<?xml version="1.0" encoding="utf-8"?>
<chocolatey xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
...

Ruby's File.read accepts an encoding option, but it is not well documented until recently. If chocolatey.xml is always UTF-8 encoded (with or without a BOM), then perhaps the chocolatey package provider should specify:

File.read(choco_config, encoding: 'bom|utf-8')

andryua · 2025-01-15T07:55:29Z

Hi! I tried with BOM and without BOM - look at this different symbols, please


<?xml version="1.0" encoding="utf-8"?>
<chocolatey xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  ...

C:\ProgramData\cygwin\home\root>"c:\Program Files\Puppet Labs\Puppet\puppet\bin\ruby.exe" -e "puts File.read('c:\programdata\chocolatey\config\chocolatey.config')"
я╗┐<?xml version="1.0" encoding="utf-8"?>
<chocolatey xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
...

if in provider (like i said in upper post) use File.open - not File.read! - everything work fine!
To reproduct my problem - you can try to change chocolatey.config file via puppet and you can see errors. if I deleted changing chocolaey functions - everything work fine
example:

chocolateysource {'chocolatey':
    	ensure    => disabled,
     }

or

chocolateyconfig {'cachelocation':
		value => "C:\\ProgramData\\chocolatey\\cache",
	}

andryua · 2025-01-15T07:57:14Z

and one more thing - I using Ukrainian language for Windows, not English

joshcooper · 2025-01-15T19:37:30Z

Based on C:\ProgramData\cygwin\home\root it looks like you're using cygwin? From the Start menu, can you run "Start Command Prompt with Puppet" , delete any cygwin directories from your PATH and run ruby rex.rb? Also include the output of set?

andryua · 2025-01-16T06:52:13Z

andryua · 2025-01-16T07:00:19Z

I using cp866 by default code page. And You can see if running your script - everithing work ok, but, if I using command - ruby.exe -e "puts File.read('c:\programdata\chocolatey\config\chocolatey.config')" - first symbol was a problem for puppet-chocolatey provider.
I tried to use forked puppetlabs-chocolatey and changing there read to open - and all working good (puppet didin't send errors). but, if I changed to File.read - puppet sending errors again

andryua added the bug Something isn't working label Dec 16, 2024

mhashizume mentioned this issue Dec 17, 2024

Skipping because provider prefetch failed puppetlabs/puppetlabs-chocolatey#367

Closed

joshcooper added the triaged Jira issue has been created for this label Jan 14, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Skipping because provider prefetch failed #9532

Skipping because provider prefetch failed #9532

andryua commented Dec 16, 2024

mhashizume commented Dec 17, 2024

andryua commented Dec 31, 2024

andryua commented Dec 31, 2024

andryua commented Jan 6, 2025 •

edited

Loading

andryua commented Jan 6, 2025

joshcooper commented Jan 6, 2025

andryua commented Jan 7, 2025 •

edited

Loading

andryua commented Jan 7, 2025

joshcooper commented Jan 7, 2025

andryua commented Jan 8, 2025

andryua commented Jan 8, 2025

gep13 commented Jan 8, 2025

andryua commented Jan 10, 2025

andryua commented Jan 10, 2025 •

edited

Loading

github-actions bot commented Jan 14, 2025

joshcooper commented Jan 14, 2025

joshcooper commented Jan 15, 2025

andryua commented Jan 15, 2025

andryua commented Jan 15, 2025

joshcooper commented Jan 15, 2025

andryua commented Jan 16, 2025

andryua commented Jan 16, 2025

Skipping because provider prefetch failed #9532

Skipping because provider prefetch failed #9532

Comments

andryua commented Dec 16, 2024

Describe the Bug

Steps to Reproduce

Environment

mhashizume commented Dec 17, 2024

andryua commented Dec 31, 2024

andryua commented Dec 31, 2024

andryua commented Jan 6, 2025 • edited Loading

andryua commented Jan 6, 2025

joshcooper commented Jan 6, 2025

andryua commented Jan 7, 2025 • edited Loading

andryua commented Jan 7, 2025

joshcooper commented Jan 7, 2025

andryua commented Jan 8, 2025

andryua commented Jan 8, 2025

gep13 commented Jan 8, 2025

andryua commented Jan 10, 2025

andryua commented Jan 10, 2025 • edited Loading

github-actions bot commented Jan 14, 2025

joshcooper commented Jan 14, 2025

joshcooper commented Jan 15, 2025

andryua commented Jan 15, 2025

andryua commented Jan 15, 2025

joshcooper commented Jan 15, 2025

andryua commented Jan 16, 2025

andryua commented Jan 16, 2025

andryua commented Jan 6, 2025 •

edited

Loading

andryua commented Jan 7, 2025 •

edited

Loading

andryua commented Jan 10, 2025 •

edited

Loading