Closed WishmasterUK closed 4 years ago
Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @pvrk.
It seems "01/01/2001 00:00:00" is default value if there is no backup. Service team, please look into this problem.
The only server in the example I provided to look at is MW-2019-SERVER, the other 2 backups on my subscription are being removed in a few days so that info is correct as it hasn't ran in a while.
This issue is happening across all the checks I deployed in our RMM system (N-Central) that runs this script for our Azure clients. They all report last backup time as 12th June where we have checked each one manually and they are up to date as per their daily policy. Recovery Point details seem to be coming through correctly.
The Get-AzRecoveryServicesBackupItem cmdlet seems to be correctly displaying the results it receives from backend service. As mentioned the issue seems to be with MW-2019-SERVER, for which the last recoveryPointTime is "2020-06-18T08:37:37.1833669Z" but while getting the backupItems it shows "lastBackupStatus" as "" and "lastBackupTime" as "2001-01-01T00:00:00Z"
The other two backup items "mw-vm-2019test" and "mw-vm-dc" seem to be fine for which lastBackupTime is "2020-06-06T01:29:14.2957535Z" and "2020-06-06T00:07:50.4102982Z" respectively.
@WishmasterUK, can you please run and provide us the output of the below commands -
$vault=Get-AzRecoveryServicesVault -ResourceGroupName "mw-test-vnet" -Name "mw-vnet-rsv" Get-AzRecoveryServicesBackupItem -BackupManagementType "AzureVM" -WorkloadType "AzureVM" -VaultId $vault.ID -debug
There is an ongoing issue (in the backend) in returning the latest backup status, date and other relevant issues. This is not an issue with Azure Backup powershell but with Azure Backup service. Will update the thread with details of fix.
@pvrk Thank you for confirming an issue within Azure, I suspected as much given the lack of any errors in gathering job info.
@hiaga I doubt you need this now but here is the output from your commands, only the vm named MW-2019-SERVER exists now that my old vm backups have been fully removed.
PS C:\Users\MWAdmin>
$vault=Get-AzRecoveryServicesVault -ResourceGroupName "mw-test-vnet" -Name "mw-vnet-rsv"
Get-AzRecoveryServicesBackupItem -BackupManagementType "AzureVM" -WorkloadType "AzureVM" -VaultId $vault.ID -debug
DEBUG: 10:17:56 - GetAzureRmRecoveryServicesBackupItem begin processing with ParameterSet 'GetItemsForVault'. DEBUG: 10:18:00 - using account id '3b82497f-f6dd-4748-a2b3-da1e71590777'... DEBUG: Inside Restore. Going to create ResourceClient. DEBUG: [Common.Authentication]: Authenticating using Account: '3b82497f-f6dd-4748-a2b3-da1e71590777', environment: 'AzureCloud', tenant: '26005678-d224-4eec-b562-ed0367d13c33' DEBUG: [Common.Authentication]: Authenticating using configuration values: Domain: '26005678-d224-4eec-b562-ed0367d13c33', Endpoint: 'https://login.microsoftonline.com/', ClientId: '1950a258-227b-4e31-a9cf-717495945fc2', ClientRedirect: 'urn:ietf:wg:oauth:2. 0:oob', ResourceClientUri: 'https://management.core.windows.net/', ValidateAuthority: 'True' DEBUG: [Common.Authentication]: Renewing token using AppId: '3b82497f-f6dd-4748-a2b3-da1e71590777', AdalConfiguration with ADDomain: '26005678-d224-4eec-b562-ed0367d13c33', AdEndpoint: 'https://login.microsoftonline.com/', ClientId: '1950a258-227b-4e31-a9cf- 717495945fc2', RedirectUri: 'urn:ietf:wg:oauth:2.0:oob' DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: ADAL PCL.Desktop with assembly version '3.19.2.6005', file version '3.19.50302.0130' and informational version '2a8bec6c4c76d0c1ef819b55bdc3cda2d2 605056' is running...
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: ADAL PCL.Desktop with assembly version '3.19.2.6005', file version '3.19.50302.0130' and informational version '2a8bec6c4c76d0c1ef819b55bdc3cda2d2 605056' is running...
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: === Token Acquisition started: CacheType: null Authentication Target: Client , Authority Host: login.microsoftonline.com
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: === Token Acquisition started: Authority: https://login.microsoftonline.com/26005678-d224-4eec-b562-ed0367d13c33/ Resource: https://management.core.windows.net/ ClientId: 3b82497f-f6dd-4748-a2b3-da1e71590777 CacheType: null Authentication Target: Client
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: Loading from cache.
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: Loading from cache.
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: 00000000-0000-0000-0000-000000000000 - LoggerBase.cs: Deserialized 1 items to token cache.
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: Looking up cache for a token...
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: Looking up cache for a token...
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: An item matching the requested resource was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: An item matching the requested resource was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: 54.5135503016667 minutes left until token in cache expires
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: 54.5135503016667 minutes left until token in cache expires
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: A matching item (access token or refresh token or both) was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: A matching item (access token or refresh token or both) was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: === Token Acquisition finished successfully. An access token was returned: Expiration Time: 23/06/2020 10:12:31 +00:00
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8259819Z: cebbe1de-fa94-4666-a54a-6278165109f9 - LoggerBase.cs: === Token Acquisition finished successfully. An access token was returned: Expiration Time: 23/06/2020 10:12:31 +00:00Access Token Hash: Kr/KDul/z Ot1Vb4C1Oq01I9YpNDWMlmtWOpYYUFTU9k= User id:
DEBUG: Client Created successfully DEBUG: [Common.Authentication]: Authenticating using Account: '3b82497f-f6dd-4748-a2b3-da1e71590777', environment: 'AzureCloud', tenant: '26005678-d224-4eec-b562-ed0367d13c33' DEBUG: [Common.Authentication]: Authenticating using configuration values: Domain: '26005678-d224-4eec-b562-ed0367d13c33', Endpoint: 'https://login.microsoftonline.com/', ClientId: '1950a258-227b-4e31-a9cf-717495945fc2', ClientRedirect: 'urn:ietf:wg:oauth:2. 0:oob', ResourceClientUri: 'https://management.core.windows.net/', ValidateAuthority: 'True' DEBUG: [Common.Authentication]: Renewing token using AppId: '3b82497f-f6dd-4748-a2b3-da1e71590777', AdalConfiguration with ADDomain: '26005678-d224-4eec-b562-ed0367d13c33', AdEndpoint: 'https://login.microsoftonline.com/', ClientId: '1950a258-227b-4e31-a9cf- 717495945fc2', RedirectUri: 'urn:ietf:wg:oauth:2.0:oob' DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: ADAL PCL.Desktop with assembly version '3.19.2.6005', file version '3.19.50302.0130' and informational version '2a8bec6c4c76d0c1ef819b55bdc3cda2d2 605056' is running...
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: ADAL PCL.Desktop with assembly version '3.19.2.6005', file version '3.19.50302.0130' and informational version '2a8bec6c4c76d0c1ef819b55bdc3cda2d2 605056' is running...
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: === Token Acquisition started: CacheType: null Authentication Target: Client , Authority Host: login.microsoftonline.com
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: === Token Acquisition started: Authority: https://login.microsoftonline.com/26005678-d224-4eec-b562-ed0367d13c33/ Resource: https://management.core.windows.net/ ClientId: 3b82497f-f6dd-4748-a2b3-da1e71590777 CacheType: null Authentication Target: Client
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: Loading from cache.
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: Loading from cache.
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: 00000000-0000-0000-0000-000000000000 - LoggerBase.cs: Deserialized 1 items to token cache.
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: Looking up cache for a token...
DEBUG: [ADAL]: Verbose: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: Looking up cache for a token...
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: An item matching the requested resource was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: An item matching the requested resource was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: 54.513323455 minutes left until token in cache expires
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: 54.513323455 minutes left until token in cache expires
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: A matching item (access token or refresh token or both) was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: A matching item (access token or refresh token or both) was found in the cache
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: === Token Acquisition finished successfully. An access token was returned: Expiration Time: 23/06/2020 10:12:31 +00:00
DEBUG: [ADAL]: Information: 2020-06-23T09:18:00.8395927Z: c7a05041-863d-4dbc-854c-a8d8488e2f91 - LoggerBase.cs: === Token Acquisition finished successfully. An access token was returned: Expiration Time: 23/06/2020 10:12:31 +00:00Access Token Hash: Kr/KDul/z Ot1Vb4C1Oq01I9YpNDWMlmtWOpYYUFTU9k= User id:
DEBUG: [Common.Authentication]: Checking token expiration, token expires '06/23/2020 10:12:31 +00:00' Comparing to '06/23/2020 09:18:00 +00:00' With threshold '00:05:00', calculated time until token expiry: '00:54:30.7994073' DEBUG: ============================ HTTP REQUEST ============================
HTTP Method: GET
Absolute Uri: https://management.azure.com/Subscriptions/2a71b569-c1ae-4837-9a58-716468a2b227/resourceGroups/mw-test-vnet/providers/Microsoft.RecoveryServices/vaults/mw-vnet-rsv/backupProtectedItems?$filter=backupManagementType eq 'AzureIaasVM' and itemType eq 'VM'&api-ve rsion=2019-06-15
Headers: x-ms-client-request-id : aeb4e7f6-4c2b-46ee-a8be-b00696e0490a accept-language : en-US
Body:
DEBUG: ============================ HTTP RESPONSE ============================
Status Code: OK
Headers: Pragma : no-cache X-Content-Type-Options : nosniff x-ms-request-id : 2525e5cb-8277-40ee-b671-93e25aa89f0d x-ms-client-request-id : 1679742e-c801-40f6-882e-f6f24d1f7432,1679742e-c801-40f6-882e-f6f24d1f7432 Strict-Transport-Security : max-age=31536000; includeSubDomains x-ms-ratelimit-remaining-subscription-reads: 11999 x-ms-correlation-request-id : 2525e5cb-8277-40ee-b671-93e25aa89f0d x-ms-routing-request-id : WESTEUROPE:20200623T091801Z:2525e5cb-8277-40ee-b671-93e25aa89f0d Cache-Control : no-cache Date : Tue, 23 Jun 2020 09:18:00 GMT Server : Microsoft-IIS/10.0 X-Powered-By : ASP.NET
Body: { "value": [ { "id": "/Subscriptions/2a71b569-c1ae-4837-9a58-716468a2b227/resourceGroups/mw-test-vnet/providers/Microsoft.RecoveryServices/vaults/mw-vnet-rsv/backupFabrics/Azure/protectionContainers/IaasVMContainer;iaasvmcontainerv2;mw-test-vnet;mw-2019-server/protec tedItems/VM;iaasvmcontainerv2;mw-test-vnet;mw-2019-server", "name": "VM;iaasvmcontainerv2;mw-test-vnet;mw-2019-server", "type": "Microsoft.RecoveryServices/vaults/backupFabrics/protectionContainers/protectedItems", "properties": { "friendlyName": "MW-2019-SERVER", "virtualMachineId": "/subscriptions/2a71b569-c1ae-4837-9a58-716468a2b227/resourceGroups/mw-test-vnet/providers/Microsoft.Compute/virtualMachines/MW-2019-SERVER", "protectionStatus": "Healthy", "protectionState": "Protected", "healthStatus": "Passed", "lastBackupStatus": "", "lastBackupTime": "2001-01-01T00:00:00Z", "protectedItemDataId": "211107145150327", "protectedItemType": "Microsoft.Compute/virtualMachines", "backupManagementType": "AzureIaasVM", "workloadType": "VM", "containerName": "iaasvmcontainerv2;mw-test-vnet;mw-2019-server", "sourceResourceId": "/subscriptions/2a71b569-c1ae-4837-9a58-716468a2b227/resourceGroups/mw-test-vnet/providers/Microsoft.Compute/virtualMachines/MW-2019-SERVER", "policyId": "/Subscriptions/2a71b569-c1ae-4837-9a58-716468a2b227/resourceGroups/mw-test-vnet/providers/Microsoft.RecoveryServices/vaults/mw-vnet-rsv/backupPolicies/DefaultPolicy", "policyName": "DefaultPolicy", "lastRecoveryPoint": "2020-06-23T08:33:54.4694631Z" } } ] }
Name ContainerType ContainerUniqueName WorkloadType ProtectionStatus HealthStatus DeleteState
VM;iaasvmcontainerv2;mw-test-vnet;mw-... AzureVM iaasvmcontainerv2;mw-test-vnet;mw-201... AzureVM Healthy Passed NotDeleted
DEBUG: AzureQoSEvent: CommandName - Get-AzRecoveryServicesBackupItem; IsSuccess - True; Duration - 00:00:04.9352993;
DEBUG: Finish sending metric.
DEBUG: 10:18:01 - GetAzureRmRecoveryServicesBackupItem end processing.
PS C:\Users\MWAdmin>
The issue is currently planned to be fixed by June 25th. Please recheck with available recovery points in June 26th or later.
@WishmasterUK Thanks for posting the results, but I was more interested in the results for other two backup items - ie. the lastBackupStatus/Time for those items. Anyways, as @pvrk said this is an internal service issue.
All working as expected again as of this morning, thanks.
Thanks for the confirmation. Closing this issue since the deployment completed and everything is working fine.
Description
I have a script I wrote and have used for over a year now, and since last Friday's AzureVM's backups the LastBackupTime and LastBackupStatus fields do not return the latest values. The latest recovery point fields are correct.
On a new test VM built yesterday, with backup configured, i get the following results in these fields and they do not update on further backups being ran.
Steps to reproduce
Environment data
Module versions
Debug output
Error output