New-AzureRmSqlDatabaseCopy : Long running operation failed with status 'NotFound'

gstolz commented 6 years ago

Description

When calling New-AzureRmSqlDatabaseCopy we sporadically receive error message "Long running operation failed with status 'NotFound'". (on Azure Germany)

Script/Steps for Reproduction

All the need resources are present.

New-AzureRmSqlDatabaseCopy -ResourceGroupName $rgName -ServerName $sourceSqlServerName -DatabaseName $db.DatabaseName -CopyResourceGroupName $rgName -CopyServerName $targetSqlServerName -CopyDatabaseName $db.DatabaseName -ElasticPoolName $targetElPoolName

Module Version

Script 6.1.0 AzureRM

Environment Data

Name Value
---- -----
PSVersion 5.1.14409.1012
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.14409.1012
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1

Debug Output

DEBUG: 09:32:41 - NewAzureSqlDatabaseCopy begin processing with ParameterSet 'DtuBasedDatabase'.
DEBUG: 09:32:41 - using account id '152a3cdd-'...
DEBUG: [Common.Authentication]: Authenticating using Account: '152a3cdd-', environment: 
'AzureGermanCloud', tenant: '1ddb90d5-'
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 17aa9027- - AcquireTokenHandlerBase: === Token Acquisition 
started:
 Authority: https://login.microsoftonline.de/1ddb90d5-/
 Resource: https://management.core.cloudapi.de/
 ClientId: 152a3cdd-
 CacheType: Microsoft.Azure.Commands.Common.Authentication.ProtectedFileTokenCache (5 items)
 Authentication Target: Client

DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41:  - TokenCache: Deserialized 5 items to token cache.
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Verbose: 1 : 
DEBUG: 06/13/2018 07:32:41: 17aa9027- - TokenCache: Looking up cache for a token...
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 17aa9027- - TokenCache: An item matching the requested resource 
was found in the cache
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Verbose: 1 : 
DEBUG: 06/13/2018 07:32:41: 17aa9027- - TokenCache: 21.2127137816667 minutes left until 
token in cache expires
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 17aa9027- - TokenCache: A matching item (access token or refresh
 token or both) was found in the cache
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 17aa9027- - AcquireTokenHandlerBase: === Token Acquisition 
finished successfully. An access token was retuned:
 Access Token Hash: O0M+gyMs0o3cROjW8OFdgnA3phGRDeffMN5EIDgbcHI=
 Refresh Token Hash: [No Refresh Token]
 Expiration Time: 06/13/2018 07:53:54 +00:00
 User Hash: null

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv/databases/azuresql-db?api-version=2017-10-01-preview

Headers:

x-ms-client-request-id        : d1549cb1-2231-4695-9819-6022f0e5fff0

accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

NotFound

Headers:

Pragma                        : no-cache

x-ms-request-id               : b8e5b556-acfa-4123-aaa0-dffdf3056460

x-ms-ratelimit-remaining-subscription-reads: 14972

x-ms-correlation-request-id   : a33dda10-cf5a-4d55-90ff-403e6b0e1806

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073241Z:a33dda10-cf5a-4d55-90ff-403e6b0e1806

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:32:40 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "error": {

    "code": "ResourceNotFound",

    "message": "The requested resource of type 'Microsoft.Sql/servers/databases' with name 'azuresql-db' was 
not found."

  }

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv2?api-version=2015-05-01-preview

Headers:

x-ms-client-request-id        : d79ce711-34cb-46fb-afaf-55f40bebdfd4

accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

x-ms-request-id               : 912695cc-5539-4ef5-956d-1d6d5a7be95c

x-ms-ratelimit-remaining-subscription-reads: 14944

x-ms-correlation-request-id   : 3138daf2-4cff-4152-990c-496bd8f425cd

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073241Z:3138daf2-4cff-4152-990c-496bd8f425cd

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:32:40 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "kind": "v12.0",

  "properties": {

    "administratorLogin": "****",

    "version": "12.0",

    "state": "Ready",

    "fullyQualifiedDomainName": "azuresql-dbsrv2.database.cloudapi.de"

  },

  "location": "germanycentral",

  "id": 
