OneAgent auto upgrade on Windows Desktop

[snikolic]

Hi,

I have the OneAgent for SaaS Dynatrace installed through a company software distribution policy (version 1.135). It is reporting back to the tenant fine. However, selecting the host in Dynatrace console tells me that the upgrade is available (to 1.143). Selecting upgrade button indicates the upgrade is progressing, and after some time upgrade failed due to another upgrade already running.

Looking through the ruxitagent_host_NNNN log file - indication is that the installer (.msi) file download fails - presumably because the proxy is blocking unauthorized download (HTTP code 407).

Interesting is that it seem to download the msi file and the installer signature (msi.sig) and successfully verify the signature. Then it waits for the install to finish, and attempts the install again for some reason (see line: 2018-05-22 02:55:46.928 UTC to 2018-05-22 03:00:54.699 UTC).

2018-05-22 02:46:00.441 UTC [0000230c] info [native] Plugin update report. New: Updated: dynatrace.python.openstack.glance:0.002->1.002 | dynatrace.python.openstack.libvirt:1.13->1.15 | ruxit.python.docker:2.123->2.127 | ruxit.python.haproxy:2.002->2.003 | ruxit.python.memcached:2.000->2.001 | ruxit.python.notifications.openstack:1.32->1.34 | ruxit.python.rabbitmq:2.005->2.009 | ruxit.python.redis:2.002->2.003 | Removed: ruxit.jmx.activemq:2.001 | ruxit.jmx.appserver:1.807 | ruxit.jmx.appserver.jetty:1.805 | ruxit.jmx.cassandra:2.000 | ruxit.jmx.hadoop.hdfs:2.001 | ruxit.jmx.hadoop.yarn:2.001 | ruxit.jmx.hornetq:1.792 | ruxit.jmx.netflix.servo:1.2 | ruxit.jmx.solr:1.800 | ruxit.jmx.spark:2.001 | ruxit.pmi.appserver:1.030 | ruxit.pmi.connectionpool:1.024 | Content changed - Plugin Agent restart required. 2018-05-22 02:47:47.061 UTC [0000234c] info [native] AutoUpdater: Downloading installer file. 2018-05-22 02:47:52.113 UTC [0000234c] info [native] AutoUpdater: Started download of version: 1.143.114.20180504-102758 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:51:05.584 UTC [00001d20] info [native] URL https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... not working (Received HTTP code 407 from proxy after CONNECT) 2018-05-22 02:55:46.927 UTC [0000234c] info [native] AutoUpdater: Downloaded file: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 02:55:46.928 UTC [0000234c] info [native] AutoUpdater: Downloading installer signature. 2018-05-22 02:55:50.704 UTC [0000234c] info [native] AutoUpdater: Started download of version: 1.143.114.20180504-102758 2018-05-22 02:55:55.503 UTC [0000234c] info [native] AutoUpdater: Downloaded file: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi.sig 2018-05-22 02:55:55.503 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 02:55:55.503 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 166070 MB, needed 447 MB. 2018-05-22 02:55:55.509 UTC [0000234c] info [native] AutoUpdater: Free system memory: 29629MB 2018-05-22 02:55:55.969 UTC [0000234c] info [native] AutoUpdater: Used 77368320 bytes to calculate installer file sha-256 digest: 30ad834db1df516d020996005b319e890713743cd2df70d6093a7c328aa88a71 2018-05-22 02:55:55.969 UTC [0000234c] info [native] AutoUpdater: Signature verification successful 2018-05-22 02:55:57.924 UTC [0000234c] info [native] AutoUpdater: Waiting for finishing external msi finished 2018-05-22 02:55:57.924 UTC [0000234c] info [native] AutoUpdater: Waiting for updater binary to finish. 2018-05-22 02:59:13.807 UTC [00001d20] info [native] Local time is 2018-05-22 02:59:13.571 UTC, Cluster time is 2018-05-22 02:59:13.417 UTC (+154ms) 2018-05-22 02:59:23.679 UTC [00001d20] info [native] Local time is 2018-05-22 02:59:23.342 UTC, Cluster time is 2018-05-22 02:59:23.430 UTC (-88ms) 2018-05-22 03:00:54.698 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:00:54.699 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165984 MB, needed 447 MB. 2018-05-22 03:00:54.701 UTC [0000234c] info [native] AutoUpdater: Could not start auto-update, another installer working. 2018-05-22 03:02:13.813 UTC [00001d20] info [native] Exception handling periodic task heartbeat: unable to perform request using https://sg-ap-southeast-2-52-63-8-98-prod-ap-sout... Failure when receiving data from the peer. Totaltime: 0.0310s, Uploadsize: 0b, Downloadsize: 0b, Connecttime: 0s 2018-05-22 03:02:14.033 UTC [00001d20] info [native] Exception handling periodic task protocols.messages.shared.ClusterRuntimeInfoRequest: Not sent because last heartbeat failed. 2018-05-22 03:02:14.033 UTC [00001d20] info [native] Exception handling periodic task protocols.messages.configuration.ConfigurationRequest: Not sent because last heartbeat failed. 2018-05-22 03:02:14.033 UTC [00001d20] info [native] Exception handling periodic task protocols.messages.configuration.OSAgentConfigurationRequest: Not sent because last heartbeat failed. 2018-05-22 03:02:16.256 UTC [00002364] warning [native] Exception sending async messages: Not sent because last heartbeat failed. 2018-05-22 03:02:23.825 UTC [00001d20] info [native] Exception handling periodic task protocols.messages.shared.ClusterTimeRequest: Not sent because last heartbeat failed. 2018-05-22 03:02:26.062 UTC [00001d20] info [native] Successfully handled periodic task heartbeat 2018-05-22 03:02:26.389 UTC [00001d20] info [native] Successfully handled periodic task protocols.messages.shared.ClusterRuntimeInfoRequest 2018-05-22 03:02:28.314 UTC [00001d20] info [native] Successfully handled periodic task protocols.messages.configuration.ConfigurationRequest 2018-05-22 03:02:29.778 UTC [00001d20] info [native] Successfully handled periodic task protocols.messages.configuration.OSAgentConfigurationRequest 2018-05-22 03:02:34.223 UTC [00001d20] info [native] Successfully handled periodic task protocols.messages.shared.ClusterTimeRequest 2018-05-22 03:02:51.274 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:02:51.275 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165984 MB, needed 447 MB. 2018-05-22 03:02:51.275 UTC [0000234c] info [native] AutoUpdater: Could not start auto-update, another installer working. 2018-05-22 03:04:48.216 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:04:48.217 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165984 MB, needed 447 MB. 2018-05-22 03:04:48.219 UTC [0000234c] info [native] AutoUpdater: Could not start auto-update, another installer working. 2018-05-22 03:06:45.760 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:06:45.761 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165983 MB, needed 447 MB. 2018-05-22 03:06:45.763 UTC [0000234c] info [native] AutoUpdater: Could not start auto-update, another installer working. 2018-05-22 03:08:49.939 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:08:49.940 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165982 MB, needed 447 MB. 2018-05-22 03:08:49.941 UTC [0000234c] info [native] AutoUpdater: Could not start auto-update, another installer working. 2018-05-22 03:09:33.801 UTC [00001d20] info [native] Local time is 2018-05-22 03:09:33.668 UTC, Cluster time is 2018-05-22 03:09:33.467 UTC (+201ms) 2018-05-22 03:09:43.679 UTC [00001d20] info [native] Local time is 2018-05-22 03:09:43.395 UTC, Cluster time is 2018-05-22 03:09:43.448 UTC (-53ms) 2018-05-22 03:10:49.624 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:10:49.625 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165982 MB, needed 447 MB. 2018-05-22 03:10:49.626 UTC [0000234c] info [native] AutoUpdater: Could not start auto-update, another installer working. 2018-05-22 03:12:46.506 UTC [0000234c] info [native] AutoUpdater: Starting update to version 1.143.114.20180504-102758 from: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:12:46.506 UTC [0000234c] info [native] AutoUpdater: Free space available on "C:" 165982 MB, needed 447 MB. 2018-05-22 03:12:46.512 UTC [0000234c] info [native] AutoUpdater: Free system memory: 29595MB 2018-05-22 03:12:46.514 UTC [0000234c] warning [native] AutoUpdater: Failed to open installer file: C:/Program Files (x86)/dynatrace/oneagent/downloads/Dynatrace-OneAgent-Windows-1.143.114.20180504-102758.msi 2018-05-22 03:12:46.515 UTC [0000234c] info [native] suspicious: AutoUpdater: Signature verification failed for downloaded installer file. Aborting installation 2018-05-22 03:14:51.182 UTC [0000234c] info [native] AutoUpdater: Downloading installer file. 2018-05-22 03:14:56.003 UTC [0000234c] info [native] AutoUpdater: Started download of version: 1.143.114.20180504-102758 

