vmaccessforlinux extension called when snapshot extension was run

This was a customer reported issue that the VMAccessForLinux extension was executed when the Snapshot/Backup extension was triggered although there wasn't a direct request made for executing the VMAccessForLinux.

From VMAccess extension log:
2017/02/24 16:00:43 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] sequence number is 0
2017/02/24 16:00:43 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] setting file path is/var/lib/waagent/Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0/config/0.settings
2017/02/24 16:00:43 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] JSON config: {"runtimeSettings": [{"handlerSettings": {"publicSettings": {}, "protectedSettingsCertThumbprint": "A39A71079C09A94F14635B8063F7C7443FA3F5CA", "protectedSettings": "MIIB6AYJKoZIhvcNAQcDoIIB2TCCAdUCAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEBRBxC0mj0W8RnawAYyCZnkwDQYJKoZIhvcNAQEBBQAEggEAdkdDQPSsF1E0cP7QOM9TiPsKvweByVDup+chhIrfYMRts+rKkN+xAeKecWf+gSsbcd0/I7MQ9d1kUZ9mD7dXb7nHAQWWHYpTq2vHvtGMTCNy48BC40ojAFwOISIPMTE4VkvO/9hYJu2bdDfN5LViwHtMh4HbDMF8BM/AraVtCrB3TPyZjvfYQE7ehZRex1gn2Plfa2qJupO29TczzbClgHS/K35extSoQxbCHN6uIFxi7yXNR4MvhOAuvWu/Gk6qeQ1mHlhuFGMSQlc+MWiuDLkkpUC0JHqCSoPt1+1QBY2e1kChGCJSkZDle3O8HPic7B2pBjegri3tU1hZqsA2QTBjBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECERZiYdVrkLlgECUAq10nreWm5C1fZZfNkLhAL1TUMRMuDMRg6doL6CysAjmzshxm3cYHd4c1nL6VBuP7tG4AzXAmN1sRTVAtuTf"}}]}
2017/02/24 16:00:43 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] Config decoded correctly.
2017/02/24 16:00:43 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] Install,success,0,Install Succeeded
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] sequence number is 0
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] setting file path is/var/lib/waagent/Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0/config/0.settings
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] JSON config: {"runtimeSettings": [{"handlerSettings": {"publicSettings": {}, "protectedSettingsCertThumbprint": "A39A71079C09A94F14635B8063F7C7443FA3F5CA", "protectedSettings": "MIIB6AYJKoZIhvcNAQcDoIIB2TCCAdUCAQAxggFpMIIBZQIBADBNMDkxNzA1BgoJkiaJk/IsZAEZFidXaW5kb3dzIEF6dXJlIENSUCBDZXJ0aWZpY2F0ZSBHZW5lcmF0b3ICEBRBxC0mj0W8RnawAYyCZnkwDQYJKoZIhvcNAQEBBQAEggEAdkdDQPSsF1E0cP7QOM9TiPsKvweByVDup+chhIrfYMRts+rKkN+xAeKecWf+gSsbcd0/I7MQ9d1kUZ9mD7dXb7nHAQWWHYpTq2vHvtGMTCNy48BC40ojAFwOISIPMTE4VkvO/9hYJu2bdDfN5LViwHtMh4HbDMF8BM/AraVtCrB3TPyZjvfYQE7ehZRex1gn2Plfa2qJupO29TczzbClgHS/K35extSoQxbCHN6uIFxi7yXNR4MvhOAuvWu/Gk6qeQ1mHlhuFGMSQlc+MWiuDLkkpUC0JHqCSoPt1+1QBY2e1kChGCJSkZDle3O8HPic7B2pBjegri3tU1hZqsA2QTBjBgkqhkiG9w0BBwEwFAYIKoZIhvcNAwcECERZiYdVrkLlgECUAq10nreWm5C1fZZfNkLhAL1TUMRMuDMRg6doL6CysAjmzshxm3cYHd4c1nL6VBuP7tG4AzXAmN1sRTVAtuTf"}}]}
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] Config decoded correctly.
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] set most recent sequence number to 0
2017/02/24 16:00:44 CreateAccount: tagetik already exists. Will update password.
2017/02/24 16:00:44 Change user password
2017/02/24 16:00:44 Created user account: tagetik
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] Succeeded in create the account or set the password.
2017/02/24 16:00:44 [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.6.0] Enable,success,0,Enable succeeded.