"/subscriptions/f291673a-/resourceGroups/dev2-rg/providers/Microsoft.Sql/servers/azu
resql-tsi-dev2-dbsrv2",

  "name": "azuresql-dbsrv2",

  "type": "Microsoft.Sql/servers"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv?api-version=2015-05-01-preview

Headers:

x-ms-client-request-id        : 01373625-71aa-48d2-9308-ec379e1b95e9

accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

x-ms-request-id               : 5f928767-82cb-422b-8abd-4b17b4c45d13

x-ms-ratelimit-remaining-subscription-reads: 14943

x-ms-correlation-request-id   : 657819e1-2719-4fa5-bd3d-a49790c6cc74

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073241Z:657819e1-2719-4fa5-bd3d-a49790c6cc74

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:32:40 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "kind": "v12.0",

  "properties": {

    "administratorLogin": "****",

    "version": "12.0",

    "state": "Ready",

    "fullyQualifiedDomainName": "azuresql-dbsrv.database.cloudapi.de"

  },

  "location": "germanycentral",

  "id": 
"/subscriptions/f291673a-/resourceGroups/dev2-rg/providers/Microsoft.Sql/servers/azu
resql-tsi-dev2-dbsrv",

  "name": "azuresql-dbsrv",

  "type": "Microsoft.Sql/servers"

}

DEBUG: [Common.Authentication]: Authenticating using Account: '152a3cdd-', environment: 
'AzureGermanCloud', tenant: '1ddb90d5-'
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 610f5d46-c0f2-4405-9399-05ffbb4b41ea - AcquireTokenHandlerBase: === Token Acquisition 
started:
 Authority: https://login.microsoftonline.de/1ddb90d5-/
 Resource: https://management.core.cloudapi.de/
 ClientId: 152a3cdd-
 CacheType: Microsoft.Azure.Commands.Common.Authentication.ProtectedFileTokenCache (5 items)
 Authentication Target: Client

DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41:  - TokenCache: Deserialized 5 items to token cache.
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Verbose: 1 : 
DEBUG: 06/13/2018 07:32:41: 610f5d46-c0f2-4405-9399-05ffbb4b41ea - TokenCache: Looking up cache for a token...
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 610f5d46-c0f2-4405-9399-05ffbb4b41ea - TokenCache: An item matching the requested resource 
was found in the cache
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Verbose: 1 : 
DEBUG: 06/13/2018 07:32:41: 610f5d46-c0f2-4405-9399-05ffbb4b41ea - TokenCache: 21.207130725 minutes left until token in
 cache expires
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 610f5d46-c0f2-4405-9399-05ffbb4b41ea - TokenCache: A matching item (access token or refresh
 token or both) was found in the cache
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 610f5d46-c0f2-4405-9399-05ffbb4b41ea - AcquireTokenHandlerBase: === Token Acquisition 
finished successfully. An access token was retuned:
 Access Token Hash: O0M+gyMs0o3cROjW8OFdgnA3phGRDeffMN5EIDgbcHI=
 Refresh Token Hash: [No Refresh Token]
 Expiration Time: 06/13/2018 07:53:54 +00:00
 User Hash: null

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv2/databases/azuresql-db?api-version=2017-10-01-preview

Headers:

x-ms-client-request-id        : 576b131f-9078-444a-93b5-04918532c3c6

accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

x-ms-request-id               : df397fa7-1d90-46a0-98a0-ff7b8431a373

x-ms-ratelimit-remaining-subscription-reads: 14942

