Giter Club home page Giter Club logo

Comments (16)

sirinek avatar sirinek commented on August 15, 2024

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.

nmaludy avatar nmaludy commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

I think this is from using Add-Content on a file that doesn't yet exist, in tasks/update_windows.ps1

from puppet-patching.

nmaludy avatar nmaludy commented on August 15, 2024

@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.

sirinek avatar sirinek commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

To address the issue of patching.json being appended to while missing, I've tried:

  1. Starting the plan with a json file only containing {}
  2. Starting the plan after creating a valid json file:
{ 
  "upgraded": [ ],
  "installed": [ ]
}
  1. 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.

sirinek avatar sirinek commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

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.

nmaludy avatar nmaludy commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

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.

nmaludy avatar nmaludy commented on August 15, 2024

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.

sirinek avatar sirinek commented on August 15, 2024

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.

nmaludy avatar nmaludy commented on August 15, 2024

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)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo 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.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.