Comments (16)
I rebuilt the host, and did this again, ensuring the directories were there before running the bolt plans/tasks. They were, and the result was identical.
from puppet-patching.
I will take a look! Sounds like a bug and we need to simply create the directory if it doesn't exist (thought I had that covered, but maybe there is a gap).
Any insight into what might be different? What version of Windows? Anything with directory permissions maybe?
from puppet-patching.
The directory was created before I ran the plan... I think the plans/task try to access the patching.json file before it gets created. It was not there prior to running the plan for the first time, assume it remains there for subsequent runs and that may be why the script assumes it is there?
At the end of the first run of the plan, both the log and json files were present.
This is PE 2019.3.0
Client was windows 2016 server standard. Puppet server is on rhel 7.
from puppet-patching.
I think this is from using Add-Content on a file that doesn't yet exist, in tasks/update_windows.ps1
from puppet-patching.
@sirinek I agree, i think we need a function to "Create directory and file if it doesn't exist" something with Test-Path
and New-Item
.
from puppet-patching.
Forgot to mention the plan was launched from a rhel7 host running bolt 1.48. not sure if it makes a difference.
from puppet-patching.
So I've tried to get around this issue by ensuring the file was present before running the plan for the first time and it's failed. The first time, I used a blank file in c:\programdata\patching\log\patching.json and the second time I just had the contents of {}
Both times the output was the same:
Starting: plan patching
Starting: plan patching::check_puppet
Starting: task puppet_agent::version on windowshost.company.com
Finished: task puppet_agent::version with 0 failures in 1.42 sec
Starting: plan patching::puppet_facts
Starting: task patching::puppet_facts on windowshost.company.com
Finished: task patching::puppet_facts with 0 failures in 6.5 sec
Finished: plan patching::puppet_facts in 6.51 sec
Finished: plan patching::check_puppet in 7.95 sec
Starting: plan patching::ordered_groups
Groups = []
Group '' nodes = [windowshost.company.com]
Finished: plan patching::ordered_groups in 0.02 sec
Starting: task patching::cache_update on windowshost.company.com
Finished: task patching::cache_update with 0 failures in 1.24 sec
Starting: plan patching::available_updates
Starting: task patching::available_updates on windowshost.company.com
Finished: task patching::available_updates with 0 failures in 305.91 sec
Host update status: ('+' has available update; '-' no update) [num updates]
+ windowshost.company.com [1]
Finished: plan patching::available_updates in 5 min, 6 sec
Starting: plan patching::pre_update
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.01 sec
Starting: plan patching::pre_post_update
pre_post_update - noop = false
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.01 sec
Starting: task patching::pre_update on windowshost.company.com
Finished: task patching::pre_update with 0 failures in 1.26 sec
Finished: plan patching::pre_post_update in 1.3 sec
Finished: plan patching::pre_update in 1.35 sec
Starting: task patching::update on windowshost.company.com
Finished: task patching::update with 1 failure in 1044.63 sec
The following hosts failed during update:
[{"target":"windowshost.company.com","action":"task","object":"patching::update","status":"failure","result":{"_output":"null","_error":{"kind":"puppetlabs.tasks/task-error","issue_code":"TASK_ERROR","msg":"The task failed with exit code unknown","details":{"exit_code":"unknown"}}},"node":"windowshost.company.com"}]
Starting: wait until available on windowshost.company.com
Finished: wait until available with 0 failures in 0.04 sec
Starting: plan patching::update_history
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.01 sec
Starting: task patching::update_history on windowshost.company.com
Finished: task patching::update_history with 0 failures in 2.37 sec
Finished: plan patching::update_history in 2.4 sec
Finished: plan patching in 22 min, 44 sec
{
"kind": "bolt/pal-error",
"msg": "'size' parameter 'arg' expects a value of type Collection, String, or Binary, got Undef",
"details": {
}
}
from puppet-patching.
To address the issue of patching.json being appended to while missing, I've tried:
- Starting the plan with a json file only containing {}
- Starting the plan after creating a valid json file:
{
"upgraded": [ ],
"installed": [ ]
}
- Forking the repo and making the change to ensure the file exists and if not, create a blank file.
All give me the same error as shown in my previous comment:
The following hosts failed during update:
[{"target":"windowshost.company.com","action":"task","object":"patching::update","status":"failure","result":{"_output":"null","_error":{"kind":"puppetlabs.tasks/task-error","issue_code":"TASK_ERROR","msg":"The task failed with exit code unknown","details":{"exit_code":"unknown"}}},"node":"windowshost.company.com"}]
. . .
{
"kind": "bolt/pal-error",
"msg": "'size' parameter 'arg' expects a value of type Collection, String, or Binary, got Undef",
"details": {
}
}
from puppet-patching.
When I run the plan a second time on the same host the pretty printing works:
bsirinek@puppet $ bolt plan run --transport=pcp patching reboot_strategy=only_required monitoring_enabled=false snapshot_plan=disabled nodes=windowshost.company.com
Starting: plan patching
Starting: plan patching::check_puppet
Starting: task puppet_agent::version on windowshost.company.com
Finished: task puppet_agent::version with 0 failures in 1.53 sec
Starting: plan patching::puppet_facts
Starting: task patching::puppet_facts on windowshost.company.com
Finished: task patching::puppet_facts with 0 failures in 6.62 sec
Finished: plan patching::puppet_facts in 6.64 sec
Finished: plan patching::check_puppet in 8.18 sec
Starting: plan patching::ordered_groups
Groups = []
Group '' nodes = [windowshost.company.com]
Finished: plan patching::ordered_groups in 0.04 sec
Starting: task patching::cache_update on windowshost.company.com
Finished: task patching::cache_update with 0 failures in 2.64 sec
Starting: plan patching::available_updates
Starting: task patching::available_updates on windowshost.company.com
Finished: task patching::available_updates with 0 failures in 183.47 sec
Host update status: ('+' has available update; '-' no update) [num updates]
- windowshost.company.com [0]
Finished: plan patching::available_updates in 3 min, 3 sec
Starting: wait until available on windowshost.company.com
Finished: wait until available with 0 failures in 0.05 sec
Starting: plan patching::update_history
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.01 sec
Starting: task patching::update_history on windowshost.company.com
Finished: task patching::update_history with 0 failures in 1.29 sec
host | upgraded | installed
-----------------------------------------------------
windowshost.company.com | 1 | 0
Finished: plan patching::update_history in 1.33 sec
Finished: plan patching in 3 min, 16 sec
Plan completed successfully with no result
from puppet-patching.
The JSON looks like:
{
"upgraded" : [ {
"server_selection" : 0,
"name" : "2020-02 Cumulative Update for Windows Server 2016 for x64-based Systems (KB4537764)",
"result_code" : 2,
"result" : "succeeded",
"id" : "682fa286-32a1-4c8f-b939-ed54f005703c",
"version" : 200,
"kb_ids" : [ "4537764" ],
"provider" : "windows",
"reboot_required" : true
} ],
"installed" : [ ]
}
from puppet-patching.
Setting format to 'none' on line 266 of plans/init.pp removed the error I got at the end of the bolt plan run. However I still get the error for patching::update I showed earlier
Here's the patching.log from the host I patched.
[2020-02-25T12:21:16.3338094-05:00] ==================================================================================
[2020-02-25T12:21:16.3418100-05:00] = Starting Update
[2020-02-25T12:21:16.3448092-05:00] provider = all
[2020-02-25T12:21:16.3498107-05:00] =========================================
[2020-02-25T12:21:16.3518081-05:00] = Starting Update-Windows
[2020-02-25T12:21:16.6448349-05:00] =========================================
[2020-02-25T12:21:16.6658366-05:00] = Starting Update-Windows in scheduled task
[2020-02-25T12:21:16.6818362-05:00] Starting search for updates...
[2020-02-25T12:24:17.9294599-05:00] Finished search for updates...
[2020-02-25T12:24:17.9364608-05:00] ===============
[2020-02-25T12:24:17.9394604-05:00] = Starting server selection: 0
[2020-02-25T12:24:17.9434614-05:00] Number of updates returned from search: 1
[2020-02-25T12:24:17.9944652-05:00] Number of updates to install: 1
[2020-02-25T12:24:17.9974641-05:00] Number of updates to download: 1
[2020-02-25T12:24:18.0104662-05:00] Updates to be installed: [
{
"id": "652fa296-32a1-4c9f-b939-ed54f005703b",
"name": "2020-02 Cumulative Update for Windows Server 2016 for x64-based Systems (KB4537764)",
"server_selection": 0,
"provider": "windows",
"kb_ids": [
"4537764"
],
"version": 200
}
]
[2020-02-25T12:24:18.0344681-05:00] Starting to download updates...
[2020-02-25T12:25:16.0944110-05:00] Finished downloading updates...
[2020-02-25T12:25:16.1064130-05:00] Starting update installs...
[2020-02-25T12:39:28.4274824-05:00] Finished update installs...
[2020-02-25T12:39:28.4556900-05:00] Parsing update results...
[2020-02-25T12:39:28.6128536-05:00] = Finished server selection: 0
[2020-02-25T12:39:28.6214810-05:00] ===============
[2020-02-25T12:39:29.2496130-05:00] = Finishing Update-Windows
[2020-02-25T12:39:29.2526136-05:00] =========================================
[2020-02-25T12:39:29.2776153-05:00] =========================================
[2020-02-25T12:39:29.2806159-05:00] = Starting Update-Chocolatey
[2020-02-25T12:39:29.2826161-05:00] Searching for choco command
[2020-02-25T12:39:29.2886155-05:00] choco command exists!
[2020-02-25T12:39:29.2906177-05:00] Executing: choco upgrade all --yes --limit-output --no-progress --ignore-unfound
[2020-02-25T12:39:31.7114575-05:00] Finished: choco ugprade ... exit_code = 0
[2020-02-25T12:39:31.7144581-05:00] Upgrading the following packages:
all
By upgrading you accept licenses for the packages.
7zip|18.5.0.20180730|18.5.0.20180730|false
7zip.install|18.5.0.20180730|18.5.0.20180730|false
chocolatey|0.10.11|0.10.11|false
chocolatey-core.extension|1.3.3|1.3.3|false
googlechrome|70.0.3538.77|70.0.3538.77|false
notepadplusplus|7.5.9|7.5.9|false
notepadplusplus.install|7.5.9|7.5.9|false
splunkforwarder|7.2.0.0|7.2.0.0|false
Chocolatey upgraded 0/8 packages.
See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).
[2020-02-25T12:39:31.7244589-05:00] = Finishing Update-Chocolatey
[2020-02-25T12:39:31.7274595-05:00] =========================================
[2020-02-25T12:39:31.7568331-05:00] = Finished Update
[2020-02-25T12:39:31.7598515-05:00] ==================================================================================
PS C:\programdata\patching\log>
from puppet-patching.
We've been going back/forth on slack and have figured out it's related to PCP transport. Bolt must do something special with PowerShell on Windows when using the PCP transport different than WinRM.
from puppet-patching.
Both of these logs are from a new windows 2016 box with the same single update waiting in WSUS.
Here's the output from bolt when running over the pcp transport:
Starting: plan patching
Starting: plan patching::check_puppet
Starting: task puppet_agent::version on windowshost.company.com
Finished: task puppet_agent::version with 0 failures in 1.32 sec
Starting: plan patching::puppet_facts
Starting: task patching::puppet_facts on windowshost.company.com
Finished: task patching::puppet_facts with 0 failures in 6.5 sec
Finished: plan patching::puppet_facts in 6.51 sec
Finished: plan patching::check_puppet in 7.84 sec
Starting: plan patching::ordered_groups
Groups = []
Group '' nodes = [windowshost.company.com]
Finished: plan patching::ordered_groups in 0.04 sec
Starting: task patching::cache_update on windowshost.company.com
Finished: task patching::cache_update with 0 failures in 1.27 sec
Starting: plan patching::available_updates
Starting: task patching::available_updates on windowshost.company.com
Finished: task patching::available_updates with 0 failures in 306.22 sec
Host update status: ('+' has available update; '-' no update) [num updates]
+ windowshost.company.com [1]
Finished: plan patching::available_updates in 5 min, 6 sec
Starting: plan patching::pre_update
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.01 sec
Starting: plan patching::pre_post_update
pre_post_update - noop = false
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.01 sec
Starting: task patching::pre_update on windowshost.company.com
Finished: task patching::pre_update with 0 failures in 1.26 sec
Finished: plan patching::pre_post_update in 1.31 sec
Finished: plan patching::pre_update in 1.35 sec
Starting: task patching::update on windowshost.company.com
Finished: task patching::update with 1 failure in 1044.84 sec
The following hosts failed during update:
[{"target":"windowshost.company.com","action":"task","object":"patching::update","status":"failure","value":{"_output":"null","_error":{"kind":"puppetlabs.tasks/task-error","issue_code":"TASK_ERROR","msg":"The task failed with exit code unknown","details":{"exit_code":"unknown"}}}}]
Starting: wait until available on windowshost.company.com
Finished: wait until available with 0 failures in 0.04 sec
Starting: plan patching::update_history
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.02 sec
Starting: task patching::update_history on windowshost.company.com
Finished: task patching::update_history with 0 failures in 1.38 sec
Finished: plan patching::update_history in 1.42 sec
Finished: plan patching in 22 min, 43 sec
This is the log when using the WinRM transport:
Starting: plan patching
Starting: plan patching::check_puppet
Starting: task puppet_agent::version on windowshost.company.com
Finished: task puppet_agent::version with 0 failures in 1.24 sec
Starting: plan patching::puppet_facts
Starting: task patching::puppet_facts on windowshost.company.com
Finished: task patching::puppet_facts with 0 failures in 6.29 sec
Finished: plan patching::puppet_facts in 6.31 sec
Finished: plan patching::check_puppet in 7.59 sec
Starting: plan patching::ordered_groups
Groups = []
Group '' nodes = [windowshost.company.com]
Finished: plan patching::ordered_groups in 0.03 sec
Starting: task patching::cache_update on windowshost.company.com
Finished: task patching::cache_update with 0 failures in 1.38 sec
Starting: plan patching::available_updates
Starting: task patching::available_updates on windowshost.company.com
Finished: task patching::available_updates with 0 failures in 320.12 sec
Host update status: ('+' has available update; '-' no update) [num updates]
+ windowshost.company.com [1]
Finished: plan patching::available_updates in 5 min, 20 sec
Starting: plan patching::pre_update
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.0 sec
Starting: plan patching::pre_post_update
pre_post_update - noop = false
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.0 sec
Starting: task patching::pre_update on windowshost.company.com
Finished: task patching::pre_update with 0 failures in 0.93 sec
Finished: plan patching::pre_post_update in 0.95 sec
Finished: plan patching::pre_update in 0.97 sec
Starting: task patching::update on windowshost.company.com
Finished: task patching::update with 0 failures in 1173.5 sec
Starting: plan patching::post_update
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.0 sec
Starting: plan patching::pre_post_update
pre_post_update - noop = false
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.0 sec
Starting: task patching::post_update on windowshost.company.com
Finished: task patching::post_update with 0 failures in 1.3 sec
Finished: plan patching::pre_post_update in 1.31 sec
Finished: plan patching::post_update in 1.32 sec
Starting: plan patching::reboot_required
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.0 sec
Starting: task patching::reboot_required on windowshost.company.com
Finished: task patching::reboot_required with 0 failures in 2.53 sec
Reboot strategy: always
Host reboot required status: ('+' reboot required; '-' reboot NOT required)
+ windowshost.company.com
Starting: plan reboot
Starting: task reboot on windowshost.company.com
Finished: task reboot with 0 failures in 0.9 sec
Finished: plan reboot in 5 min, 16 sec
Finished: plan patching::reboot_required in 5 min, 19 sec
Starting: wait until available on windowshost.company.com
Finished: wait until available with 0 failures in 0.34 sec
Starting: plan patching::update_history
Starting: plan patching::get_targets
Finished: plan patching::get_targets in 0.0 sec
Starting: task patching::update_history on windowshost.company.com
Finished: task patching::update_history with 0 failures in 1.01 sec
Finished: plan patching::update_history in 1.02 sec
Finished: plan patching in 30 min, 25 sec
Plan completed successfully with no result
from puppet-patching.
FYI found the code in the patching::update_windows
task that creates the directory if it doesn't exist: https://github.com/EncoreTechnologies/puppet-patching/blob/master/tasks/update_windows.ps1#L344-L345
Starting to think it's something with the context that PCP agent is running in. Definitely looks like something is crashing in the patching::update_windows
task that has downstream effects when trying to read the results file in patching::update_history_windows
from puppet-patching.
Here is the latest log:
[2020-02-26T15:05:22.1424600-05:00] ==================================================================================
[2020-02-26T15:05:22.1544617-05:00] = Starting Update
[2020-02-26T15:05:22.1564615-05:00] provider = all
[2020-02-26T15:05:22.1614619-05:00] =========================================
[2020-02-26T15:05:22.1634604-05:00] = Starting Update-Windows
[2020-02-26T15:05:22.4774872-05:00] =========================================
[2020-02-26T15:05:22.4994890-05:00] = Starting Update-Windows in scheduled task
[2020-02-26T15:05:22.5164904-05:00] Starting search for updates...
[2020-02-26T15:08:23.4012889-05:00] Finished search for updates...
[2020-02-26T15:08:23.4092909-05:00] ===============
[2020-02-26T15:08:23.4112900-05:00] = Starting server selection: 0
[2020-02-26T15:08:23.4172898-05:00] Number of updates returned from search: 1
[2020-02-26T15:08:23.4542908-05:00] Number of updates to install: 1
[2020-02-26T15:08:23.4732916-05:00] Number of updates to download: 1
[2020-02-26T15:08:23.4872940-05:00] Updates to be installed: [
{
"id": "652fa296-32a1-4c9f-b939-ed54f005703b",
"name": "2020-02 Cumulative Update for Windows Server 2016 for x64-based Systems (KB4537764)",
"server_selection": 0,
"provider": "windows",
"kb_ids": [
"4537764"
],
"version": 200
}
]
[2020-02-26T15:08:23.5152961-05:00] Starting to download updates...
[2020-02-26T15:09:21.4018304-05:00] Finished downloading updates...
[2020-02-26T15:09:21.4158342-05:00] Starting update installs...
[2020-02-26T15:26:46.0083915-05:00] Finished update installs...
[2020-02-26T15:26:46.0603957-05:00] Parsing update results...
[2020-02-26T15:26:46.3027726-05:00] = Finished server selection: 0
[2020-02-26T15:26:46.3127734-05:00] ===============
[2020-02-26T15:26:47.0720212-05:00] = Finishing Update-Windows
[2020-02-26T15:26:47.0750156-05:00] =========================================
[2020-02-26T15:26:47.0930163-05:00] =========================================
[2020-02-26T15:26:47.0960169-05:00] = Starting Update-Chocolatey
[2020-02-26T15:26:47.1000175-05:00] Searching for choco command
[2020-02-26T15:26:47.1050182-05:00] choco command exists!
[2020-02-26T15:26:47.1070180-05:00] Executing: choco upgrade all --yes --limit-output --no-progress --ignore-unfound
[2020-02-26T15:26:48.5511203-05:00] Finished: choco ugprade ... exit_code = 0
[2020-02-26T15:26:48.5551185-05:00] Upgrading the following packages:
all
By upgrading you accept licenses for the packages.
7zip|18.5.0.20180730|18.5.0.20180730|false
7zip.install|18.5.0.20180730|18.5.0.20180730|false
chocolatey|0.10.11|0.10.11|false
chocolatey-core.extension|1.3.3|1.3.3|false
googlechrome|70.0.3538.77|70.0.3538.77|false
notepadplusplus|7.5.9|7.5.9|false
notepadplusplus.install|7.5.9|7.5.9|false
splunkforwarder|7.2.0.0|7.2.0.0|false
Chocolatey upgraded 0/8 packages.
See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).
[2020-02-26T15:26:48.5661204-05:00] = Finishing Update-Chocolatey
[2020-02-26T15:26:48.5701203-05:00] =========================================
[2020-02-26T15:26:48.5821215-05:00] = Finished Update
[2020-02-26T15:26:48.5851228-05:00] ==================================================================================
PS C:\programdata\patching\log>
from puppet-patching.
FYI turns out this was related to the pcp
transport used by PE and the default timeout of 1000 seconds for the PCP transport tasks: https://puppet.com/docs/bolt/latest/bolt_configuration_reference.html#pcp
Changing to a larger value for of the job timeout parameter fixed the issue:
---
pcp:
# 2 hours = 120 minutes = 7,200 seconds
job-poll-timeout: 7200
from puppet-patching.
Related Issues (20)
- file::write not supported in PE HOT 2
- patching::update generates error when run on Windows Server 2008 R2 HOT 2
- When I run bolt plan run -t windows patching::pre_update. The plan executes the script on target windows nodes successfully but the output says it failed. HOT 2
- plan fails on bolt 2.4.0 HOT 3
- Update task is ignoring errors of yum command because of tee
- Errors finding VMs in VMware does not cause the plan to error
- Reboot warning step
- Flag for patching all hosts, not just ones with updates
- Content promotion workflow for WSUS and Foreman/Satellite HOT 2
- allow user to specify provider for update task
- Exclude packages HOT 2
- Evaluation error when calling plan reboot_required with noop
- needs-restarting should be checked for before installing packages?
- Feature request: Support puppetlabs/puppet_agent > 3.0 HOT 2
- Pass arbitrary parameters to native package managers
- incorrect statistics for nodes without available updates
- With PE PLAN no such file to load -- rbvmomi HOT 4
- update bolt configuration to bolt v3 HOT 2
- ManagedObjectNotFound: The object 'vim.Task:task-256811' has already been deleted or has not been completely created HOT 1
- Server 2019, Ubuntu 20.04, 22.04, AlmaLinux|OracleLinux 8+ Support?
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from puppet-patching.