• Arun Nukula

Behind the scenes: vRLCM upgrade 8.1 to 8.2

I always had a passion for reading logs and understanding what really happens in the background when a user clicks or performs an action through UI.

Yesterday, I did a blog about vRSLCM upgrade from 8.1 to 8.2 through UI, let me decipher what happens in the background when you upgrade.


The only log you would need to check is

/var/log/vrlcm/vmware_vrlcm.log
/var/log/bootstrap/preupdate.log
/var/log/bootstrap/postupdate.log


Just before you start an upgrade you would check if the upgrade is actually available or not.



2020-10-08 01:30:53.274 INFO  [http-nio-8080-exec-8] c.v.v.l.u.ShellExecutor -  -- Executing shell command: /opt/vmware/bin/vamicli update --check
2020-10-08 01:30:53.275 INFO  [http-nio-8080-exec-8] c.v.v.l.u.ProcessUtil -  -- Execute /opt/vmware/bin/vamicli
2020-10-08 01:30:55.475 INFO  [http-nio-8080-exec-8] c.v.v.l.u.ShellExecutor -  -- Result: [Checking for available updates, this process can take a few minutes...
..
Available Updates - 
   8.2.0.23 Build 16982087].

Once you have verified that the upgrade is available and you trigger an upgrade there is a Postgres backup taken in the background



2020-10-08 01:34:16.418 INFO  [http-nio-8080-exec-1] c.v.v.l.u.ShellExecutor -  -- Executing shell command: /etc/vlcm/upgrade-va
2020-10-08 01:34:16.419 INFO  [http-nio-8080-exec-1] c.v.v.l.u.ProcessUtil -  -- Execute /etc/vlcm/upgrade-va
2020-10-08 01:34:21.326 INFO  [http-nio-8080-exec-1] c.v.v.l.u.ShellExecutor -  -- Result: [taking postgres backup before starting upgrade
creating new backup file
current file does not exist
creating a deamon process
Successfully triggered upgrade.].

There will be a check which would be performed to see if an upgrade is already running


2020-10-08 01:34:21.383 INFO  [http-nio-8080-exec-6] c.v.v.l.u.ShellExecutor -  -- Executing shell command: /opt/vmware/bin/vamicli update --progress --detail
2020-10-08 01:34:21.385 INFO  [http-nio-8080-exec-6] c.v.v.l.u.ProcessUtil -  -- Execute /opt/vmware/bin/vamicli
2020-10-08 01:34:21.588 INFO  [http-nio-8080-exec-6] c.v.v.l.u.ShellExecutor -  -- Result: [No update instance is running.].


At this point, we start downloading packages needed for upgrade




2020-10-08 01:34:25.647 INFO  [http-nio-8080-exec-4] c.v.v.l.u.ProcessUtil -  -- Execute /opt/vmware/bin/vamicli
2020-10-08 01:34:25.947 INFO  [http-nio-8080-exec-4] c.v.v.l.u.ShellExecutor -  -- Result: [4/92 packages downloaded.
Downloading...
PyYAML  Done
VMware-Log-Insight-Agent  Done
audit Done
bindutils Done
blackstone  
bzip2 
bzip2-libs  
ca-certificates 
*
*
*
vmware-studio-appliance-config  
vmware-studio-init  
which 
zip].
2020-10-08 01:34:41.643 INFO  [http-nio-8080-exec-3] c.v.v.l.u.ShellExecutor -  -- Executing shell command: /opt/vmware/bin/vamicli update --progress --detail
2020-10-08 01:34:41.645 INFO  [http-nio-8080-exec-3] c.v.v.l.u.ProcessUtil -  -- Execute /opt/vmware/bin/vamicli
2020-10-08 01:34:41.814 INFO  [http-nio-8080-exec-3] c.v.v.l.u.ShellExecutor -  -- Result: [69/92 packages downloaded.
Downloading...
PyYAML  Done
VMware-Log-Insight-Agent  Done
*
*
*
vmware-studio-appliance-config  
vmware-studio-init  
which 
zip].
*
*
*

