Oracle services are suddenly vanished

akummich · February 2, 2022, 7:44am

CMK version: Managed Enterprise Edition v1.6.0p25
Oracle DB-Version: 19.0.0.0.0

We are experiencing a strange behaviour with the mk_oracle plugin.
It runs on a Windows Server (W2K12 Datacenter), monitoring an Oracle Database (v19).

The plugin works for 1-2 days. Then, we get an agent alert, that all Oracle services are vanished:
Tue Feb 01 23:09:40 UTC 2022
WARN - no unmonitored services found, 35 vanished services (oracle_tablespaces:18, oracle_sessions:2, oracle_recovery_status:1, oracle_processes:2, oracle_recovery_area:1, oracle_rman:3, oracle_undostat:2, oracle_locks:2, oracle_instance:2, oracle_logswitches:2)WARN, no new host labels, rediscovery scheduled

Because we have a rule that deactivates vanished services automatically, they disappear suddenly.
Unfortunately, I can’t find any hint in the local C:\ProgramData\checkmk\agent\log\check_mk.log at the time when the services are vanished (23:09):

2022-02-01 23:08:49.454 perf:  In [569] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[2900] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:08:49.454 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:08:49.464 perf:  In [582] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[8632] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:08:49.464 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:09:49.352 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-01 23:09:49.352 Put on queue, size is [1]
2022-02-01 23:09:49.352 Found connection on queue, in queue left[0]
2022-02-01 23:09:49.353 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-01 23:09:49.353 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-01 23:09:49.354 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:09:49.354 [Trace] Left [43] files to execute
2022-02-01 23:09:49.354 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:09:49.354 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:09:49.361 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.361 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.361 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:09:49.361 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.361 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.362 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:09:49.362 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.362 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:09:49.363 Generating answer number [1]
2022-02-01 23:09:49.363 Id is [8868231522785035] 
2022-02-01 23:09:49.364 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:09:49.364 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:09:49.364 [Trace] Provider 'wmi_cpuload' is direct called, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.382 Object 'Win32_PerfRawData_PerfOS_System' in 17ms sends [776] bytes
2022-02-01 23:09:49.390 Object 'Win32_ComputerSystem' in 6ms sends [1226] bytes
2022-02-01 23:09:49.390 [Trace] Sending data 'wmi_cpuload' id is [8868231522785035] length [2086]
2022-02-01 23:09:49.391 perf: Section 'wmi_cpuload' took [26] milliseconds
2022-02-01 23:09:49.391 [Trace] Provider 'uptime' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.391 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-01 23:09:49.391 [Trace] Sending data 'uptime' id is [8868231522785035] length [20]
2022-02-01 23:09:49.392 [Trace] Provider 'df' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.392 [Trace] Provider 'mem' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.392 [Trace] Provider 'services' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.393 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-01 23:09:49.393 [Trace] Provider 'ps' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.393 [Trace] Provider 'fileinfo' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.393 [Trace] Loaded [3] entries in LogWatch
2022-02-01 23:09:49.394 perf: Section 'uptime' took [0] milliseconds
2022-02-01 23:09:49.394 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:09:49.394 [Trace] Left [43] files to execute
2022-02-01 23:09:49.395 [Trace] Sending data 'fileinfo' id is [8868231522785035] length [34]
2022-02-01 23:09:49.395 [Trace] Provider 'logwatch' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.400 [Trace] Sending data 'logwatch' id is [8868231522785035] length [159]
2022-02-01 23:09:49.400 perf: Section 'logwatch' took [4] milliseconds
2022-02-01 23:09:49.400 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:09:49.401 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:09:49.401 [Trace] Sending data 'mem' id is [8868231522785035] length [227]
2022-02-01 23:09:49.402 perf: Section 'mem' took [9] milliseconds
2022-02-01 23:09:49.402 perf: Section 'fileinfo' took [1] milliseconds
2022-02-01 23:09:49.403 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:8868231522785035 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-01 23:09:49.410 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.410 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.410 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:09:49.410 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.411 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.411 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:09:49.411 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:09:49.412 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:09:49.412 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:09:49.412 [Trace] Left [0] files to execute
2022-02-01 23:09:49.413 [Trace] Left [0] files to execute in 'local'
2022-02-01 23:09:49.413 [Trace] Skipping 'wmi_webservices' by time
2022-02-01 23:09:49.413 [Trace] 'msexch' is skipped by config
2022-02-01 23:09:49.413 [Trace] Skipping 'msexch' by config
2022-02-01 23:09:49.414 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-01 23:09:49.414 [Trace] Skipping 'skype' by config
2022-02-01 23:09:49.414 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-01 23:09:49.415 Received [2214] bytes from 'wmi_cpuload'
2022-02-01 23:09:49.415 [Trace] To start [0] sync plugins
2022-02-01 23:09:49.415 [Trace] Sending data 'services' id is [8868231522785035] length [7957]
2022-02-01 23:09:49.416 [Trace] Provider 'mrpe' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.416 [Warn ] Section 'mrpe' cannot provide data
2022-02-01 23:09:49.416 [Trace] Provider 'local' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.416 [Trace] Provider 'spool' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.417 perf: Section 'services' took [23] milliseconds
2022-02-01 23:09:49.417 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.418 [Trace] Sending data 'mrpe' id is [8868231522785035] length [0]
2022-02-01 23:09:49.418 [Trace] To start [7] sync plugins
2022-02-01 23:09:49.418 [Warn ] Section 'local' cannot provide data
2022-02-01 23:09:49.419 [Warn ] Section 'spool' cannot provide data
2022-02-01 23:09:49.419 [Trace] Sending data 'spool' id is [8868231522785035] length [0]
2022-02-01 23:09:49.419 perf: Section 'mrpe' took [2] milliseconds
2022-02-01 23:09:49.419 [Trace] Sending data 'local' id is [8868231522785035] length [0]
2022-02-01 23:09:49.420 perf: Section 'spool' took [2] milliseconds
2022-02-01 23:09:49.420 perf: Section 'local' took [3] milliseconds
2022-02-01 23:09:49.420 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-01 23:09:49.420 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:09:49.421 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-01 23:09:49.421 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-01 23:09:49.423 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:09:49.423 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '59' seconds
2022-02-01 23:09:49.423 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:09:49.423 [Warn ] Bad creation date from WMI ''
2022-02-01 23:09:49.424 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-01 23:09:49.425 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:09:49.425 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-01 23:09:49.425 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:09:49.427 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-01 23:09:49.427 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-01 23:09:49.434 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-01 23:09:49.434 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-01 23:09:49.435 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:09:49.436 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-01 23:09:49.436 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:09:49.437 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-01 23:09:49.437 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-01 23:09:49.438 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:09:49.438 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-01 23:09:49.438 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:09:49.440 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-01 23:09:49.440 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-01 23:09:49.441 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:09:49.441 [Trace] Provider 'plugins' is about to be started, id '8868231522785035' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:09:49.442 [Trace] Sending data 'plugins' id is [8868231522785035] length [603]
2022-02-01 23:09:49.442 perf: Section 'plugins' took [0] milliseconds
2022-02-01 23:09:49.446 Received [148] bytes from 'uptime'
2022-02-01 23:09:49.468 [Trace] Sending data 'ps' id is [8868231522785035] length [5947]
2022-02-01 23:09:49.468 perf: Section 'ps' took [75] milliseconds
2022-02-01 23:09:49.470 [Trace] df: Processed [5] drives
2022-02-01 23:09:49.470 [Trace] Sending data 'df' id is [8868231522785035] length [255]
2022-02-01 23:09:49.470 perf: Section 'df' took [78] milliseconds
2022-02-01 23:09:49.476 Received [162] bytes from 'fileinfo'
2022-02-01 23:09:49.478 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 60ms sends [1341] bytes
2022-02-01 23:09:49.478 [Trace] Sending data 'dotnet_clrmemory' id is [8868231522785035] length [1391]
2022-02-01 23:09:49.478 perf: Section 'dotnet_clrmemory' took [60] milliseconds
2022-02-01 23:09:49.512 Received [287] bytes from 'logwatch'
2022-02-01 23:09:49.539 Received [355] bytes from 'mem'
2022-02-01 23:09:49.570 Received [8085] bytes from 'services'
2022-02-01 23:09:49.601 Received [128] bytes from 'mrpe'
2022-02-01 23:09:49.617 perf:  In [176] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[5504] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:09:49.617 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-01 23:09:49.617 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:09:49.633 Received [128] bytes from 'spool'
2022-02-01 23:09:49.664 Received [128] bytes from 'local'
2022-02-01 23:09:49.695 Received [731] bytes from 'plugins'
2022-02-01 23:09:49.726 Received [4664] bytes from 'winperf'
2022-02-01 23:09:49.742 perf:  In [304] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[6916] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-01 23:09:49.742 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:09:49.757 Received [6075] bytes from 'ps'
2022-02-01 23:09:49.788 Received [383] bytes from 'df'
2022-02-01 23:09:49.820 Received [1519] bytes from 'dotnet_clrmemory'
2022-02-01 23:09:49.820 perf: Answer is ready in [457] milliseconds
2022-02-01 23:09:49.820 Send [23952] bytes of data
2022-02-01 23:09:49.866 perf:  In [432] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[11164] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:09:49.867 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-01 23:09:49.867 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:09:49.953 perf:  In [531] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[7288] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:09:49.953 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:09:49.991 perf:  In [564] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[10140] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:09:49.992 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'

The strange thing is that the local execution of “C:\Program Files (x86)\checkmk\service\check_mk_agent.exe test” shows all Oracle services properly:

...
<<<oracle_rman:sep(124)>>>
CSS|COMPLETED|2022-02-01_20:35:
CSS|COMPLETED||2022-02-01_22:08
CSS|COMPLETED|2022-02-02_08:11:
<<<oracle_jobs:sep(124)>>>
CSS|SYS|SM$CLEAN_AUTO_SPLIT_MER
CSS|ORACLE_OCM|MGMT_CONFIG_JOB|
...

The services are missing when I do a “telnet HOSTNAME 6556” on the corresponding Checkmk server.
Even the cmk debug command shows no single Oracle service:

OMD[site]:~$ cmk --debug -vvn xxx.xxx.xxx
[cpu_tracking] Start with phase 'busy'
Check_MK version 1.6.0p25
Try aquire lock on /omd/sites/site/tmp/check_mk/counters/xxx.xxx.xxx
Got lock on /omd/sites/site/tmp/check_mk/counters/xxx.xxx.xxx
Releasing lock on /omd/sites/site/tmp/check_mk/counters/xxx.xxx.xxx
Released lock on /omd/sites/site/tmp/check_mk/counters/xxx.xxx.xxx
Loading autochecks from /omd/sites/site/var/check_mk/autochecks/xxx.xxx.xxx.mk
+ FETCHING DATA
[cpu_tracking] Push phase 'agent' (Stack: ['busy'])
 [agent] Not using cache (Don't try it)
 [agent] Execute data source
 [agent] Connecting via TCP to xxx.xxx.xxx:6556 (60.0s timeout)
 [agent] Reading data from agent
 [agent] Write data to cache file /omd/sites/site/tmp/check_mk/cache/xxx.xxx.xxx
Try aquire lock on /omd/sites/site/tmp/check_mk/cache/xxx.xxx.xxx
Got lock on /omd/sites/site/tmp/check_mk/cache/xxx.xxx.xxx
Releasing lock on /omd/sites/site/tmp/check_mk/cache/xxx.xxx.xxx
Released lock on /omd/sites/site/tmp/check_mk/cache/xxx.xxx.xxx
 [agent] Using persisted section 'win_disks'
 [agent] Using persisted section 'win_video'
 [agent] Using persisted section 'win_system'
 [agent] Using persisted section 'win_ip_r'
 [agent] Using persisted section 'win_os'
 [agent] Using persisted section 'win_bios'
 [agent] Using persisted section 'win_wmi_updates'
 [agent] Using persisted section 'win_exefiles'
 [agent] Using persisted section 'win_cpuinfo'
 [agent] Using persisted section 'win_computersystem'
 [agent] Using persisted section 'win_networkadapter'
 [agent] Using persisted section 'win_reg_uninstall'
 [agent] Using persisted section 'win_wmi_software'
[cpu_tracking] Pop phase 'agent' (Stack: ['busy', 'agent'])
[cpu_tracking] Push phase 'agent' (Stack: ['busy'])
 [piggyback] No persisted sections loaded
 [piggyback] Execute data source
No piggyback files for 'xxx.xxx.xxx'. Skip processing.
No piggyback files for 'xxx.xxx.xxx'. Skip processing.
[cpu_tracking] Pop phase 'agent' (Stack: ['busy', 'agent'])
CPU utilization      OK - Total CPU: 0%, user perc: 4.1 %, privileged perc: 4.0 %, 4 CPUs
Check_MK Agent       OK - no errors, last update check: 2022-02-02 06:44:19
Disk IO SUMMARY      OK - Read: 85.24 kB/s, Write: 326.79 kB/s, Average Read Wait: 0.02 ms, Average Write Wait: 0.09 ms, Average Read Queue Length: 0.00, Average Write Queue Length: 0.00, Read operations: 5.33 1/s, Write operations: 22.22 1/s
Filesystem C:/       OK - 66.46% used (56.26 of 84.66 GB), trend: +3.29 MB / 24 hours - time left until disk full: more than a year
Filesystem G:/       OK - 27.99% used (167.92 of 599.87 GB), trend: -3.44 GB / 24 hours
Filesystem P:/       OK - 79.57% used (50.83 of 63.87 GB), trend: -2.2 MB / 24 hours
Filesystem T:/       OK - 72.19% used (433.04 of 599.87 GB), trend: -101.64 MB / 24 hours
Filesystem U:/       OK - 32.17% used (647.94 MB of 1.97 GB), trend: 0 B / 24 hours
Interface vmxnet3 Ethernet Adapter OK - [1] (Connected) 10 Gbit/s, In: 2.4 kB/s (0.0%), Out: 5.45 kB/s (0.0%)
Memory and pagefile  OK - Memory usage: 58.01% (18.56 GB/32 GB), Commit charge: 52.59% (19.07 GB/36.25 GB)
System Time          OK - Offset: - 3.10 µs
Uptime               OK - Up since Fri Oct 22 06:45:59 2021 (103d 00:28:45)
+ EXECUTING INVENTORY PLUGINS
Plugins: check_mk mem win_bios win_computersystem win_cpuinfo win_disks win_ip_r win_networkadapter win_os win_reg_uninstall win_system win_video win_wmi_software win_wmi_updates winperf_if
[cpu_tracking] End
OK - [agent] Version: 1.6.0p25, OS: windows, execution time 0.7 sec | execution_time=0.697 user_time=0.250 system_time=0.000 children_user_time=0.000 children_system_time=0.000 cmk_time_agent=0.445

If I start a service discovery no Oracle services are discovered. I have to restart the Checkmk agent (Windows service) to be able to rediscover these services…

Does anyone know why the services are vanishes after some hours of running properly?

Thank you very much in advance.
Antje

tosch · February 2, 2022, 8:15am

Hi @akummich,

looks like a problem with the cache. At your agent trace i can’t see the execution of the mk_oracle plugin. Can you check the 5 minutes before at the log too? Your cache age seems top be 300 seconds.
Can you please also provide which section at the oracle plugin your are monitoring sync and which async? Maybe the plugin isn’t working properly because a section is running too long and therefore the plugin doesn’t update as a whole.

akummich · February 2, 2022, 8:33am

Hi @tosch,

thank you for your help.
As requested, I’ll post the log entries of the previous 5 minutes (see below).
The mk_oracle plugin is executed. I only see a timeout of 300. Cache age is not mentioned.

2022-02-01 23:04:46.398 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-01 23:04:46.398 Put on queue, size is [1]
2022-02-01 23:04:46.398 Found connection on queue, in queue left[0]
2022-02-01 23:04:46.399 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-01 23:04:46.399 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-01 23:04:46.400 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:04:46.400 [Trace] Left [43] files to execute
2022-02-01 23:04:46.400 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:04:46.401 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:04:46.407 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.407 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.407 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:04:46.408 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.408 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.408 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:04:46.408 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.408 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:04:46.409 Generating answer number [1]
2022-02-01 23:04:46.409 Id is [8867928568890659] 
2022-02-01 23:04:46.409 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:04:46.410 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:04:46.410 [Trace] Provider 'wmi_cpuload' is direct called, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.456 Object 'Win32_PerfRawData_PerfOS_System' in 45ms sends [776] bytes
2022-02-01 23:04:46.464 Object 'Win32_ComputerSystem' in 7ms sends [1226] bytes
2022-02-01 23:04:46.465 [Trace] Sending data 'wmi_cpuload' id is [8867928568890659] length [2086]
2022-02-01 23:04:46.465 perf: Section 'wmi_cpuload' took [54] milliseconds
2022-02-01 23:04:46.465 [Trace] Provider 'uptime' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.466 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-01 23:04:46.466 [Trace] Sending data 'uptime' id is [8867928568890659] length [20]
2022-02-01 23:04:46.466 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-01 23:04:46.467 [Trace] Provider 'df' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.467 [Trace] Provider 'mem' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.467 [Trace] Provider 'services' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.467 [Trace] Provider 'ps' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.468 [Trace] Loaded [3] entries in LogWatch
2022-02-01 23:04:46.468 [Trace] Provider 'fileinfo' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.469 perf: Section 'uptime' took [0] milliseconds
2022-02-01 23:04:46.469 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:8867928568890659 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-01 23:04:46.469 [Trace] Sending data 'mem' id is [8867928568890659] length [227]
2022-02-01 23:04:46.469 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:04:46.470 [Trace] Sending data 'fileinfo' id is [8867928568890659] length [34]
2022-02-01 23:04:46.470 perf: Section 'fileinfo' took [1] milliseconds
2022-02-01 23:04:46.470 perf: Section 'mem' took [2] milliseconds
2022-02-01 23:04:46.471 [Trace] Left [43] files to execute
2022-02-01 23:04:46.471 [Trace] Provider 'logwatch' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.471 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:04:46.472 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:04:46.475 [Trace] Sending data 'logwatch' id is [8867928568890659] length [159]
2022-02-01 23:04:46.475 perf: Section 'logwatch' took [4] milliseconds
2022-02-01 23:04:46.482 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.482 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.483 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:04:46.483 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.483 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.484 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:04:46.484 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.484 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:04:46.485 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:04:46.485 [Trace] Left [0] files to execute
2022-02-01 23:04:46.485 [Trace] Left [0] files to execute in 'local'
2022-02-01 23:04:46.486 [Trace] Skipping 'wmi_webservices' by time
2022-02-01 23:04:46.486 [Trace] 'msexch' is skipped by config
2022-02-01 23:04:46.486 [Trace] Skipping 'msexch' by config
2022-02-01 23:04:46.486 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-01 23:04:46.487 [Trace] Skipping 'skype' by config
2022-02-01 23:04:46.487 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-01 23:04:46.487 [Trace] To start [7] sync plugins
2022-02-01 23:04:46.488 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '60' seconds
2022-02-01 23:04:46.488 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:04:46.488 [Trace] To start [0] sync plugins
2022-02-01 23:04:46.488 [Trace] Provider 'local' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.489 [Warn ] Section 'local' cannot provide data
2022-02-01 23:04:46.489 [Trace] Sending data 'local' id is [8867928568890659] length [0]
2022-02-01 23:04:46.489 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-01 23:04:46.489 perf: Section 'local' took [0] milliseconds
2022-02-01 23:04:46.490 [Trace] Provider 'spool' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.490 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:04:46.490 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '60' seconds
2022-02-01 23:04:46.490 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:04:46.491 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.491 [Trace] Provider 'mrpe' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.492 [Warn ] Section 'spool' cannot provide data
2022-02-01 23:04:46.492 [Trace] Sending data 'spool' id is [8867928568890659] length [0]
2022-02-01 23:04:46.492 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-01 23:04:46.493 [Warn ] Section 'mrpe' cannot provide data
2022-02-01 23:04:46.493 [Trace] Sending data 'mrpe' id is [8867928568890659] length [0]
2022-02-01 23:04:46.494 perf: Section 'mrpe' took [2] milliseconds
2022-02-01 23:04:46.494 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:04:46.494 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-01 23:04:46.494 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:04:46.494 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-01 23:04:46.495 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-01 23:04:46.496 Received [2214] bytes from 'wmi_cpuload'
2022-02-01 23:04:46.498 perf: Section 'spool' took [2] milliseconds
2022-02-01 23:04:46.508 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-01 23:04:46.509 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-01 23:04:46.510 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:04:46.511 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-01 23:04:46.511 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:04:46.517 [Warn ] Bad creation date from WMI ''
2022-02-01 23:04:46.517 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:04:46.517 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-01 23:04:46.518 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:04:46.518 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-01 23:04:46.518 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-01 23:04:46.519 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-01 23:04:46.519 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-01 23:04:46.519 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:04:46.519 [Trace] Provider 'plugins' is about to be started, id '8867928568890659' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:04:46.520 [Trace] Sending data 'plugins' id is [8867928568890659] length [603]
2022-02-01 23:04:46.520 perf: Section 'plugins' took [0] milliseconds
2022-02-01 23:04:46.521 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-01 23:04:46.525 Received [148] bytes from 'uptime'
2022-02-01 23:04:46.528 [Trace] Sending data 'services' id is [8867928568890659] length [7957]
2022-02-01 23:04:46.528 perf: Section 'services' took [61] milliseconds
2022-02-01 23:04:46.546 [Trace] df: Processed [5] drives
2022-02-01 23:04:46.547 [Trace] Sending data 'df' id is [8867928568890659] length [255]
2022-02-01 23:04:46.547 perf: Section 'df' took [79] milliseconds
2022-02-01 23:04:46.557 Received [355] bytes from 'mem'
2022-02-01 23:04:46.560 [Trace] Sending data 'ps' id is [8867928568890659] length [6139]
2022-02-01 23:04:46.560 perf: Section 'ps' took [92] milliseconds
2022-02-01 23:04:46.585 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 93ms sends [1461] bytes
2022-02-01 23:04:46.585 [Trace] Sending data 'dotnet_clrmemory' id is [8867928568890659] length [1514]
2022-02-01 23:04:46.585 perf: Section 'dotnet_clrmemory' took [94] milliseconds
2022-02-01 23:04:46.592 Received [162] bytes from 'fileinfo'
2022-02-01 23:04:46.618 Received [287] bytes from 'logwatch'
2022-02-01 23:04:46.634 perf:  In [115] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[10232] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:04:46.634 perf:  In [125] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[11164] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:04:46.635 perf:  In [116] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[4484] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-01 23:04:46.635 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-01 23:04:46.635 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-01 23:04:46.636 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:04:46.636 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:04:46.636 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:04:46.650 Received [128] bytes from 'local'
2022-02-01 23:04:46.682 Received [128] bytes from 'spool'
2022-02-01 23:04:46.712 Received [128] bytes from 'mrpe'
2022-02-01 23:04:46.743 Received [731] bytes from 'plugins'
2022-02-01 23:04:46.774 Received [8085] bytes from 'services'
2022-02-01 23:04:46.806 Received [4664] bytes from 'winperf'
2022-02-01 23:04:46.837 Received [383] bytes from 'df'
2022-02-01 23:04:46.868 Received [6267] bytes from 'ps'
2022-02-01 23:04:46.899 Received [1642] bytes from 'dotnet_clrmemory'
2022-02-01 23:04:46.900 perf: Answer is ready in [490] milliseconds
2022-02-01 23:04:46.900 Send [24267] bytes of data
2022-02-01 23:04:47.056 perf:  In [560] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[9448] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:04:47.056 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:04:47.149 perf:  In [659] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[4508] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:04:47.149 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:05:46.985 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-01 23:05:46.985 Put on queue, size is [1]
2022-02-01 23:05:46.986 Found connection on queue, in queue left[0]
2022-02-01 23:05:46.987 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-01 23:05:46.987 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-01 23:05:46.989 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:05:46.989 [Trace] Left [43] files to execute
2022-02-01 23:05:46.990 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:05:46.991 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:05:47.000 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.000 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.001 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:05:47.001 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.001 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.002 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:05:47.002 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.002 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:05:47.003 Generating answer number [1]
2022-02-01 23:05:47.003 Id is [8867989163030440] 
2022-02-01 23:05:47.004 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:05:47.004 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:05:47.004 [Trace] Provider 'wmi_cpuload' is direct called, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.057 Object 'Win32_PerfRawData_PerfOS_System' in 51ms sends [776] bytes
2022-02-01 23:05:47.066 Object 'Win32_ComputerSystem' in 8ms sends [1226] bytes
2022-02-01 23:05:47.066 [Trace] Sending data 'wmi_cpuload' id is [8867989163030440] length [2086]
2022-02-01 23:05:47.067 perf: Section 'wmi_cpuload' took [61] milliseconds
2022-02-01 23:05:47.067 [Trace] Provider 'uptime' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.067 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-01 23:05:47.067 [Trace] Sending data 'uptime' id is [8867989163030440] length [20]
2022-02-01 23:05:47.068 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-01 23:05:47.068 [Trace] Provider 'mem' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.068 [Trace] Provider 'services' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.068 [Trace] Provider 'df' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.069 [Trace] Provider 'ps' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.069 [Trace] Provider 'fileinfo' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.069 [Trace] Sending data 'fileinfo' id is [8867989163030440] length [34]
2022-02-01 23:05:47.069 perf: Section 'fileinfo' took [0] milliseconds
2022-02-01 23:05:47.070 perf: Section 'uptime' took [0] milliseconds
2022-02-01 23:05:47.070 [Trace] Sending data 'mem' id is [8867989163030440] length [227]
2022-02-01 23:05:47.070 perf: Section 'mem' took [1] milliseconds
2022-02-01 23:05:47.070 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:8867989163030440 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-01 23:05:47.071 [Trace] Loaded [3] entries in LogWatch
2022-02-01 23:05:47.072 [Trace] Provider 'logwatch' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.074 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:05:47.074 [Trace] Left [43] files to execute
2022-02-01 23:05:47.074 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:05:47.075 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:05:47.086 [Trace] Sending data 'services' id is [8867989163030440] length [7957]
2022-02-01 23:05:47.087 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.087 perf: Section 'services' took [18] milliseconds
2022-02-01 23:05:47.087 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.088 Received [2214] bytes from 'wmi_cpuload'
2022-02-01 23:05:47.088 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:05:47.088 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.088 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.089 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:05:47.089 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:05:47.089 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:05:47.090 [Trace] To start [7] sync plugins
2022-02-01 23:05:47.090 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-01 23:05:47.090 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:05:47.090 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:05:47.091 [Trace] Left [0] files to execute
2022-02-01 23:05:47.091 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-01 23:05:47.091 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:05:47.092 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '60' seconds
2022-02-01 23:05:47.092 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-01 23:05:47.092 [Trace] Left [0] files to execute in 'local'
2022-02-01 23:05:47.092 [Trace] Skipping 'wmi_webservices' by time
2022-02-01 23:05:47.093 [Trace] 'msexch' is skipped by config
2022-02-01 23:05:47.093 [Trace] Skipping 'msexch' by config
2022-02-01 23:05:47.093 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-01 23:05:47.094 [Trace] Sending data 'logwatch' id is [8867989163030440] length [159]
2022-02-01 23:05:47.094 [Trace] Skipping 'skype' by config
2022-02-01 23:05:47.094 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-01 23:05:47.095 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:05:47.095 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.096 [Trace] Provider 'mrpe' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.096 [Warn ] Section 'mrpe' cannot provide data
2022-02-01 23:05:47.096 [Trace] To start [0] sync plugins
2022-02-01 23:05:47.097 [Trace] Provider 'local' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.097 [Warn ] Section 'local' cannot provide data
2022-02-01 23:05:47.097 [Trace] Sending data 'local' id is [8867989163030440] length [0]
2022-02-01 23:05:47.098 perf: Section 'local' took [0] milliseconds
2022-02-01 23:05:47.098 [Trace] Provider 'spool' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.098 perf: Section 'logwatch' took [21] milliseconds
2022-02-01 23:05:47.098 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-01 23:05:47.099 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:05:47.101 [Trace] Sending data 'mrpe' id is [8867989163030440] length [0]
2022-02-01 23:05:47.101 [Warn ] Section 'spool' cannot provide data
2022-02-01 23:05:47.101 [Trace] Sending data 'spool' id is [8867989163030440] length [0]
2022-02-01 23:05:47.101 perf: Section 'spool' took [3] milliseconds
2022-02-01 23:05:47.102 perf: Section 'mrpe' took [4] milliseconds
2022-02-01 23:05:47.102 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-01 23:05:47.102 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:05:47.102 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-01 23:05:47.103 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:05:47.103 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-01 23:05:47.103 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:05:47.104 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-01 23:05:47.104 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-01 23:05:47.104 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:05:47.105 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-01 23:05:47.105 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-01 23:05:47.105 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:05:47.105 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-01 23:05:47.108 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-01 23:05:47.109 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-01 23:05:47.109 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:05:47.109 [Trace] Provider 'plugins' is about to be started, id '8867989163030440' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:05:47.110 [Trace] Sending data 'plugins' id is [8867989163030440] length [603]
2022-02-01 23:05:47.110 perf: Section 'plugins' took [0] milliseconds
2022-02-01 23:05:47.111 [Warn ] Bad creation date from WMI ''
2022-02-01 23:05:47.111 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-01 23:05:47.119 Received [148] bytes from 'uptime'
2022-02-01 23:05:47.149 Received [162] bytes from 'fileinfo'
2022-02-01 23:05:47.154 [Trace] df: Processed [5] drives
2022-02-01 23:05:47.155 [Trace] Sending data 'df' id is [8867989163030440] length [255]
2022-02-01 23:05:47.155 perf: Section 'df' took [86] milliseconds
2022-02-01 23:05:47.167 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 70ms sends [1319] bytes
2022-02-01 23:05:47.167 [Trace] Sending data 'dotnet_clrmemory' id is [8867989163030440] length [1369]
2022-02-01 23:05:47.167 perf: Section 'dotnet_clrmemory' took [71] milliseconds
2022-02-01 23:05:47.181 Received [355] bytes from 'mem'
2022-02-01 23:05:47.181 [Trace] Sending data 'ps' id is [8867989163030440] length [6082]
2022-02-01 23:05:47.182 perf: Section 'ps' took [112] milliseconds
2022-02-01 23:05:47.212 Received [8085] bytes from 'services'
2022-02-01 23:05:47.227 perf:  In [122] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[4496] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-01 23:05:47.228 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:05:47.243 Received [287] bytes from 'logwatch'
2022-02-01 23:05:47.282 Received [128] bytes from 'local'
2022-02-01 23:05:47.290 perf:  In [181] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[10384] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:05:47.290 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-01 23:05:47.290 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:05:47.305 Received [128] bytes from 'mrpe'
2022-02-01 23:05:47.321 perf:  In [216] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[3336] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:05:47.321 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-01 23:05:47.321 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:05:47.337 Received [128] bytes from 'spool'
2022-02-01 23:05:47.368 Received [731] bytes from 'plugins'
2022-02-01 23:05:47.399 Received [383] bytes from 'df'
2022-02-01 23:05:47.430 Received [1497] bytes from 'dotnet_clrmemory'
2022-02-01 23:05:47.461 Received [4664] bytes from 'winperf'
2022-02-01 23:05:47.493 Received [6210] bytes from 'ps'
2022-02-01 23:05:47.493 perf: Answer is ready in [489] milliseconds
2022-02-01 23:05:47.494 Send [24065] bytes of data
2022-02-01 23:05:47.680 perf:  In [588] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[5368] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:05:47.680 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:05:47.727 perf:  In [627] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[8312] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:05:47.727 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:06:47.590 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-01 23:06:47.591 Put on queue, size is [1]
2022-02-01 23:06:47.591 Found connection on queue, in queue left[0]
2022-02-01 23:06:47.592 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-01 23:06:47.593 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-01 23:06:47.594 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:06:47.594 [Trace] Left [43] files to execute
2022-02-01 23:06:47.595 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:06:47.595 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:06:47.601 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.601 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.602 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:06:47.602 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.602 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.602 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:06:47.602 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.603 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:06:47.603 Generating answer number [1]
2022-02-01 23:06:47.603 Id is [8868049763294769] 
2022-02-01 23:06:47.604 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:06:47.604 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:06:47.605 [Trace] Provider 'wmi_cpuload' is direct called, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.646 Object 'Win32_PerfRawData_PerfOS_System' in 41ms sends [776] bytes
2022-02-01 23:06:47.657 Object 'Win32_ComputerSystem' in 9ms sends [1226] bytes
2022-02-01 23:06:47.657 [Trace] Sending data 'wmi_cpuload' id is [8868049763294769] length [2086]
2022-02-01 23:06:47.658 perf: Section 'wmi_cpuload' took [52] milliseconds
2022-02-01 23:06:47.658 [Trace] Provider 'uptime' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.658 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-01 23:06:47.659 [Trace] Sending data 'uptime' id is [8868049763294769] length [20]
2022-02-01 23:06:47.659 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-01 23:06:47.659 [Trace] Provider 'mem' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.660 [Trace] Provider 'df' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.660 [Trace] Provider 'services' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.661 [Trace] Loaded [3] entries in LogWatch
2022-02-01 23:06:47.661 [Trace] Provider 'ps' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.661 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:06:47.662 [Trace] Left [43] files to execute
2022-02-01 23:06:47.662 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:8868049763294769 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-01 23:06:47.663 [Trace] Sending data 'mem' id is [8868049763294769] length [227]
2022-02-01 23:06:47.663 [Trace] Provider 'logwatch' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.664 [Trace] Provider 'fileinfo' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.664 [Trace] Sending data 'fileinfo' id is [8868049763294769] length [34]
2022-02-01 23:06:47.664 perf: Section 'fileinfo' took [0] milliseconds
2022-02-01 23:06:47.664 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:06:47.665 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:06:47.665 perf: Section 'mem' took [3] milliseconds
2022-02-01 23:06:47.667 perf: Section 'uptime' took [0] milliseconds
2022-02-01 23:06:47.669 [Trace] Sending data 'logwatch' id is [8868049763294769] length [159]
2022-02-01 23:06:47.669 perf: Section 'logwatch' took [5] milliseconds
2022-02-01 23:06:47.670 Received [2214] bytes from 'wmi_cpuload'
2022-02-01 23:06:47.673 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.673 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.673 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:06:47.673 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.674 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.674 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:06:47.674 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:06:47.674 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:06:47.675 [Trace] To start [7] sync plugins
2022-02-01 23:06:47.675 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:06:47.675 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-01 23:06:47.676 [Trace] Left [0] files to execute
2022-02-01 23:06:47.676 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:06:47.676 [Trace] Left [0] files to execute in 'local'
2022-02-01 23:06:47.677 [Trace] Skipping 'wmi_webservices' by time
2022-02-01 23:06:47.677 [Trace] To start [0] sync plugins
2022-02-01 23:06:47.677 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.678 [Trace] 'msexch' is skipped by config
2022-02-01 23:06:47.678 [Trace] Skipping 'msexch' by config
2022-02-01 23:06:47.679 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:06:47.679 [Trace] Provider 'local' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.679 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-01 23:06:47.680 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-01 23:06:47.680 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '59' seconds
2022-02-01 23:06:47.680 [Warn ] Section 'local' cannot provide data
2022-02-01 23:06:47.681 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:06:47.681 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-01 23:06:47.681 [Trace] Sending data 'local' id is [8868049763294769] length [0]
2022-02-01 23:06:47.681 perf: Section 'local' took [2] milliseconds
2022-02-01 23:06:47.682 [Trace] Provider 'mrpe' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.682 [Trace] Skipping 'skype' by config
2022-02-01 23:06:47.683 [Warn ] Section 'mrpe' cannot provide data
2022-02-01 23:06:47.683 [Trace] Sending data 'mrpe' id is [8868049763294769] length [0]
2022-02-01 23:06:47.683 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-01 23:06:47.683 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:06:47.684 [Trace] Provider 'spool' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.684 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-01 23:06:47.684 perf: Section 'mrpe' took [0] milliseconds
2022-02-01 23:06:47.685 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-01 23:06:47.685 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:06:47.685 [Warn ] Section 'spool' cannot provide data
2022-02-01 23:06:47.686 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-01 23:06:47.686 [Trace] Sending data 'spool' id is [8868049763294769] length [0]
2022-02-01 23:06:47.686 perf: Section 'spool' took [2] milliseconds
2022-02-01 23:06:47.688 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:06:47.688 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-01 23:06:47.688 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:06:47.689 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-01 23:06:47.689 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-01 23:06:47.690 [Trace] Sending data 'services' id is [8868049763294769] length [7957]
2022-02-01 23:06:47.690 perf: Section 'services' took [29] milliseconds
2022-02-01 23:06:47.692 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-01 23:06:47.692 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-01 23:06:47.693 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:06:47.693 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-01 23:06:47.693 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:06:47.694 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-01 23:06:47.694 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:06:47.694 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-01 23:06:47.694 [Trace] Provider 'plugins' is about to be started, id '8868049763294769' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:06:47.695 [Trace] Sending data 'plugins' id is [8868049763294769] length [603]
2022-02-01 23:06:47.695 perf: Section 'plugins' took [0] milliseconds
2022-02-01 23:06:47.701 Received [148] bytes from 'uptime'
2022-02-01 23:06:47.718 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 40ms sends [1321] bytes
2022-02-01 23:06:47.719 [Trace] Sending data 'dotnet_clrmemory' id is [8868049763294769] length [1371]
2022-02-01 23:06:47.719 perf: Section 'dotnet_clrmemory' took [41] milliseconds
2022-02-01 23:06:47.736 Received [355] bytes from 'mem'
2022-02-01 23:06:47.743 [Warn ] Bad creation date from WMI ''
2022-02-01 23:06:47.743 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-01 23:06:47.747 [Trace] df: Processed [5] drives
2022-02-01 23:06:47.747 [Trace] Sending data 'df' id is [8868049763294769] length [255]
2022-02-01 23:06:47.747 perf: Section 'df' took [87] milliseconds
2022-02-01 23:06:47.762 Received [162] bytes from 'fileinfo'
2022-02-01 23:06:47.792 Received [287] bytes from 'logwatch'
2022-02-01 23:06:47.796 [Trace] Sending data 'ps' id is [8868049763294769] length [6080]
2022-02-01 23:06:47.796 perf: Section 'ps' took [134] milliseconds
2022-02-01 23:06:47.823 Received [128] bytes from 'local'
2022-02-01 23:06:47.854 Received [128] bytes from 'mrpe'
2022-02-01 23:06:47.885 Received [128] bytes from 'spool'
2022-02-01 23:06:47.885 perf:  In [193] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[9776] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-01 23:06:47.886 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:06:47.916 Received [8085] bytes from 'services'
2022-02-01 23:06:47.948 Received [731] bytes from 'plugins'
2022-02-01 23:06:47.979 Received [1499] bytes from 'dotnet_clrmemory'
2022-02-01 23:06:48.010 Received [4664] bytes from 'winperf'
2022-02-01 23:06:48.041 perf:  In [347] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[1776] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:06:48.042 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-01 23:06:48.042 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:06:48.045 Received [383] bytes from 'df'
2022-02-01 23:06:48.072 Received [6208] bytes from 'ps'
2022-02-01 23:06:48.073 perf: Answer is ready in [469] milliseconds
2022-02-01 23:06:48.073 Send [24065] bytes of data
2022-02-01 23:06:48.104 perf:  In [414] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[11260] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:06:48.104 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-01 23:06:48.104 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:06:48.280 perf:  In [600] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[9428] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:06:48.280 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:06:48.307 perf:  In [622] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[9960] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:06:48.307 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:07:48.179 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-01 23:07:48.179 Put on queue, size is [1]
2022-02-01 23:07:48.180 Found connection on queue, in queue left[0]
2022-02-01 23:07:48.180 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-01 23:07:48.180 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-01 23:07:48.181 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:07:48.181 [Trace] Left [43] files to execute
2022-02-01 23:07:48.181 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:07:48.181 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:07:48.188 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.188 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.188 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:07:48.188 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.188 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.189 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:07:48.189 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.189 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:07:48.189 Generating answer number [1]
2022-02-01 23:07:48.190 Id is [8868110349600946] 
2022-02-01 23:07:48.190 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:07:48.190 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:07:48.191 [Trace] Provider 'wmi_cpuload' is direct called, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.231 Object 'Win32_PerfRawData_PerfOS_System' in 39ms sends [776] bytes
2022-02-01 23:07:48.238 Object 'Win32_ComputerSystem' in 6ms sends [1226] bytes
2022-02-01 23:07:48.238 [Trace] Sending data 'wmi_cpuload' id is [8868110349600946] length [2086]
2022-02-01 23:07:48.239 perf: Section 'wmi_cpuload' took [47] milliseconds
2022-02-01 23:07:48.239 [Trace] Provider 'uptime' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.239 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-01 23:07:48.239 [Trace] Sending data 'uptime' id is [8868110349600946] length [20]
2022-02-01 23:07:48.240 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-01 23:07:48.240 [Trace] Provider 'df' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.240 [Trace] Provider 'mem' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.241 [Trace] Provider 'services' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.241 [Trace] Provider 'ps' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.241 [Trace] Provider 'fileinfo' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.241 [Trace] Sending data 'fileinfo' id is [8868110349600946] length [34]
2022-02-01 23:07:48.242 perf: Section 'uptime' took [0] milliseconds
2022-02-01 23:07:48.242 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:8868110349600946 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-01 23:07:48.243 [Trace] Sending data 'mem' id is [8868110349600946] length [227]
2022-02-01 23:07:48.243 [Trace] Loaded [3] entries in LogWatch
2022-02-01 23:07:48.244 perf: Section 'fileinfo' took [0] milliseconds
2022-02-01 23:07:48.244 perf: Section 'mem' took [2] milliseconds
2022-02-01 23:07:48.244 [Trace] Provider 'logwatch' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.244 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:07:48.245 [Trace] Left [43] files to execute
2022-02-01 23:07:48.245 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:07:48.245 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:07:48.249 [Trace] Sending data 'logwatch' id is [8868110349600946] length [159]
2022-02-01 23:07:48.250 perf: Section 'logwatch' took [5] milliseconds
2022-02-01 23:07:48.253 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.254 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.254 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:07:48.254 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.254 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.255 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:07:48.255 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:07:48.255 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:07:48.256 [Trace] To start [7] sync plugins
2022-02-01 23:07:48.256 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-01 23:07:48.256 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:07:48.257 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:07:48.257 [Trace] Left [0] files to execute
2022-02-01 23:07:48.257 [Trace] Left [0] files to execute in 'local'
2022-02-01 23:07:48.257 [Trace] Skipping 'wmi_webservices' by time
2022-02-01 23:07:48.258 [Trace] To start [0] sync plugins
2022-02-01 23:07:48.258 [Trace] Provider 'local' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.258 [Trace] 'msexch' is skipped by config
2022-02-01 23:07:48.258 [Warn ] Section 'local' cannot provide data
2022-02-01 23:07:48.259 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.259 [Trace] Skipping 'msexch' by config
2022-02-01 23:07:48.259 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-01 23:07:48.260 [Trace] Sending data 'local' id is [8868110349600946] length [0]
2022-02-01 23:07:48.260 [Trace] Skipping 'skype' by config
2022-02-01 23:07:48.260 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-01 23:07:48.260 perf: Section 'local' took [1] milliseconds
2022-02-01 23:07:48.261 [Trace] Provider 'mrpe' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.261 [Warn ] Section 'mrpe' cannot provide data
2022-02-01 23:07:48.261 [Trace] Sending data 'mrpe' id is [8868110349600946] length [0]
2022-02-01 23:07:48.262 perf: Section 'mrpe' took [0] milliseconds
2022-02-01 23:07:48.262 [Trace] Provider 'spool' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.262 [Warn ] Section 'spool' cannot provide data
2022-02-01 23:07:48.263 [Trace] Sending data 'spool' id is [8868110349600946] length [0]
2022-02-01 23:07:48.263 perf: Section 'spool' took [0] milliseconds
2022-02-01 23:07:48.265 [Trace] Sending data 'services' id is [8868110349600946] length [7957]
2022-02-01 23:07:48.266 perf: Section 'services' took [24] milliseconds
2022-02-01 23:07:48.266 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:07:48.266 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '59' seconds
2022-02-01 23:07:48.266 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:07:48.267 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:07:48.267 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-01 23:07:48.267 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:07:48.268 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-01 23:07:48.268 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-01 23:07:48.268 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-01 23:07:48.268 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-01 23:07:48.269 Received [2214] bytes from 'wmi_cpuload'
2022-02-01 23:07:48.269 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-01 23:07:48.269 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-01 23:07:48.270 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:07:48.270 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-01 23:07:48.270 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:07:48.270 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:07:48.271 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-01 23:07:48.271 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:07:48.272 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-01 23:07:48.272 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-01 23:07:48.278 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-01 23:07:48.278 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-01 23:07:48.281 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:07:48.281 [Trace] Provider 'plugins' is about to be started, id '8868110349600946' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:07:48.281 [Trace] Sending data 'plugins' id is [8868110349600946] length [603]
2022-02-01 23:07:48.281 perf: Section 'plugins' took [0] milliseconds
2022-02-01 23:07:48.292 [Warn ] Bad creation date from WMI ''
2022-02-01 23:07:48.292 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-01 23:07:48.304 Received [148] bytes from 'uptime'
2022-02-01 23:07:48.312 [Trace] df: Processed [5] drives
2022-02-01 23:07:48.314 [Trace] Sending data 'df' id is [8868110349600946] length [255]
2022-02-01 23:07:48.314 perf: Section 'df' took [73] milliseconds
2022-02-01 23:07:48.328 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 68ms sends [1325] bytes
2022-02-01 23:07:48.328 [Trace] Sending data 'dotnet_clrmemory' id is [8868110349600946] length [1375]
2022-02-01 23:07:48.329 perf: Section 'dotnet_clrmemory' took [69] milliseconds
2022-02-01 23:07:48.336 Received [162] bytes from 'fileinfo'
2022-02-01 23:07:48.339 [Trace] Sending data 'ps' id is [8868110349600946] length [6010]
2022-02-01 23:07:48.340 perf: Section 'ps' took [98] milliseconds
2022-02-01 23:07:48.361 Received [355] bytes from 'mem'
2022-02-01 23:07:48.393 Received [287] bytes from 'logwatch'
2022-02-01 23:07:48.393 perf:  In [120] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[5712] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-01 23:07:48.393 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:07:48.425 Received [128] bytes from 'local'
2022-02-01 23:07:48.455 perf:  In [177] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[11224] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:07:48.455 Received [128] bytes from 'mrpe'
2022-02-01 23:07:48.456 perf:  In [185] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[5444] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:07:48.456 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-01 23:07:48.456 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-01 23:07:48.456 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:07:48.456 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:07:48.486 Received [128] bytes from 'spool'
2022-02-01 23:07:48.517 Received [8085] bytes from 'services'
2022-02-01 23:07:48.549 Received [731] bytes from 'plugins'
2022-02-01 23:07:48.580 Received [4664] bytes from 'winperf'
2022-02-01 23:07:48.623 Received [383] bytes from 'df'
2022-02-01 23:07:48.658 Received [1503] bytes from 'dotnet_clrmemory'
2022-02-01 23:07:48.689 Received [6138] bytes from 'ps'
2022-02-01 23:07:48.690 perf: Answer is ready in [499] milliseconds
2022-02-01 23:07:48.690 Send [23999] bytes of data
2022-02-01 23:07:48.830 perf:  In [561] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[10252] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:07:48.830 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:07:48.986 perf:  In [717] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[7392] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:07:48.986 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:08:48.777 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-01 23:08:48.778 Put on queue, size is [1]
2022-02-01 23:08:48.778 Found connection on queue, in queue left[0]
2022-02-01 23:08:48.779 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-01 23:08:48.780 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-01 23:08:48.782 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:08:48.782 [Trace] Left [43] files to execute
2022-02-01 23:08:48.783 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:08:48.784 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:08:48.791 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.792 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.792 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:08:48.792 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.792 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.793 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:08:48.793 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.793 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:08:48.794 Generating answer number [1]
2022-02-01 23:08:48.794 Id is [8868170953916563] 
2022-02-01 23:08:48.795 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:08:48.795 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:08:48.795 [Trace] Provider 'wmi_cpuload' is direct called, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.844 Object 'Win32_PerfRawData_PerfOS_System' in 48ms sends [776] bytes
2022-02-01 23:08:48.851 Object 'Win32_ComputerSystem' in 6ms sends [1226] bytes
2022-02-01 23:08:48.851 [Trace] Sending data 'wmi_cpuload' id is [8868170953916563] length [2086]
2022-02-01 23:08:48.852 perf: Section 'wmi_cpuload' took [56] milliseconds
2022-02-01 23:08:48.852 [Trace] Provider 'uptime' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.852 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-01 23:08:48.853 [Trace] Sending data 'uptime' id is [8868170953916563] length [20]
2022-02-01 23:08:48.853 [Trace] Provider 'df' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.853 [Trace] Provider 'mem' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.854 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-01 23:08:48.854 [Trace] Provider 'services' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.854 [Trace] Loaded [3] entries in LogWatch
2022-02-01 23:08:48.854 [Trace] Provider 'ps' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.855 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:08:48.855 [Trace] Left [43] files to execute
2022-02-01 23:08:48.855 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-01 23:08:48.856 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-01 23:08:48.856 perf: Section 'uptime' took [0] milliseconds
2022-02-01 23:08:48.856 [Trace] Sending data 'mem' id is [8868170953916563] length [227]
2022-02-01 23:08:48.857 perf: Section 'mem' took [2] milliseconds
2022-02-01 23:08:48.857 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:8868170953916563 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-01 23:08:48.857 [Trace] Provider 'fileinfo' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.858 [Trace] Sending data 'fileinfo' id is [8868170953916563] length [34]
2022-02-01 23:08:48.858 Received [2214] bytes from 'wmi_cpuload'
2022-02-01 23:08:48.858 perf: Section 'fileinfo' took [0] milliseconds
2022-02-01 23:08:48.858 [Trace] Provider 'logwatch' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.863 [Trace] Sending data 'logwatch' id is [8868170953916563] length [159]
2022-02-01 23:08:48.863 perf: Section 'logwatch' took [4] milliseconds
2022-02-01 23:08:48.865 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.866 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.866 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-01 23:08:48.866 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.866 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.867 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-01 23:08:48.867 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:08:48.868 [Trace] Left [7] files to execute in 'plugins'
2022-02-01 23:08:48.868 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-01 23:08:48.869 [Trace] Left [0] files to execute
2022-02-01 23:08:48.869 [Trace] Left [0] files to execute in 'local'
2022-02-01 23:08:48.869 [Trace] Skipping 'wmi_webservices' by time
2022-02-01 23:08:48.869 [Trace] 'msexch' is skipped by config
2022-02-01 23:08:48.870 [Trace] Skipping 'msexch' by config
2022-02-01 23:08:48.870 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-01 23:08:48.870 [Trace] To start [0] sync plugins
2022-02-01 23:08:48.871 [Trace] Skipping 'skype' by config
2022-02-01 23:08:48.871 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-01 23:08:48.872 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.872 [Trace] Provider 'mrpe' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.872 [Warn ] Section 'mrpe' cannot provide data
2022-02-01 23:08:48.872 [Trace] Sending data 'mrpe' id is [8868170953916563] length [0]
2022-02-01 23:08:48.873 [Trace] To start [7] sync plugins
2022-02-01 23:08:48.873 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-01 23:08:48.873 perf: Section 'mrpe' took [0] milliseconds
2022-02-01 23:08:48.873 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:08:48.875 [Trace] Provider 'local' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.875 [Warn ] Section 'local' cannot provide data
2022-02-01 23:08:48.875 [Trace] Sending data 'local' id is [8868170953916563] length [0]
2022-02-01 23:08:48.876 perf: Section 'local' took [0] milliseconds
2022-02-01 23:08:48.876 [Trace] Provider 'spool' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.877 [Warn ] Section 'spool' cannot provide data
2022-02-01 23:08:48.877 [Trace] Sending data 'spool' id is [8868170953916563] length [0]
2022-02-01 23:08:48.877 perf: Section 'spool' took [0] milliseconds
2022-02-01 23:08:48.881 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-01 23:08:48.881 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-01 23:08:48.881 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '60' seconds
2022-02-01 23:08:48.881 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:08:48.882 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-01 23:08:48.885 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-01 23:08:48.885 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:08:48.885 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-01 23:08:48.885 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-01 23:08:48.886 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:08:48.887 Received [148] bytes from 'uptime'
2022-02-01 23:08:48.887 [Trace] Sending data 'services' id is [8868170953916563] length [7957]
2022-02-01 23:08:48.888 perf: Section 'services' took [33] milliseconds
2022-02-01 23:08:48.889 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-01 23:08:48.890 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-01 23:08:48.890 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:08:48.890 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-01 23:08:48.891 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:08:48.895 [Warn ] Bad creation date from WMI ''
2022-02-01 23:08:48.896 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-01 23:08:48.905 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-01 23:08:48.909 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-01 23:08:48.909 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:08:48.909 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-01 23:08:48.909 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:08:48.912 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-01 23:08:48.913 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-01 23:08:48.913 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:08:48.914 [Trace] Provider 'plugins' is about to be started, id '8868170953916563' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-01 23:08:48.914 [Trace] Sending data 'plugins' id is [8868170953916563] length [603]
2022-02-01 23:08:48.914 perf: Section 'plugins' took [0] milliseconds
2022-02-01 23:08:48.920 Received [355] bytes from 'mem'
2022-02-01 23:08:48.923 [Trace] df: Processed [5] drives
2022-02-01 23:08:48.923 [Trace] Sending data 'df' id is [8868170953916563] length [255]
2022-02-01 23:08:48.923 perf: Section 'df' took [70] milliseconds
2022-02-01 23:08:48.936 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 64ms sends [1337] bytes
2022-02-01 23:08:48.937 [Trace] Sending data 'dotnet_clrmemory' id is [8868170953916563] length [1387]
2022-02-01 23:08:48.937 perf: Section 'dotnet_clrmemory' took [64] milliseconds
2022-02-01 23:08:48.945 [Trace] Sending data 'ps' id is [8868170953916563] length [6003]
2022-02-01 23:08:48.946 perf: Section 'ps' took [90] milliseconds
2022-02-01 23:08:48.949 Received [162] bytes from 'fileinfo'
2022-02-01 23:08:48.987 Received [287] bytes from 'logwatch'
2022-02-01 23:08:49.011 Received [128] bytes from 'mrpe'
2022-02-01 23:08:49.027 perf:  In [114] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[1704] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:08:49.027 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-01 23:08:49.028 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-01 23:08:49.043 Received [128] bytes from 'local'
2022-02-01 23:08:49.074 Received [128] bytes from 'spool'
2022-02-01 23:08:49.105 Received [8085] bytes from 'services'
2022-02-01 23:08:49.105 perf:  In [196] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[10944] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-01 23:08:49.106 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-01 23:08:49.136 Received [731] bytes from 'plugins'
2022-02-01 23:08:49.137 perf:  In [246] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[9516] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-01 23:08:49.138 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-01 23:08:49.138 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-01 23:08:49.167 Received [383] bytes from 'df'
2022-02-01 23:08:49.198 Received [4664] bytes from 'winperf'
2022-02-01 23:08:49.230 Received [1515] bytes from 'dotnet_clrmemory'
2022-02-01 23:08:49.261 Received [6131] bytes from 'ps'
2022-02-01 23:08:49.261 perf: Answer is ready in [467] milliseconds
2022-02-01 23:08:49.262 Send [24004] bytes of data
2022-02-01 23:08:49.454 perf:  In [569] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[2900] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-01 23:08:49.454 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-01 23:08:49.464 perf:  In [582] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[8632] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-01 23:08:49.464 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'

I didn’t change the default settings in the plugin regarding the SYNC-/ASYNC sections:

...
# Sections that run fast and are not run with caching
$SYNC_SECTIONS = @("instance", "sessions", "logswitches", "undostat", "recovery_area", "processes", "recovery_status", "longactivesessions", "dataguard_stats", "performance")
...
# Sections that are run in the background and at a larger interval.
# These sections take longer to run and are therefore run in the background
# Note: sections not listed in ASYNC_ASM_SECTIONS, SYNC_SECTIONS or
# ASYNC_SECTIONS will not be executed at all!
$ASYNC_SECTIONS = @("tablespaces", "rman", "jobs", "ts_quotas", "resumable", "locks")
...

But, when I execute the plugin locally on the monitored server by “check_mk_agent.exe test”, all sections return quickly without any delay.
So I can’t believe that a long running section may be the cause of the issue… The agent should discover the checks, but it doesn’t…

Kind regards,
Antje

akummich · February 2, 2022, 8:40am

Addition:
The corresponding plugin config file only contains the DB user credentials (no adjustment of the SYNC-/ASYNC sections):
mk_oracle_cfg.ps1:

$DBUSER=@("xxxx", "xxxx", "SYSDBA", "localhost", "1521")

tosch · February 2, 2022, 9:05am

I also can’t see the execution of the plugin in the other time frame too. Something suspicious is happening there
I am not the expert of Windows agents and Windows plugins. Maybe @andreas-doehler or @r.sander have some hints here? On the oracle front i can’t see anything wrong so far.

andreas-doehler · February 2, 2022, 11:42am

The log file output looks very strange.
Most plugins exit without any usable data.
The oracle Powershell is not started at all.

First step to get better output would be a reboot the machine (uptime over 100 days )

akummich · February 2, 2022, 11:58am

It’s a customer’s server with productive databases running on it. We are not able to reboot the system immediately. But I will ask the customer.

The mk_oracle plugins runs for several hours… All other OS plugins also run regularly and provide performance data. If the server has a problem, we should have seen problems earlier, isn’t it?

andreas-doehler · February 2, 2022, 12:47pm

With the log file content i would say that nearly no plugin is running correctly
But it is difficult to debug such a problem without direct access to the client machine.

akummich · February 2, 2022, 12:56pm

I have direct access to the monitored machine. As I wrote, I get CPU, memory and filesystem data. The checkmk agent with its plugins works properly.
Would it help to increase the log level in the agent directory?
Currently I am only able to restart the Checkmk Agent service…

This is the current log content of another W2K12 server with a monitored Oracle DB where I don’t have any problems. The uptime is 22 days. To me, the log content is similar to my problem host…

2022-02-02 13:50:38.357 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-02 13:50:38.357 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-02 13:50:38.357 [Trace] Left [0] files to execute
2022-02-02 13:50:38.357 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-02 13:50:38.357 [Trace] Left [0] files to execute in 'local'
2022-02-02 13:50:38.358 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-02 13:50:38.358 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-02 13:50:38.358 [Trace] Skipping 'wmi_webservices' by time
2022-02-02 13:50:38.358 [Trace] To start [0] sync plugins
2022-02-02 13:50:38.359 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '1948716592845786' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:50:38.359 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-02 13:50:38.359 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' is too old, age is '58' seconds
2022-02-02 13:50:38.360 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:50:38.360 [Trace] 'msexch' is skipped by config
2022-02-02 13:50:38.360 [Trace] Provider 'local' is about to be started, id '1948716592845786' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:50:38.360 [Warn ] Section 'local' cannot provide data
2022-02-02 13:50:38.360 [Trace] Sending data 'local' id is [1948716592845786] length [0]
2022-02-02 13:50:38.361 [Trace] Skipping 'msexch' by config
2022-02-02 13:50:38.362 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1 is to be started
2022-02-02 13:50:38.362 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:50:38.362 perf: Section 'local' took [0] milliseconds
2022-02-02 13:50:38.363 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-02 13:50:38.363 [Warn ] Bad creation date from WMI ''
2022-02-02 13:50:38.363 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1"', mode [0]
2022-02-02 13:50:38.363 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '59' seconds
2022-02-02 13:50:38.364 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-02 13:50:38.364 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-02 13:50:38.364 [Trace] Skipping 'skype' by config
2022-02-02 13:50:38.364 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-02 13:50:38.365 [Trace] Provider 'spool' is about to be started, id '1948716592845786' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:50:38.365 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-02 13:50:38.365 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-02 13:50:38.365 [Trace] Provider 'mrpe' is about to be started, id '1948716592845786' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:50:38.365 [Warn ] Section 'spool' cannot provide data
2022-02-02 13:50:38.366 [Trace] Sending data 'spool' id is [1948716592845786] length [0]
2022-02-02 13:50:38.366 perf: Section 'spool' took [1] milliseconds
2022-02-02 13:50:38.366 [Warn ] Section 'mrpe' cannot provide data
2022-02-02 13:50:38.367 [Trace] Sending data 'mrpe' id is [1948716592845786] length [0]
2022-02-02 13:50:38.367 perf: Section 'mrpe' took [1] milliseconds
2022-02-02 13:50:38.368 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-02 13:50:38.368 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-02 13:50:38.368 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-02 13:50:38.371 [Trace] Sending data 'services' id is [1948716592845786] length [7751]
2022-02-02 13:50:38.371 [Trace] df: Processed [7] drives
2022-02-02 13:50:38.371 [Trace] Sending data 'df' id is [1948716592845786] length [364]
2022-02-02 13:50:38.371 perf: Section 'df' took [30] milliseconds
2022-02-02 13:50:38.372 perf: Section 'services' took [29] milliseconds
2022-02-02 13:50:38.372 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-02 13:50:38.372 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-02 13:50:38.372 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-02 13:50:38.372 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-02 13:50:38.373 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-02 13:50:38.375 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-02 13:50:38.375 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-02 13:50:38.375 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-02 13:50:38.375 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-02 13:50:38.375 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-02 13:50:38.375 [Trace] Provider 'plugins' is about to be started, id '1948716592845786' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:50:38.376 [Trace] Sending data 'plugins' id is [1948716592845786] length [11369]
2022-02-02 13:50:38.376 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-02 13:50:38.376 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-02 13:50:38.376 perf: Section 'plugins' took [0] milliseconds
2022-02-02 13:50:38.377 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-02 13:50:38.382 [Trace] Sending data 'ps' id is [1948716592845786] length [6037]
2022-02-02 13:50:38.383 perf: Section 'ps' took [40] milliseconds
2022-02-02 13:50:38.383 Received [148] bytes from 'uptime'
2022-02-02 13:50:38.394 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 35ms sends [1528] bytes
2022-02-02 13:50:38.395 [Trace] Sending data 'dotnet_clrmemory' id is [1948716592845786] length [1581]
2022-02-02 13:50:38.395 perf: Section 'dotnet_clrmemory' took [35] milliseconds
2022-02-02 13:50:38.415 Received [357] bytes from 'mem'
2022-02-02 13:50:38.446 Received [162] bytes from 'fileinfo'
2022-02-02 13:50:38.477 Received [305] bytes from 'logwatch'
2022-02-02 13:50:38.508 Received [128] bytes from 'local'
2022-02-02 13:50:38.542 Received [128] bytes from 'spool'
2022-02-02 13:50:38.571 Received [128] bytes from 'mrpe'
2022-02-02 13:50:38.603 Received [7879] bytes from 'services'
2022-02-02 13:50:38.634 Received [492] bytes from 'df'
2022-02-02 13:50:38.649 perf:  In [276] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[13684] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-02 13:50:38.649 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-02 13:50:38.649 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-02 13:50:38.650 perf:  In [274] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[14068] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-02 13:50:38.651 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-02 13:50:38.651 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-02 13:50:38.668 Received [11497] bytes from 'plugins'
2022-02-02 13:50:38.695 Received [6165] bytes from 'ps'
2022-02-02 13:50:38.727 Received [1709] bytes from 'dotnet_clrmemory'
2022-02-02 13:50:38.742 perf:  In [366] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[9476] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-02 13:50:38.743 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-02 13:50:38.758 Received [5871] bytes from 'winperf'
2022-02-02 13:50:38.758 perf: Answer is ready in [446] milliseconds
2022-02-02 13:50:38.759 Send [36128] bytes of data
2022-02-02 13:50:39.150 perf:  In [791] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[12340] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-02 13:50:39.150 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-02 13:50:39.179 perf:  In [814] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[10704] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-02 13:50:39.179 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-02 13:50:40.349 perf:  In [1986] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' pid:[5984] SUCCEDED - generated [10746] bytes of data in [5] blocks
2022-02-02 13:50:40.349 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:51:38.866 Connected from '10.107.3.6' ipv6 :false -> queue
2022-02-02 13:51:38.866 Put on queue, size is [1]
2022-02-02 13:51:38.866 Found connection on queue, in queue left[0]
2022-02-02 13:51:38.866 Connected from '10.107.3.6' ipv6:false <- queue
2022-02-02 13:51:38.867 [Warn ] OHM file 'C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe' is not found
2022-02-02 13:51:38.867 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-02 13:51:38.867 [Trace] Left [44] files to execute
2022-02-02 13:51:38.867 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-02 13:51:38.868 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-02 13:51:38.875 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.875 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.875 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-02 13:51:38.875 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.875 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.876 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_p4_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.876 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-02 13:51:38.876 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.876 [Trace] Left [8] files to execute in 'plugins'
2022-02-02 13:51:38.876 Generating answer number [1]
2022-02-02 13:51:38.876 Id is [1948777158161318] 
2022-02-02 13:51:38.877 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-02 13:51:38.877 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-02 13:51:38.877 [Trace] Provider 'wmi_cpuload' is direct called, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.897 Object 'Win32_PerfRawData_PerfOS_System' in 19ms sends [776] bytes
2022-02-02 13:51:38.905 Object 'Win32_ComputerSystem' in 7ms sends [1226] bytes
2022-02-02 13:51:38.906 [Trace] Sending data 'wmi_cpuload' id is [1948777158161318] length [2086]
2022-02-02 13:51:38.906 perf: Section 'wmi_cpuload' took [28] milliseconds
2022-02-02 13:51:38.906 [Trace] Provider 'uptime' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.907 Using file 'C:\Program Files (x86)\checkmk\service\check_mk_agent.exe' for winperf
2022-02-02 13:51:38.907 [Trace] Sending data 'uptime' id is [1948777158161318] length [20]
2022-02-02 13:51:38.907 Exec C:\Program Files (x86)\checkmk\service\check_mk_agent.exe for winperf started
2022-02-02 13:51:38.907 [Trace] Provider 'df' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.908 [Trace] Provider 'mem' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.908 [Trace] Provider 'services' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.908 [Trace] Provider 'ps' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.908 [Trace] Provider 'fileinfo' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.909 [Trace] Loaded [3] entries in LogWatch
2022-02-02 13:51:38.909 perf: Section 'uptime' took [0] milliseconds
2022-02-02 13:51:38.909 async RunStdCmd: "C:\Program Files (x86)\checkmk\service\check_mk_agent.exe" -runonce winperf mail:\\.\mailslot\Global\WinAgent_0 id:1948777158161318 timeout:10 ip:10.107.3.6 234:phydisk 510:if 238:processor
2022-02-02 13:51:38.910 [Trace] Sending data 'mem' id is [1948777158161318] length [229]
2022-02-02 13:51:38.910 [Trace] Sending data 'fileinfo' id is [1948777158161318] length [34]
2022-02-02 13:51:38.910 [Trace] Provider 'logwatch' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.910 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-02 13:51:38.911 perf: Section 'mem' took [1] milliseconds
2022-02-02 13:51:38.911 perf: Section 'fileinfo' took [1] milliseconds
2022-02-02 13:51:38.911 [Trace] Left [44] files to execute
2022-02-02 13:51:38.911 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe' forced to be async, due to cache_age [3600]
2022-02-02 13:51:38.912 [Trace] Sync Plugin Entry 'C:\ProgramData\checkmk\agent\plugins\veeam_*' forced to be async, due to cache_age [3600]
2022-02-02 13:51:38.917 [Trace] Sending data 'logwatch' id is [1948777158161318] length [177]
2022-02-02 13:51:38.917 perf: Section 'logwatch' took [6] milliseconds
2022-02-02 13:51:38.918 Received [2214] bytes from 'wmi_cpuload'
2022-02-02 13:51:38.920 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.920 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.920 Plugin 'C:\ProgramData\checkmk\agent\plugins\cmk-update-agent.exe'  is  async with age:3600 timeout:300 retry:3
2022-02-02 13:51:38.921 Plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.921 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.921 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_p4_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.921 Plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'  is  async with age:14400 timeout:600 retry:3
2022-02-02 13:51:38.921 Plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'  is  async with age:0 timeout:300 retry:3
2022-02-02 13:51:38.922 [Trace] Left [8] files to execute in 'plugins'
2022-02-02 13:51:38.922 [Trace] To start [8] sync plugins
2022-02-02 13:51:38.922 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' is too old, age is '59' seconds
2022-02-02 13:51:38.922 Allowed Extensions: [exe,bat,vbs,ps1]
2022-02-02 13:51:38.923 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-02 13:51:38.923 [Trace] Left [0] files to execute
2022-02-02 13:51:38.923 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-02 13:51:38.923 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1 is to be started
2022-02-02 13:51:38.924 [Trace] Left [0] files to execute in 'local'
2022-02-02 13:51:38.924 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' is too old, age is '58' seconds
2022-02-02 13:51:38.924 [Trace] To start [0] sync plugins
2022-02-02 13:51:38.925 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:51:38.925 [Trace] Skipping 'wmi_webservices' by time
2022-02-02 13:51:38.925 [Trace] Provider 'dotnet_clrmemory' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.925 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1"', mode [0]
2022-02-02 13:51:38.926 [Trace] Provider 'local' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.926 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:51:38.926 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1 is to be started
2022-02-02 13:51:38.927 [Trace] 'msexch' is skipped by config
2022-02-02 13:51:38.927 [Warn ] Section 'local' cannot provide data
2022-02-02 13:51:38.927 [Trace] Sending data 'local' id is [1948777158161318] length [0]
2022-02-02 13:51:38.928 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' is too old, age is '59' seconds
2022-02-02 13:51:38.928 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-02 13:51:38.928 [Trace] Skipping 'msexch' by config
2022-02-02 13:51:38.928 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1"', mode [0]
2022-02-02 13:51:38.929 [Warn ] Bad creation date from WMI ''
2022-02-02 13:51:38.929 Async Thread for C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1 is to be started
2022-02-02 13:51:38.929 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-02 13:51:38.930 [Trace] Absent/Empty node mrpe.config type is 1
2022-02-02 13:51:38.930 [Warn ] Can't determine creation time of the process 'System Idle Process'
2022-02-02 13:51:38.930 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1"', mode [0]
2022-02-02 13:51:38.930 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' is too old, age is '60' seconds
2022-02-02 13:51:38.931 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-02 13:51:38.931 [Trace] Skipping 'skype' by config
2022-02-02 13:51:38.931 [Trace] Skipping 'openhardwaremonitor' by time
2022-02-02 13:51:38.932 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs is to be started
2022-02-02 13:51:38.932 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs"', mode [0]
2022-02-02 13:51:38.932 [Trace] Provider 'spool' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.933 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-02 13:51:38.933 [Warn ] Section 'spool' cannot provide data
2022-02-02 13:51:38.933 [Trace] Sending data 'spool' id is [1948777158161318] length [0]
2022-02-02 13:51:38.934 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' is too old, age is '60' seconds
2022-02-02 13:51:38.934 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-02 13:51:38.934 perf: Section 'spool' took [0] milliseconds
2022-02-02 13:51:38.935 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-02 13:51:38.935 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' is too old, age is '60' seconds
2022-02-02 13:51:38.935 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-02 13:51:38.936 Async Thread for C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs is to be started
2022-02-02 13:51:38.936 Async Thread for C:\ProgramData\checkmk\agent\plugins\mssql.vbs is to be started
2022-02-02 13:51:38.936 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\mssql.vbs"', mode [0]
2022-02-02 13:51:38.936 [Trace] df: Processed [7] drives
2022-02-02 13:51:38.936 [Trace] Sending data 'df' id is [1948777158161318] length [364]
2022-02-02 13:51:38.937 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-02 13:51:38.937 [Trace] Exec app 'cscript.exe //Nologo "C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs"', mode [0]
2022-02-02 13:51:38.937 perf: Section 'df' took [29] milliseconds
2022-02-02 13:51:38.938 [Trace] Provider 'plugins' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.938 [Trace] Sending data 'plugins' id is [1948777158161318] length [11369]
2022-02-02 13:51:38.938 perf: Section 'plugins' took [0] milliseconds
2022-02-02 13:51:38.938 [Trace] Provider 'mrpe' is about to be started, id '1948777158161318' port [mail:\\.\mailslot\Global\WinAgent_0]
2022-02-02 13:51:38.938 [Warn ] Section 'mrpe' cannot provide data
2022-02-02 13:51:38.938 [Trace] Sending data 'mrpe' id is [1948777158161318] length [0]
2022-02-02 13:51:38.939 perf: Section 'local' took [1] milliseconds
2022-02-02 13:51:38.939 perf: Section 'mrpe' took [0] milliseconds
2022-02-02 13:51:38.942 [Trace] Sending data 'services' id is [1948777158161318] length [7751]
2022-02-02 13:51:38.942 perf: Section 'services' took [33] milliseconds
2022-02-02 13:51:38.950 Received [148] bytes from 'uptime'
2022-02-02 13:51:38.951 [Trace] Sending data 'ps' id is [1948777158161318] length [6059]
2022-02-02 13:51:38.952 perf: Section 'ps' took [43] milliseconds
2022-02-02 13:51:38.968 Object 'Win32_PerfRawData_NETFramework_NETCLRMemory' in 42ms sends [1563] bytes
2022-02-02 13:51:38.968 [Trace] Sending data 'dotnet_clrmemory' id is [1948777158161318] length [1616]
2022-02-02 13:51:38.968 perf: Section 'dotnet_clrmemory' took [43] milliseconds
2022-02-02 13:51:38.981 Received [357] bytes from 'mem'
2022-02-02 13:51:39.012 Received [162] bytes from 'fileinfo'
2022-02-02 13:51:39.043 Received [305] bytes from 'logwatch'
2022-02-02 13:51:39.074 Received [128] bytes from 'local'
2022-02-02 13:51:39.106 Received [128] bytes from 'spool'
2022-02-02 13:51:39.137 Received [492] bytes from 'df'
2022-02-02 13:51:39.168 Received [11497] bytes from 'plugins'
2022-02-02 13:51:39.203 Received [128] bytes from 'mrpe'
2022-02-02 13:51:39.236 Received [7879] bytes from 'services'
2022-02-02 13:51:39.246 perf:  In [310] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' pid:[10100] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-02 13:51:39.247 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs' has no data
2022-02-02 13:51:39.247 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\windows_updates.vbs'
2022-02-02 13:51:39.262 Received [6187] bytes from 'ps'
2022-02-02 13:51:39.277 perf:  In [345] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' pid:[4288] SUCCEDED - generated [2] bytes of data in [1] blocks
2022-02-02 13:51:39.278 [Warn ] Process 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs' has no data
2022-02-02 13:51:39.278 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_inventory.vbs'
2022-02-02 13:51:39.293 Received [1744] bytes from 'dotnet_clrmemory'
2022-02-02 13:51:39.324 Received [5872] bytes from 'winperf'
2022-02-02 13:51:39.324 perf: Answer is ready in [447] milliseconds
2022-02-02 13:51:39.325 Send [36186] bytes of data
2022-02-02 13:51:39.371 perf:  In [434] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs' pid:[12356] SUCCEDED - generated [420] bytes of data in [1] blocks
2022-02-02 13:51:39.371 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mssql.vbs'
2022-02-02 13:51:39.683 perf:  In [753] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1' pid:[7972] SUCCEDED - generated [9] bytes of data in [1] blocks
2022-02-02 13:51:39.683 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms_guestinfos.ps1'
2022-02-02 13:51:39.699 perf:  In [774] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1' pid:[5272] SUCCEDED - generated [24] bytes of data in [1] blocks
2022-02-02 13:51:39.699 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\hyperv_vms.ps1'
2022-02-02 13:51:40.915 perf:  In [1988] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' pid:[15756] SUCCEDED - generated [10746] bytes of data in [5] blocks
2022-02-02 13:51:40.916 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'

Or is there any difference?

andreas-doehler · February 2, 2022, 1:01pm

This log looks way better. You see that the plugin is executed every minute and takes around 2 seconds execution time with an output of 11kb.

akummich · February 2, 2022, 1:05pm

What log lines are you looking for in the logs?
When I search for the lines matching “restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1”, I get an entry every minute in both files…

andreas-doehler · February 2, 2022, 7:00pm

Here booth logs compared.

Good log

2022-02-02 13:50:38.359 [Warn ] Data 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' is too old, age is '58' seconds
2022-02-02 13:50:38.360 restarting async plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:50:38.362 Async Thread for C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1 is to be started
2022-02-02 13:50:38.362 restarted thread for plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'
2022-02-02 13:50:38.363 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1"', mode [0]
2022-02-02 13:50:40.349 perf:  In [1986] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' pid:[5984] SUCCEDED - generated [10746] bytes of data in [5] blocks
2022-02-02 13:50:40.349 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'

Bad log

2022-02-01 23:04:46.407 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3
2022-02-01 23:04:46.482 Plugin 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'  is  async with age:0 timeout:300 retry:3

In the bad log is no “restarting …” for the Oracle plugin.

akummich · February 3, 2022, 8:02am

Hi Andreas,

I am sorry, I not able to confirm your detection in both log files. I compared the current logs on both systems again. The mentioned log entry can be found every minute on the working and the failing server:

good log:

bad log:

As I already mentioned: all Oracle services are running for several hours properly. There must something happening in between that causes a failure of the Oracle plugin… Is it possible to increase the log level of the Checkmk agent?

andreas-doehler · February 3, 2022, 8:19am

andreas-doehler:

2022-02-02 13:50:38.363 [Trace] Exec app 'powershell.exe -NoLogo -NoProfile -ExecutionPolicy Bypass -File "C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1"', mode [0]
2022-02-02 13:50:40.349 perf:  In [1986] milliseconds process 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1' pid:[5984] SUCCEDED - generated [10746] bytes of data in [5] blocks
2022-02-02 13:50:40.349 [Trace] Thread OFF: 'C:\ProgramData\checkmk\agent\plugins\mk_oracle.ps1'

These lines are the important ones. If you don’t see it then the plugin is not running

akummich · February 3, 2022, 11:53am

Thank you for your help.
Unfortunately, I still don’t know what the root cause of this issue is…

akummich · February 17, 2022, 6:24am

One thing that helped on some affected Windows servers is to set a cache age in the agent for the Oracle plugin (we use the agent bakery). Timeouts had already been set for each plugin. 300 seconds for both values should be ok.
Unfortunately, I still have one Windows system with the issue, where I have to find a solution.

ChristianM · February 17, 2022, 7:49am

Hi,
did you check about action on t he database during the time where services unknown like reorg, bockup or other database locks?
Kind regards,
Christian

akummich · February 17, 2022, 8:44am

Hi Christian,

thank you for your help.
As I already wrote: When I execute the Checkmk agent locally on the affected server (using check_mk_agent.exe test), the plugin is executed properly. I get all Oracle sections and their values. So I guess, that there is no database problem.

Indeed, there can be a relation to backups, because the Check_MK Discovery shows vanished services always late in the evening and at the weekend. I will investigate.
But how can I avoid that a backup effects the agent requests? Shall I set a scheduled downtime?

Kind regards,
Antje

tosch · February 17, 2022, 9:06am

Hi @akummich,

try to cache as many as services as possible which aren’t time critical for monitoring. For example we disabled the monitoring of oracle jobs completely because they put quite a amount of work on the database to gather this stats and are totally irrelevant for us.
Also sections you don’t care at all or doesn’t give generate a service because not relevant on your system could be disabled. Also if they don’t deliver information, they need some performance or the SQL statement.
Sections for our larger RAC installations:

akummich · February 17, 2022, 9:52am

Hi @tosch,

thank you very much for your help.
That’s a good tip - I’ve disabled all Oracle sections on the affected server which we don’t want to monitor. I will monitor the behaviour tomorrow morning. Hopefully, that will help.
By the way, it’s no RAC system.

Kind regards,
Antje