I can see the installation progressing and the oneagent folder being cleared and rebuilt and installer.version contains:

1.143.114.20180504-102758

BUT...

Console says:

OneAgent updates settings Dynatrace OneAgent is currently on version 1.135.159.

Apply Global Settings: do not update OneAgent instances automaticallyAutomatically update OneAgent on this hostDo not update OneAgent on this host automatically Auto-update was unsuccessful - Another installer is currently working.

...

In the mean time - the downloaded installer files are gone and the log is showing the 1.143 installer version AND the ruxitagent_host log is showing (Check the VERSION!!!!!):

2018-05-22 03:26:57.511 UTC [00002048] info [native] -------------------------------------------------------------------------------- 2018-05-22 03:26:57.511 UTC [00002048] info [native] Dynatrace Agent for ADK Copyright (C) 2012-2018 Dynatrace LLC. www.dynatrace.com 2018-05-22 03:26:57.511 UTC [00002048] info [native] -------------------------------------------------------------------------------- 2018-05-22 03:26:57.511 UTC [00002048] info [native] Version ..................... 1.135.139.20180109-150515, build date 2018.01.09 15:05:15, svn rev. 768138 2018-05-22 03:26:57.511 UTC [00002048] info [native] Command line is "C:\Program Files (x86)\dynatrace\oneagent\agent\lib64\oneagentos.exe" -Dcom.compuware.apm.WatchDogTimeout=900 -Dcom.compuware.apm.WatchDogPort=50000 2018-05-22 03:26:57.511 UTC [00002048] info [native] Build platform .............. Windows x86 64-bit 2018-05-22 03:26:57.511 UTC [00002048] info [native] Platform .................... Windows 8.1 6.3.9600 x64 2018-05-22 03:26:57.511 UTC [00002048] info [native] OS edition .................. Standard 2018-05-22 03:26:57.511 UTC [00002048] info [native] OS productId ................ Unknown 2018-05-22 03:26:57.511 UTC [00002048] info [native] Hyper-V friendly name ....... Unknown 2018-05-22 03:26:57.511 UTC [00002048] info [native] System startup time ......... 2018-05-22 00:00:35 UTC 2018-05-22 03:26:57.511 UTC [00002048] info [native] Local timezone .............. UTC+1100 2018-05-22 03:26:57.511 UTC [00002048] info [native] User name ................... AUSTRALIANSUPER\AS201279$ 2018-05-22 03:26:57.511 UTC [00002048] info [native] Bootstrap version ........... 1.135.138.20180109-143329 2018-05-22 03:26:57.511 UTC [00002048] info [native] Log level console ........... none 2018-05-22 03:26:57.511 UTC [00002048] info [native] Log level file .............. info 2018-05-22 03:26:57.511 UTC [00002048] info [native] Log file .................... C:/Program Files (x86)/dynatrace/oneagent/log/os/ruxitagent_host_7216.0.log 2018-05-22 03:26:57.511 UTC [00002048] info [native] APR version ................. 1.5.2 2018-05-22 03:26:57.511 UTC [00002048] info [native] cURL version ................ libcurl/7.56.1 OpenSSL/1.0.2m zlib/1.2.8 2018-05-22 03:26:57.511 UTC [00002048] info [native] OpenSSL version ............. OpenSSL 1.0.2m 2 Nov 2017 2018-05-22 03:26:57.511 UTC [00002048] info [native] zlib version ................ 1.2.8 2018-05-22 03:26:57.511 UTC [00002048] info [native] Installer version ........... 1.135.159.20180123-161756 

Is this something that the tech support should be concerned with or is this something that is a local issue

[Tomasz_Gajger · Accepted solution]

Hi @Srdjan N.

Based on the logs that you've provided the only conclusion that I am able to make is that there is a problem with AutoUpdate on the host in question. We've recently been improving how the mechanism works. This could've been a problem with stopping old OneAgent service, but without full logs this is hard to tell.

Please kindly open a support case so that we can proceed with further investigation.

Regards,
Tomasz

[snikolic]

Hi Tomasz,

After a bit of investigation we are at the moment thinking that this issue was triggered by the following sequence:

1) Use SCCM (Windows Deployment Policies) to install the version X of the OneAgent across the environment (lots of hosts - can't do manual deployment per host).

2) Use the host properties page in Dynatrace SaaS to trigger OneAgent self update to version Y.

3) In the background, SCCM detects the change of the installed OneAgent signature and forces re-install of the version X.

4) OneAgent reports update failure and the OneAgent version stays at X 😞

We are still testing a modification to the installation policy that does not force reinstall, but the workaround is to make sure the OneAgent self-update is not attempted when the OneAgent installation is under SCCM control, but use SCCM consistently for all installs and version updates.

If anyone has a different experience, feel free to comment.