x-ms-correlation-request-id   : 713aec31-da37-41d5-93de-2b377d65d6bd

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073241Z:713aec31-da37-41d5-93de-2b377d65d6bd

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:32:41 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "sku": {

    "name": "ElasticPool",

    "tier": "Standard",

    "capacity": 0

  },

  "kind": "v12.0,user",

  "properties": {

    "collation": "SQL_Latin1_General_CP1_CI_AS",

    "maxSizeBytes": 268435456000,

    "elasticPoolId": 
"/subscriptions/f291673a-/resourceGroups/dev2-rg/providers/Microsoft.Sql/servers/azu
resql-tsi-dev2-dbsrv2/elasticPools/azuresql-tsi-dev2-elpool2",

    "status": "Online",

    "databaseId": "c1980640-8edd-4968-b69b-9b10fa40796e",

    "creationDate": "2018-06-12T13:37:37.38Z",

    "currentServiceObjectiveName": "ElasticPool",

    "requestedServiceObjectiveName": "ElasticPool",

    "defaultSecondaryLocation": "germanynortheast",

    "catalogCollation": "SQL_Latin1_General_CP1_CI_AS",

    "zoneRedundant": false,

    "earliestRestoreDate": "2018-06-12T14:07:37.38Z",

    "readScale": "Disabled",

    "currentSku": {

      "name": "ElasticPool",

      "tier": "Standard",

      "capacity": 0

    }

  },

  "location": "germanycentral",

  "id": 
"/subscriptions/f291673a-/resourceGroups/dev2-rg/providers/Microsoft.Sql/servers/azu
resql-tsi-dev2-dbsrv2/databases/azuresql-db",

  "name": "azuresql-db",

  "type": "Microsoft.Sql/servers/databases"

}

DEBUG: [Common.Authentication]: Authenticating using Account: '152a3cdd-', environment: 
'AzureGermanCloud', tenant: '1ddb90d5-'
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 8aa53734-7e49-4e95-926a-02fdc9e0b20d - AcquireTokenHandlerBase: === Token Acquisition 
started:
 Authority: https://login.microsoftonline.de/1ddb90d5-/
 Resource: https://management.core.cloudapi.de/
 ClientId: 152a3cdd-
 CacheType: Microsoft.Azure.Commands.Common.Authentication.ProtectedFileTokenCache (5 items)
 Authentication Target: Client

DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41:  - TokenCache: Deserialized 5 items to token cache.
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Verbose: 1 : 
DEBUG: 06/13/2018 07:32:41: 8aa53734-7e49-4e95-926a-02fdc9e0b20d - TokenCache: Looking up cache for a token...
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 8aa53734-7e49-4e95-926a-02fdc9e0b20d - TokenCache: An item matching the requested resource 
was found in the cache
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Verbose: 1 : 
DEBUG: 06/13/2018 07:32:41: 8aa53734-7e49-4e95-926a-02fdc9e0b20d - TokenCache: 21.2048497583333 minutes left until 
token in cache expires
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 8aa53734-7e49-4e95-926a-02fdc9e0b20d - TokenCache: A matching item (access token or refresh
 token or both) was found in the cache
DEBUG: Microsoft.IdentityModel.Clients.ActiveDirectory Information: 2 : 
DEBUG: 06/13/2018 07:32:41: 8aa53734-7e49-4e95-926a-02fdc9e0b20d - AcquireTokenHandlerBase: === Token Acquisition 
finished successfully. An access token was retuned:
 Access Token Hash: O0M+gyMs0o3cROjW8OFdgnA3phGRDeffMN5EIDgbcHI=
 Refresh Token Hash: [No Refresh Token]
 Expiration Time: 06/13/2018 07:53:54 +00:00
 User Hash: null

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

PUT

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv/databases/azuresql-db?api-version=2017-10-01-preview

Headers:

x-ms-client-request-id        : 1581d76a-43b3-4de4-9647-0260382dfb3e

accept-language               : en-US

Body:

{

  "properties": {

    "createMode": "Copy",

    "elasticPoolId": 
"/subscriptions/f291673a-/resourceGroups/dev2-rg/providers/Microsoft.Sql/servers/azu
resql-tsi-dev2-dbsrv/elasticPools/azuresql-tsi-dev2-elpool",

    "sourceDatabaseId": 
"/subscriptions/f291673a-/resourceGroups/dev2-rg/providers/Microsoft.Sql/Servers/azu
resql-tsi-dev2-dbsrv2/databases/azuresql-db"

  },

  "location": "germanycentral"

}

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