2020-10-08 01:38:37.939 INFO  [http-nio-8080-exec-10] c.v.v.l.u.ShellExecutor -  -- Executing shell command: /opt/vmware/bin/vamicli update --progress --detail
2020-10-08 01:38:37.942 INFO  [http-nio-8080-exec-10] c.v.v.l.u.ProcessUtil -  -- Execute /opt/vmware/bin/vamicli
2020-10-08 01:38:38.072 INFO  [http-nio-8080-exec-10] c.v.v.l.u.ShellExecutor -  -- Result: [92 packages have been downloaded.


Once all the packages have been downloaded it would start installing also it triggers /etc/bootstrap/postupdate.d/*.* scripts as well



2020-10-08 01:38:39 Main bootstrap postupdate started

2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/00-00-rpm-status-check starting...
Check if RPM packages are performed properly...
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/00-00-rpm-status-check done, succeeded.
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/20-disable-password-expiration starting...
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/20-disable-password-expiration done, succeeded.
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/21-update-ulimit starting...
Updating ulimit...
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/21-update-ulimit done, succeeded.

2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/23-postgres-conf starting...
checking whether autovaccum configurations already exists.
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/23-postgres-conf done, succeeded.
2020-10-08 01:38:39 /etc/bootstrap/postupdate.d/25-start-services starting...
+ set -e
+ echo 'Reboot not required so starting all service.'
Reboot not required so starting all service.
+ systemctl daemon-reload
+ systemctl restart vpostgres
+ touch /var/log/bootstrap/reboot-required
+ systemctl restart vrlcm-server
+ systemctl restart blackstone-spring
+ cp -r /var/lib/vrlcm/nginx.conf /etc/nginx/
+ cp -r /var/lib/vrlcm/ssl.conf /etc/nginx/
+ systemctl reload nginx
+ rm /var/lib/vrlcm/SUCCESS
+ rm -rf /tmp/dlfRepo
+ [[ ! -f /etc/triggerLicenseUpdate ]]
+ touch /etc/triggerLicenseUpdate
+ [[ -f /var/log/vrlcm/status.txt ]]
+ rm -rf /var/log/vrlcm/status.txt_backup
+ cp -r /var/log/vrlcm/status.txt /var/log/vrlcm/status.txt_backup
+ rm -rf /var/log/vrlcm/status.txt
+ /var/lib/vrlcm/populate.sh
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
^M  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0^M  0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0^M  0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0^M  0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 868, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 741, in format
    return fmt.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 465, in format
    record.message = record.getMessage()
  File "/usr/lib/python2.7/logging/__init__.py", line 329, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Logged from file insert.py, line 302
+ [[ -f /var/lib/vrlcm/SUCCESS ]]
+ echo 'Creating INPROGRESS to block UI from loading...'
Creating INPROGRESS to block UI from loading...
+ rm -rf /var/lib/vrlcm/SUCCESS
+ touch /var/lib/vrlcm/INPROGRESS
+ exit 0

After the above post-update tasks installation begins


2020-10-08 01:38:47.237 INFO  [http-nio-8080-exec-2] c.v.v.l.u.ShellExecutor -  -- Result: [92 packages have been downloaded.
Installing...].

2020-10-08 01:38:56.103 INFO  [background-preinit] o.h.v.i.u.Version -  -- HV000001: Hibernate Validator 6.0.20.Final
*
*
*
2020-10-08 01:41:39.490 INFO  [main] c.v.v.l.a.c.EngineInitializer -  -- Checking for IN_PROGRESS EVENTS
2020-10-08 01:41:39.592 INFO  [scheduling-1] c.v.v.l.a.g.c.CleanupProcessor -  -- Initiating clean-up and purging.
2020-10-08 01:41:41.017 INFO  [main] c.v.v.l.a.c.EngineInitializer -  -- IN_PROGRESS EVENTS Reset is Completed
2020-10-08 01:41:41.020 INFO  [main] c.v.v.v.s.c.DefaultUserInitializer -  -- Initializing default users and roles
2020-10-08 01:41:41.022 INFO  [main] c.v.v.l.c.l.MaskingPrintStream -  -- * SYSOUT/SYSERR CAPTURED:  -- Initializing default users and roles
2020-10-08 01:41:41.118 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : VCF Role
2020-10-08 01:41:41.121 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : Content Developer
2020-10-08 01:41:41.122 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : LCM Admin
2020-10-08 01:41:41.129 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : LCM Service Admin
2020-10-08 01:41:41.131 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : Content Release Manager
2020-10-08 01:41:41.132 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : LCM Support User
2020-10-08 01:41:41.134 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : LCM Cloud Admin
2020-10-08 01:41:41.142 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNRoleServiceImpl -  -- Existing Role name : Certificate Administrator
2020-10-08 01:41:41.217 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNUserServiceImpl -  -- Existing Local Username : serviceadmin@local
2020-10-08 01:41:41.219 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNUserServiceImpl -  -- Existing Local Username : vcfadmin@local
2020-10-08 01:41:41.220 INFO  [main] c.v.v.l.c.s.a.s.i.AuthNUserServiceImpl -  -- Existing Local Username : admin@local
2020-10-08 01:41:41.227 INFO  [main] c.v.v.v.s.c.DefaultUserInitializer -  -- Initializing default users and roles completed
2020-10-08 01:41:41.229 INFO  [main] c.v.v.l.c.l.MaskingPrintStream -  -- * SYSOUT/SYSERR CAPTURED:  -- Initializing default users and roles completed
2020-10-08 01:41:41.231 INFO  [main] c.v.v.v.s.c.ClientResourceInitializer -  -- Loading config params for setting Client Resource
2020-10-08 01:41:41.390 INFO  [main] c.v.v.v.s.c.ClientResourceInitializerUtil -  -- Truststore initialized with vidm cert.
*
*
*

2020-10-08 01:41:43.473 WARN  [main] c.v.v.l.l.u.PostUpgradeTriggers -  -- Not processing post upgrade triggers yet as reboot is pending.
2020-10-08 01:41:43.473 INFO  [main] c.v.v.l.l.e.PostEveryBootTriggers -  -- **************Invoke triggerPostEveryBoot started**************
2020-10-08 01:41:43.476 INFO  [main] c.v.v.l.l.e.PostEveryBootTriggers -  -- **************Invoke triggerPostEveryBoot completed**************
2020-10-08 01:41:43.476 INFO  [main] c.v.v.l.l.LcmUpdateInitializer -  -- **************Invoke triggerPostUpdate started**************
2020-10-08 01:41:43.497 WARN  [every-boot-thread] c.v.v.l.l.e.PostEveryBootTriggers -  -- Not processing post everyboot triggers yet as reboot is pending.
2020-10-08 01:41:43.493 INFO  [main] c.v.v.l.l.s.SystemServiceImpl -  -- Restarting server detected
2020-10-08 01:41:43.506 INFO  [main] c.v.v.l.l.s.SystemServiceImpl -  -- POST UPDATE  invoked....false
2020-10-08 01:41:43.506 INFO  [main] c.v.v.l.l.s.SystemServiceImpl -  -- Restarting server detected
2020-10-08 01:41:43.507 INFO  [main] c.v.v.l.l.s.SystemServiceImpl -  -- INPROGRESS file not available. Skip Patching instructions
2020-10-08 01:41:43.508 INFO  [main] c.v.v.l.l.LcmUpdateInitializer -  -- **************Invoke triggerPostUpdate completed*************

Populates or Updates the content

2020-10-08 01:42:10.924 INFO  [scheduling-1] c.v.v.l.u.ZipUtility -  -- Successfully populated file paths from the file system 
2020-10-08 01:42:10.926 INFO  [scheduling-1] c.v.v.l.u.ZipUtility -  -- Zipping to dir/var/log/vrlcm/purge/08-10-2020-01-41.zip
*
*
2020-10-08 01:42:21.671 INFO  [http-nio-8080-exec-1] c.v.v.l.c.c.ContentRepositoryController -  -- Creating content operation.
*
2020-10-08 01:42:21.815 INFO  [http-nio-8080-exec-1] c.v.v.l.c.s.ContentDownloadUrlServiceImpl -  -- PATH ::adapterconfiguration.vmfx
*
2020-10-08 01:42:21.849 INFO  [http-nio-8080-exec-5] c.v.v.l.c.c.ContentRepositoryController -  -- Creating content operation.
*
2020