From waagent.log:
2017/08/01 23:14:32 VMAccess started to handle.
2017/08/01 23:14:33 MyBackupTestLinuxInt started to handle.
2017/08/01 23:14:36 MyBackupTestLinuxInt started to handle.
2017/08/02 23:14:53 VMAccess started to handle.
2017/08/02 23:14:54 MyBackupTestLinuxInt started to handle.
2017/08/02 23:14:56 MyBackupTestLinuxInt started to handle.
2017/08/03 23:18:43 VMAccess started to handle.
2017/08/03 23:18:44 MyBackupTestLinuxInt started to handle.
2017/08/03 23:18:46 MyBackupTestLinuxInt started to handle.
2017/08/04 23:22:06 VMAccess started to handle.
2017/08/04 23:22:07 MyBackupTestLinuxInt started to handle.
2017/08/04 23:22:09 MyBackupTestLinuxInt started to handle.
2017/08/05 23:19:51 VMAccess started to handle.
2017/08/05 23:19:52 MyBackupTestLinuxInt started to handle.
2017/08/05 23:19:54 MyBackupTestLinuxInt started to handle.
[…]
2017/08/21 12:33:00 VMAccess started to handle.
2017/08/21 12:33:02 MyBackupTestLinuxInt started to handle.
2017/08/21 12:50:37 VMAccess started to handle.
2017/08/21 12:50:38 MyBackupTestLinuxInt started to handle.
2017/08/21 23:23:09 VMAccess started to handle.
2017/08/21 23:23:10 MyBackupTestLinuxInt started to handle.
2017/08/21 23:23:11 MyBackupTestLinuxInt started to handle.
2017/08/22 13:52:47 VMAccess started to handle.
2017/08/22 13:52:48 VMAccess started to handle.
2017/08/22 13:52:49 MyBackupTestLinuxInt started to handle.
From VMAccess extension command execution log:
2017/08/22 13:52:47.324362 INFO [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.7.1] Target handler state: uninstall
2017/08/22 13:52:47.324645 INFO [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.7.1] [Uninstall] current handler state is: enabled
2017/08/22 13:52:47.325149 INFO [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.7.1] Disable extension [./vmaccess.py -disable]
2017/08/22 13:52:48.329471 INFO [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.7.1] Uninstall extension [./vmaccess.py -uninstall]
2017/08/22 13:52:49.333682 INFO [Microsoft.OSTCExtensions.VMAccessForLinux-1.4.7.1] Remove extension handler directory: /var/lib/waagent/Microsoft.OSTCExtensions.VMAccessForLinux-1.4.7.1
2017/08/22 23:14:10 MyBackupTestLinuxInt started to handle.
2017/08/22 23:14:10 MyBackupTestLinuxInt started to handle.
2017/08/23 23:22:53 MyBackupTestLinuxInt started to handle.
2017/08/23 23:22:54 MyBackupTestLinuxInt started to handle.

We can see the VMAccess extension is triggered everytime the Snapshot extension is executed.

Based on Chango's initial investigation, he reported:
"Looks like the VMAccessForLinux handler has an idempotency problem. The CRP log Chase referenced shows the extension remains at sequence number 0. "

Further investigation needs to be done to confirm if this is an actual bug or somehow the extension got into a bad state.

Start by examining the VMAccessForLinux handler and the vmaccess.py disable, uninstall, and enable paths shown in the command log. Compare handler sequence-number handling with the waagent.log entries when the Snapshot/Backup extension runs. Done means confirming the trigger or idempotency cause and preventing unintended VMAccess execution during Snapshot/Backup operations.

Written by the indexing model from the issue text.