Accepted

Headers:

Pragma                        : no-cache

Retry-After                   : 15

Azure-AsyncOperation          : 
https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

x-ms-request-id               : 3560c57c-3930-439b-8431-d58fb7786fb6

x-ms-ratelimit-remaining-subscription-writes: 1181

x-ms-correlation-request-id   : deac53b5-3384-4423-aa65-033dbac1c9e1

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073242Z:deac53b5-3384-4423-aa65-033dbac1c9e1

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:32:41 GMT

Location                      : 
https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseOperationResults/3027d248-acbb-43d1-b45f-0f7683132da0?api-vers
ion=2017-10-01-preview

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "operation": "CreateDatabaseAsCopy",

  "startTime": "2018-06-13T07:32:42.037Z"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

Headers:

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

Retry-After                   : 15

x-ms-request-id               : 0fdda9ac-e14a-410f-93cf-ea7c5e6e9749

x-ms-ratelimit-remaining-subscription-reads: 14962

x-ms-correlation-request-id   : d83eb7dd-a45a-4532-898d-94ef1c4c6673

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073257Z:d83eb7dd-a45a-4532-898d-94ef1c4c6673

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:32:57 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "name": "3027d248-acbb-43d1-b45f-0f7683132da0",

  "status": "InProgress",

  "startTime": "2018-06-13T07:32:42.303Z"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

Headers:

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

Retry-After                   : 15

x-ms-request-id               : 35734af0-ad41-42e2-b6ca-1683ce2169d5

x-ms-ratelimit-remaining-subscription-reads: 14961

x-ms-correlation-request-id   : 1358a1b9-b97b-4913-a73e-b6fd638967f9

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073312Z:1358a1b9-b97b-4913-a73e-b6fd638967f9

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:33:11 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "name": "3027d248-acbb-43d1-b45f-0f7683132da0",

  "status": "InProgress",

  "startTime": "2018-06-13T07:32:42.303Z"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

Headers:

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

Retry-After                   : 15

x-ms-request-id               : 01e151ec-47e4-48de-89c4-161b58a5ec87

x-ms-ratelimit-remaining-subscription-reads: 14960

x-ms-correlation-request-id   : 6bc32ada-1f3b-43e6-bb6e-b554d990c795

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073327Z:6bc32ada-1f3b-43e6-bb6e-b554d990c795

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:33:26 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "name": "3027d248-acbb-43d1-b45f-0f7683132da0",

  "status": "InProgress",

  "startTime": "2018-06-13T07:32:42.303Z"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

Headers:

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

Retry-After                   : 15

x-ms-request-id               : 112180e4-b2df-4bd7-8a9f-910d9a046ec0

x-ms-ratelimit-remaining-subscription-reads: 14959

x-ms-correlation-request-id   : 87ece2f2-af4a-40f0-be0a-90dd6e04cf79

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073342Z:87ece2f2-af4a-40f0-be0a-90dd6e04cf79

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:33:41 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "name": "3027d248-acbb-43d1-b45f-0f7683132da0",

  "status": "InProgress",

  "startTime": "2018-06-13T07:32:42.303Z"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

Headers:

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

OK

Headers:

Pragma                        : no-cache

Retry-After                   : 15

x-ms-request-id               : f71e9f2f-e592-470f-b196-dca13ac67930

x-ms-ratelimit-remaining-subscription-reads: 14958

x-ms-correlation-request-id   : 9ff19210-2f04-409b-8820-9d72f9dd52b8

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073357Z:9ff19210-2f04-409b-8820-9d72f9dd52b8

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:33:57 GMT

Server                        : Microsoft-HTTPAPI/2.0

Body:

{

  "name": "3027d248-acbb-43d1-b45f-0f7683132da0",

  "status": "Succeeded",

  "startTime": "2018-06-13T07:32:42.303Z"

}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:

GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv/databases/azuresql-db?api-version=2017-10-01-preview

Headers:

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:

NotFound

Headers:

Pragma                        : no-cache

x-ms-failure-cause            : gateway

x-ms-request-id               : 7b642a0a-ba42-4eef-9304-8e364b1bbf25

x-ms-correlation-request-id   : 7b642a0a-ba42-4eef-9304-8e364b1bbf25

x-ms-routing-request-id       : GERMANYCENTRAL:20180613T073357Z:7b642a0a-ba42-4eef-9304-8e364b1bbf25

Strict-Transport-Security     : max-age=31536000; includeSubDomains

X-Content-Type-Options        : nosniff

Cache-Control                 : no-cache

Date                          : Wed, 13 Jun 2018 07:33:57 GMT

Body:

{

  "error": {

    "code": "ResourceNotFound",

    "message": "The Resource 'Microsoft.Sql/servers/azuresql-dbsrv/databases/azuresql-db' under 
resource group 'dev2-rg' was not found."

  }

}

New-AzureRmSqlDatabaseCopy : Long running operation failed with status 'NotFound'.
In C:\Jenkins\workspace\GreenBlueDeployment\mia-infra-greenblue-database\infrastructure\Powershell\green-blue-deploymen
t\copy_tenant_dbs.ps1:97 Zeichen:5
+     New-AzureRmSqlDatabaseCopy -ResourceGroupName $rgName -ServerName ...
+     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : CloseError: (:) [New-AzureRmSqlDatabaseCopy], CloudException
    + FullyQualifiedErrorId : Microsoft.Azure.Commands.Sql.Replication.Cmdlet.NewAzureSqlDatabaseCopy

DEBUG: AzureQoSEvent: CommandName - New-AzureRmSqlDatabaseCopy; IsSuccess - False; Duration - 00:01:16.4644338; 
Exception - Microsoft.Rest.Azure.CloudException: Long running operation failed with status 'NotFound'.

   bei Microsoft.Rest.ClientRuntime.Azure.LRO.LROPollState`2.<CheckErrorStatusAndThrowAsync>d__52.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.ClientRuntime.Azure.LRO.LROPollState`2.<GetRawAsync>d__50.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.ClientRuntime.Azure.LRO.LROPollState`2.<UpdateResourceFromPollingUri>d__47.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.ClientRuntime.Azure.LRO.PutLRO`2.<PostPollingAsync>d__4.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.ClientRuntime.Azure.LRO.AzureLRO`2.<BeginLROAsync>d__12.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.Azure.AzureClientExtensions.<GetLongRunningOperationResultAsync>d__1`2.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.Azure.AzureClientExtensions.<GetLongRunningOperationResultAsync>d__0`1.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Rest.Azure.AzureClientExtensions.<GetPutOrPatchOperationResultAsync>d__5`1.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Azure.Management.Sql.DatabasesOperations.<CreateOrUpdateWithHttpMessagesAsync>d__14.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Azure.Management.Sql.DatabasesOperationsExtensions.<CreateOrUpdateAsync>d__19.MoveNext()

--- Ende der Stapel�berwachung vom vorhergehenden Ort, an dem die Ausnahme ausgel”st wurde ---

   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   bei Microsoft.Azure.Management.Sql.DatabasesOperationsExtensions.CreateOrUpdate(IDatabasesOperations operations, 
String resourceGroupName, String serverName, String databaseName, Database parameters)

   bei 
Microsoft.Azure.Commands.Sql.ReplicationLink.Services.AzureSqlDatabaseReplicationAdapter.CopyDatabaseWithNewSdk(String 
copyResourceGroup, String copyServerName, AzureSqlDatabaseCopyModel model)

   bei Microsoft.Azure.Commands.Sql.Replication.Cmdlet.NewAzureSqlDatabaseCopy.PersistChanges(IEnumerable`1 entity)

   bei Microsoft.Azure.Commands.Sql.Common.AzureSqlCmdletBase`2.<>c__DisplayClass16_0.<ExecuteCmdlet>b__0()

   bei Microsoft.WindowsAzure.Commands.Utilities.Common.AzurePSCmdlet.ConfirmAction(String processMessage, String 
target, Action action)

   bei Microsoft.Azure.Commands.Sql.Common.AzureSqlCmdletBase`2.ExecuteCmdlet()

   bei Microsoft.WindowsAzure.Commands.Utilities.Common.AzurePSCmdlet.ProcessRecord();
DEBUG: Finish sending metric.
DEBUG: 09:33:58 - NewAzureSqlDatabaseCopy end processing.
DEBUG: 09:33:58 - NewAzureSqlDatabaseCopy end processing.

gstolz commented 6 years ago

Just to be clear, the originating database is present. This error only appears sporadically. That's why I assume this has something to do with too limited timeouts. (sorry for the partly German output. I hope the important part is still readable.)

praries880 commented 6 years ago

@jaredmoo @akromm can you guys take a look at this issue?

martygriffin commented 6 years ago

Any updates on this issue?

dalibormesaric commented 6 years ago

This really became critical for us yesterday.

I already opened an issue #6122 but the behavior was that first it failed, and on the second try it succeeded. We were ok with that because we couldn't spend any more time dealing with support regarding this issue.

But yesterday it failed 5 or 6 times in a row. This stops us from deploying to production which is a critical issue.

jaredmoo commented 6 years ago

Sorry for not getting a chance to look at this for such a long time.

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method: GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/locations/germanycentral/databaseAzureAsyncOperation/3027d248-acbb-43d1-b45f-0f7683132da0?api-v
ersion=2017-10-01-preview

DEBUG: ============================ HTTP RESPONSE ============================

Status Code: OK
Body:
{
  "name": "3027d248-acbb-43d1-b45f-0f7683132da0",
  "status": "Succeeded",
  "startTime": "2018-06-13T07:32:42.303Z"
}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method: GET

Absolute Uri:

https://management.microsoftazure.de/subscriptions/f291673a-/resourceGroups/dev2-rg/
providers/Microsoft.Sql/servers/azuresql-dbsrv/databases/azuresql-db?api-version=2017-10-01-preview

DEBUG: ============================ HTTP RESPONSE ============================

Status Code: NotFound

Body:
{
  "error": {
    "code": "ResourceNotFound",
    "message": "The Resource 'Microsoft.Sql/servers/azuresql-dbsrv/databases/azuresql-db' under 
resource group 'dev2-rg' was not found."
  }
}

In the longs you can see that the long-running operation succeeded (GET databaseAzureAsyncOperation => "Succeeded"), but then GETting the database itself immediately after that failed.

Are you able to see the database using Azure management interfaces (e.g. Portal or PowerShell), and are you able to connect to the the database (e.g. using SSMS)? If you are able to connect with SSMS, was the database actually copied as expected?

My hypothesis for now is that the copy succeeded, but there is a timing issue where the database fails for GET in a short window after it is created.

@maboja-msft @jimoha fyi

MertSenel commented 5 years ago

Any updates on this is appreciated as we are also facing this issue.

anosov1960 commented 5 years ago

@MertSenel, we may know the answer but would like to confirm with your case before publishing. Can you pls send the server and database name (source and target).

MertSenel commented 5 years ago

@MertSenel, we may know the answer but would like to confirm with your case before publishing. Can you pls send the server and database name (source and target).

@anosov1960, I unfortunately can't share details as it happened to us in production environment. I had to fix this fast, so I just installed AzureRM module 5.7.0 and the latest 6.13.1 side by side and converted my scripts to import version 5.7.0 instead of the latest.

I will try to replicate this in the upcoming weeks and share details.

TheReaLee commented 5 years ago

Any news on this? We are running the New-AzureRmSqlDatabaseCopy daily and the above error is happening periodically.

AzureRM - 6.13.1 AzureRM.Sql - 4.12.1

mewilh0 commented 5 years ago

Same issue for me also. An immediate rerun of the process is successful.

AzureRM.Sql 4.12.1

codecontemplator commented 5 years ago

We experience this problem as well in Azure West Europe.

samsmithnz commented 5 years ago

This just started for me in the last week too, but it's worked for the last 3 months, but for me, it's with New-AzureRmSqlDatabaseImport. Something seems to have changed recently. Ideally, I'd like to be able to look at a status and wait in my powershell to confirm that the delete was successful before running the import, but I intermittently get a "database already exists" error...

jaredmoo commented 5 years ago

We understand the issue here - it's due to some complicated interactions with ARM resource tracking. Unfortunately the fix is not easy. We are investigating various strategies to improve the reliability of this scenario, but it will take some time. Thanks for your patience.

dannythomas13 commented 5 years ago

I too am getting the same issue, up to last week it was working great. Essentially what I want to do is as part of a staging build, delete existing staging db, take a copy of production db, restore this copy as staging

samsmithnz commented 5 years ago

I ended up writing some PowerShell to loop until the database deletion was resolved. As I run my script in Dev/QA overnight, it wasn't a big deal to let it run for 5-10 minutes for it complete. Happy to share it here.

grankko commented 5 years ago

Same issue here, exact same scenario as @dannythomas13.

John-Blair commented 5 years ago

I got the same issue but with the newer New-AzSqlDatabaseCopy - been working fine for weeks. The command always works fine in CloudShell - the db copy takes approx 1 minute. When run in a release pipeline - it takes ages to fail - approx 10 minutes, when it works it takes approx 3 minutes - no idea why 3 times longer than interactive. Also when it fails, and I check the db has actually been copied successfully.

Can't believe this critical issue has been open for so long - doesn't anyone see the urgency in getting this fixed?

John-Blair commented 5 years ago

FYI I saw this related article https://github.com/microsoft/azure-pipelines-tasks/issues/10085 and it suggested issue was related to resources deleted immediately before the db copy i.e. the target of the copy. So I introduced a Wait 60 seconds task into my pipeline (from the Marketplace) and not seen an error so far since - although as it was intermittent, I can't read too much into the change so far.

jeroenterheerdt commented 4 years ago

@maboja-msft

jepandey commented 4 years ago

This issue is still happening. When fix will be available ?

John-Blair commented 4 years ago

fyi since i introduced my Wait 60 seconds task in my pipeline I have not seen any re-occurrence. Its a workaround rather than a fix.

jepandey commented 4 years ago

fyi since i introduced my Wait 60 seconds task in my pipeline I have not seen any re-occurrence. Its a workaround rather than a fix.

Can you tell me where is option to put my wait in azure power shell tasks in release pipeline

John-Blair commented 4 years ago

Pull the Wait task in from the marketplace, and then add to your release pipeline - task yaml for a 60 second delay is:

steps:

task: deadlydog.WaitBuildAndReleaseTask.Wait.Wait@1 displayName: 'Wait for 60 seconds' inputs: Value: 60

MonkeyTennis commented 4 years ago

I am intermittently also getting this problem. I have a ps1 script called from the AzurePowerShell@4 YAML task that simply does the following:

Remove-AzSqlInstanceDatabase -ResourceGroupName $AzureResourceGroupName -InstanceName $AzureSqlServerResourceName -Name $DatabaseName -Force;

New-AzSqlInstanceDatabase -ResourceGroupName $AzureResourceGroupName -InstanceName $AzureSqlServerResourceName -Name $DatabaseName;

The script intermittently errors out on the New-AzSqlInstanceDatabase command, with an error:

Long running operation failed with status 'NotFound'.

The YAML target ran for 1m 41s on this occasion.

I will try the wait workaround but it is only a workaround.

gstolz commented 4 years ago

I'm not working in this field anymore and cannot retest the original issue. But I would leave this open because of all the other users, so they can track any progress.