No longer able to deploy an Azure Web App because Newtonsoft dll could not be loaded

cloud

(Baffour) #1

Octopus Server version: v2018.7.8
Hi, we deploy some Web Apps to Azure through Octopus using the “Deploy an Azure Web App” step template by Octopus. One Project recently started failing for every Tenant, even with older releases that were deploying successfully, but the other projects deploy fine.
As you can see in the task log the error happens in Octopus.AzureContext.ps1 when the “Login-AzureRmAccount” command is called, and is around it being unable to find a specific version of the NewtonSoft.Json assembly. I may be misunderstanding how Calamari works but I’m under the impression that this command is running on the Octopus Server Node, but when I run Login-AzureRmAccount manually on the machine it works fine so I’m not clear on the context the script is run in.

Any ideas on what the issue could be?
Thanks!

Task Log
Task ID:        ServerTasks-64907
Task status:    Failed
Task queued:    Thursday, September 13, 2018 5:01:36 PM
Task started:   Thursday, September 13, 2018 5:01:36 PM
Task completed: Thursday, September 13, 2018 5:02:06 PM
Task duration:  29 seconds
Server version: 2018.7.8+Branch.master.Sha.7caedf8c767263254aa9f2e8ba3bc8655d46d97f
Server node:    [REDACTED MACHINE NAME]

                    | == Failed: Deploy Identity Server release 0.0.34 to Global for [REDACTED] ==
17:02:06   Info     |   Step 1: Deploy Identity Database - SQL Azure was manually skipped, and will not be executed
17:02:06   Verbose  |   Guided failure is not enabled for this task
17:02:06   Fatal    |   The deployment failed because one or more steps failed. Please see the deployment log for details.
                    | 
                    |   == Success: Acquire packages ==
17:01:37   Info     |     Acquiring packages
17:01:37   Info     |     Making a list of packages to acquire
17:01:37   Verbose  |     No packages are required on any deployment targets
17:01:37   Verbose  |     Acquire [REDACTED WebAppName].Server.1.2.1808.0601 on Octopus Server
17:01:37   Verbose  |     Checking package cache for package [REDACTED WebAppName].Server v1.2.1808.0601
17:01:37   Info     |     Package [REDACTED WebAppName].Server v1.2.1808.0601 was found in cache. No need to download.
17:01:37   Verbose  |     Using file: E:\Octopus\Packages\[REDACTED WebAppName].Server\[REDACTED WebAppName].Server.1.2.1808.0601.nupkg
17:01:37   Info     |     All packages have been acquired
17:01:37   Verbose  |     Acquire Packages completed
                    |   
                    |     Success: Octopus Server
                    |     
                    |       Success: Download package [REDACTED WebAppName].Server v1.2.1808.0601 from Octopus Server (built-in)
17:01:37   Info     |         Successfully downloaded [REDACTED WebAppName].Server 1.2.1808.0601 (2.174 MB)
17:01:37   Verbose  |         Stored package in E:\Octopus\Packages\[REDACTED WebAppName].Server\[REDACTED WebAppName].Server.1.2.1808.0601.nupkg
                    |       
                    |   == Failed: Step 2: Deploy [REDACTED WebAppName] ==
17:02:05   Fatal    |     The step failed: Activity Deploy [REDACTED WebAppName] on Azure Global failed with error 'The remote script failed with exit code 1'.
17:02:05   Verbose  |     Deploy [REDACTED WebAppName] completed
                    |   
                    |     Failed: Octopus Server on behalf of Azure Global
17:01:38   Verbose  |       Octopus Server version: 2018.7.8+Branch.master.Sha.7caedf8c767263254aa9f2e8ba3bc8655d46d97f
17:01:38   Verbose  |       Environment Information:
                    |       OperatingSystem: Microsoft Windows NT 6.3.9600.0
                    |       OsBitVersion: x64
                    |       Is64BitProcess: True
                    |       CurrentUser: NT AUTHORITY\SYSTEM
                    |       MachineName: [REDACTED MACHINE NAME]
                    |       ProcessorCount: 4
                    |       CurrentDirectory: C:\Windows\system32
                    |       TempDirectory: C:\Windows\TEMP\
                    |       HostProcessName: Octopus.Server
                    |       PID: 1600
17:01:38   Verbose  |       Executing Deploy [REDACTED WebAppName] (type Deploy an Azure Web App) on Octopus Server
17:01:38   Verbose  |       Using account ID '[Redacted Azure Service Principal]'
17:01:38   Verbose  |       Using Calamari.Cloud 4.7.34
17:01:38   Verbose  |       Using Octopus.Dependencies.AzureCmdlets 5.7.0
17:01:38   Verbose  |       Running this script as the Octopus Server (NT AUTHORITY\SYSTEM)
17:01:38   Verbose  |       Starting C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe in working directory 'E:\Octopus\Work\20180913160138-64907-134' using 'OEM United States' encoding running as 'NT AUTHORITY\SYSTEM' with the same environment variables as the launching process
17:01:39   Verbose  |       Octopus Deploy: Calamari version 4.7.34
17:01:39   Verbose  |       Environment Information:
17:01:39   Verbose  |       OperatingSystem: Microsoft Windows NT 6.3.9600.0
17:01:39   Verbose  |       OsBitVersion: x64
17:01:39   Verbose  |       Is64BitProcess: True
17:01:39   Verbose  |       CurrentUser: NT AUTHORITY\SYSTEM
17:01:39   Verbose  |       MachineName: [REDACTED MACHINE NAME]
17:01:39   Verbose  |       ProcessorCount: 4
17:01:39   Verbose  |       CurrentDirectory: E:\Octopus\Work\20180913160138-64907-134
17:01:39   Verbose  |       TempDirectory: C:\Windows\TEMP\
17:01:39   Verbose  |       HostProcessName: Calamari
17:01:41   Info     |       Deploying package:    E:\Octopus\Packages\[REDACTED WebAppName].Server\[REDACTED WebAppName].Server.1.2.1808.0601.nupkg
17:01:41   Verbose  |       Extracting package to: E:\Octopus\Work\20180913160138-64907-134\staging
17:01:41   Verbose  |       Extracted 194 files
17:01:41   Verbose  |       Executing 'E:\Octopus\Work\20180913160138-64907-134\staging\Octopus.Action.CustomScripts.PreDeploy.ps1'
17:01:43   Verbose  |       Name                           Value
17:01:43   Verbose  |       ----                           -----
17:01:43   Verbose  |       PSVersion                      5.1.14409.1012
17:01:43   Verbose  |       PSEdition                      Desktop
17:01:43   Verbose  |       PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
17:01:43   Verbose  |       BuildVersion                   10.0.14409.1012
17:01:43   Verbose  |       CLRVersion                     4.0.30319.42000
17:01:43   Verbose  |       WSManStackVersion              3.0
17:01:43   Verbose  |       PSRemotingProtocolVersion      2.3
17:01:43   Verbose  |       SerializationVersion           1.1.0.1
17:01:43   Verbose  |       PowerShell Environment Information:
17:01:43   Verbose  |       OperatingSystem: Microsoft Windows NT 6.3.9600.0
17:01:43   Verbose  |       OsBitVersion: x64
17:01:43   Verbose  |       Is64BitProcess: True
17:01:43   Verbose  |       CurrentUser: NT AUTHORITY\SYSTEM
17:01:43   Verbose  |       MachineName: [REDACTED MACHINE NAME]
17:01:43   Verbose  |       ProcessorCount: 4
17:01:43   Verbose  |       CurrentDirectory: E:\Octopus\Work\20180913160138-64907-134\staging
17:01:43   Verbose  |       CurrentLocation: E:\Octopus\Work\20180913160138-64907-134\staging
17:01:43   Verbose  |       TempDirectory: C:\Windows\TEMP\
17:01:45   Verbose  |       HostProcessName: powershell
17:01:45   Verbose  |       TotalPhysicalMemory: 14679604 KB
17:01:45   Verbose  |       AvailablePhysicalMemory: 11388872 KB
17:01:45   Verbose  |       Authenticating with Service Principal
17:01:45   Verbose  |       Attempt 1 of 5 failed: Could not load file or assembly 'Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed' or one of its dependencies. The system cannot find the file specified.
17:01:45   Verbose  |       Waiting for 5 seconds before retrying...
17:01:50   Verbose  |       Retrying...
17:01:50   Verbose  |       Authenticating with Service Principal
17:01:50   Verbose  |       Attempt 2 of 5 failed: Could not load file or assembly 'Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed' or one of its dependencies. The system cannot find the file specified.
17:01:50   Verbose  |       Waiting for 5 seconds before retrying...
17:01:55   Verbose  |       Retrying...
17:01:55   Verbose  |       Authenticating with Service Principal
17:01:55   Verbose  |       Attempt 3 of 5 failed: Could not load file or assembly 'Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed' or one of its dependencies. The system cannot find the file specified.
17:01:55   Verbose  |       Waiting for 5 seconds before retrying...
17:02:00   Verbose  |       Retrying...
17:02:00   Verbose  |       Authenticating with Service Principal
17:02:00   Verbose  |       Attempt 4 of 5 failed: Could not load file or assembly 'Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed' or one of its dependencies. The system cannot find the file specified.
17:02:00   Verbose  |       Waiting for 5 seconds before retrying...
17:02:05   Verbose  |       Retrying...
17:02:05   Verbose  |       Authenticating with Service Principal
17:02:05   Error    |       Login-AzureRmAccount : Could not load file or assembly 'Newtonsoft.Json,
17:02:05   Error    |       Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed' or one of
17:02:05   Error    |       its dependencies. The system cannot find the file specified.
17:02:05   Error    |       At
17:02:05   Error    |       E:\Octopus\Work\20180913160138-64907-134\staging\Octopus.AzureContext.ps1:72
17:02:05   Error    |       char:9
17:02:05   Error    |       +         Login-AzureRmAccount -Credential $creds -TenantId $OctopusAzu ...
17:02:05   Error    |       +         ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
17:02:05   Error    |       + CategoryInfo          : NotSpecified: (:) [Connect-AzureRmAccount], File
17:02:05   Error    |       NotFoundException
17:02:05   Error    |       + FullyQualifiedErrorId : System.IO.FileNotFoundException,Microsoft.Azure.
17:02:05   Error    |       Commands.Profile.ConnectAzureRmAccountCommand
17:02:05   Error    |       PreDeploy script returned non-zero exit code: 1
17:02:05   Error    |       Running rollback conventions...
17:02:05   Error    |       PreDeploy script returned non-zero exit code: 1
17:02:05   Verbose  |       Process C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe in E:\Octopus\Work\20180913160138-64907-134 exited with code 1
17:02:05   Verbose  |       Updating manifest with output variables
17:02:05   Verbose  |       Updating manifest with action evaluated variables
17:02:05   Fatal    |       The remote script failed with exit code 1
17:02:05   Fatal    |       The action Deploy [REDACTED WebAppName] on Azure Global failed
                    |     
                    |   Canceled: Step 3: Approve
17:02:05   Verbose  |     Step "Approve" runs only when all previous steps succeeded; skipping
                    |   
                    |   Canceled: Step 4: Swap Slots
17:02:05   Verbose  |     Step "Swap Slots" runs only when all previous steps succeeded; skipping
                    |   

(John Simons) #2

Hi,

Trying to figure out how to reproduce this issue locally, so I have a few questions.

Because you say that

but when I run Login-AzureRmAccount manually on the machine

I assume you have Azure Powershell Cmdlets installed locally ? And if so what version do you have installed ?

Octopus ships it’s own version of the Powershell Cmdlets but if you do have the cmdlets installed locally, you can disable this to force using the locally installed ones, to do this follow https://octopus.com/docs/deployment-examples/azure-deployments/running-azure-powershell/configuring-the-version-of-the-azure-powershell-modules#ConfiguringtheversionoftheAzurePowerShellmodules-Octopus2018.5.5(ornewer)
Let me know if this fix the issue ?

Another more technical way to figure out what is trying to load this version of Newtonsoft.Json, is by enabling the fusion logs, see https://stackoverflow.com/a/1527249/90882, this should create log files that should tell us what locations are being searched.
But before going down this path, try disabling the Octopus shipped cmdlets.

Regards
John


(Baffour) #3

Thanks for the reply John,
I believe it’s 5.1.2 but for completeness, this is the full list of Azure related modules installed on the server:

Azure Modules
Name Version
Azure 5.1.2
Azure.AnalysisServices 0.5.3
Azure.AnalysisServices 0.5.0
Azure.Storage 4.4.0
Azure.Storage 4.2.1
AzureRM 6.6.0
AzureRM 5.7.0
AzureRM.AnalysisServices 0.6.11
AzureRM.AnalysisServices 0.6.6
AzureRM.ApiManagement 6.1.2
AzureRM.ApiManagement 5.1.2
AzureRM.ApplicationInsights 0.1.5
AzureRM.ApplicationInsights 0.1.3
AzureRM.Automation 5.0.3
AzureRM.Automation 4.3.2
AzureRM.Backup 4.0.7
AzureRM.Backup 4.0.4
AzureRM.Batch 4.1.2
AzureRM.Batch 4.0.6
AzureRM.Billing 0.14.4
AzureRM.Billing 0.14.1
AzureRM.Cdn 5.0.2
AzureRM.Cdn 4.2.2
AzureRM.CognitiveServices 0.9.7
AzureRM.CognitiveServices 0.9.4
AzureRM.Compute 5.4.0
AzureRM.Compute 4.6.0
AzureRM.Consumption 0.3.6
AzureRM.Consumption 0.3.1
AzureRM.ContainerInstance 0.2.7
AzureRM.ContainerInstance 0.2.5
AzureRM.ContainerRegistry 1.0.7
AzureRM.ContainerRegistry 1.0.4
AzureRM.DataFactories 5.0.2
AzureRM.DataFactories 4.2.2
AzureRM.DataFactoryV2 0.5.7
AzureRM.DataFactoryV2 0.5.3
AzureRM.DataLakeAnalytics 5.1.1
AzureRM.DataLakeAnalytics 4.2.3
AzureRM.DataLakeStore 6.1.1
AzureRM.DataLakeStore 5.2.0
AzureRM.DevTestLabs 4.0.6
AzureRM.DevTestLabs 4.0.4
AzureRM.Dns 5.0.1
AzureRM.Dns 4.1.2
AzureRM.EventGrid 0.3.6
AzureRM.EventGrid 0.3.2
AzureRM.EventHub 0.6.7
AzureRM.EventHub 0.6.3
AzureRM.HDInsight 4.1.5
AzureRM.HDInsight 4.1.2
AzureRM.Insights 5.1.0
AzureRM.Insights 4.0.4
AzureRM.IotHub 3.1.5
AzureRM.IotHub 3.1.2
AzureRM.KeyVault 5.1.0
AzureRM.KeyVault 4.3.0
AzureRM.LogicApp 4.1.1
AzureRM.LogicApp 4.0.3
AzureRM.MachineLearning 0.18.2
AzureRM.MachineLearning 0.17.2
AzureRM.MachineLearningCompute 0.4.5
AzureRM.MachineLearningCompute 0.4.2
AzureRM.MarketplaceOrdering 0.2.4
AzureRM.MarketplaceOrdering 0.2.1
AzureRM.Media 0.10.1
AzureRM.Media 0.9.2
AzureRM.Network 6.4.1
AzureRM.Network 5.4.2
AzureRM.NotificationHubs 5.0.2
AzureRM.NotificationHubs 4.1.1
AzureRM.OperationalInsights 5.0.3
AzureRM.OperationalInsights 4.3.2
AzureRM.PolicyInsights 1.0.3
AzureRM.PowerBIEmbedded 4.1.7
AzureRM.PowerBIEmbedded 4.1.4
AzureRM.profile 5.3.4
AzureRM.profile 4.6.0
AzureRM.RecoveryServices 4.1.5
AzureRM.RecoveryServices 4.1.2
AzureRM.RecoveryServices.Backup 4.3.1
AzureRM.RecoveryServices.Backup 4.1.2
AzureRM.RecoveryServices.SiteRecovery 0.2.7
AzureRM.RecoveryServices.SiteRecovery 0.2.4
AzureRM.RedisCache 5.0.2
AzureRM.RedisCache 4.1.2
AzureRM.Relay 0.3.7
AzureRM.Relay 0.3.3
AzureRM.Resources 6.3.0
AzureRM.Resources 5.5.2
AzureRM.Scheduler 0.16.7
AzureRM.Scheduler 0.16.3
AzureRM.ServerManagement 4.1.2
AzureRM.ServiceBus 0.6.8
AzureRM.ServiceBus 0.6.4
AzureRM.ServiceFabric 0.3.9
AzureRM.ServiceFabric 0.3.4
AzureRM.SiteRecovery 5.0.6
AzureRM.Sql 4.11.0
AzureRM.Sql 4.4.0
AzureRM.Storage 5.0.1
AzureRM.Storage 4.2.3
AzureRM.StreamAnalytics 4.0.7
AzureRM.StreamAnalytics 4.0.4
AzureRM.Tags 4.0.4
AzureRM.Tags 4.0.1
AzureRM.TrafficManager 4.0.8
AzureRM.TrafficManager 4.0.3
AzureRM.UsageAggregates 4.0.4
AzureRM.UsageAggregates 4.0.2
AzureRM.Websites 5.0.6
AzureRM.Websites 4.2.2
AzureRmStorageTable 1.0.0.22

I’ve just tried enabling the OctopusUseBundledAzureModules variable as suggested but this hasn’t fixed the issue.

I also went ahead and tried enabling the fusion logs and re-deploying, and I see logs for Octopus.Server.exe, Tentacle.exe and Calamari.exe, each of which successfully loads the dll from the executable directory. However an attempt is made to load it by powershell.exe which fails, the log for that is below:

Fusion Log for powershell.exe loading Newtonsoft.Json
<meta http-equiv="Content-Type" content="charset=unicode-1-1-utf-8"><!-- saved from url=(0015)assemblybinder: --><html><pre>
*** Assembly Binder Log Entry  (9/17/2018 @ 1:29:34 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: DisplayName = Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
(Fully-specified)
LOG: Appbase = file:///C:/Windows/System32/WindowsPowerShell/v1.0/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = PowerShell.exe
Calling assembly : Microsoft.Rest.ClientRuntime.Azure, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Post-policy reference: Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
LOG: GAC Lookup was unsuccessful.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json.EXE.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json/Newtonsoft.Json.EXE.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json.EXE.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json/Newtonsoft.Json.EXE.
LOG: All probing URLs attempted and failed.

</pre></html><meta http-equiv="Content-Type" content="charset=unicode-1-1-utf-8"><!-- saved from url=(0015)assemblybinder: --><html><pre>
*** Assembly Binder Log Entry  (9/17/2018 @ 1:29:34 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: DisplayName = Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
(Fully-specified)
LOG: Appbase = file:///C:/Windows/System32/WindowsPowerShell/v1.0/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = PowerShell.exe
Calling assembly : Microsoft.Rest.ClientRuntime.Azure, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Post-policy reference: Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
LOG: GAC Lookup was unsuccessful.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json.EXE.
LOG: Attempting download of new URL file:///C:/Windows/System32/WindowsPowerShell/v1.0/Newtonsoft.Json/Newtonsoft.Json.EXE.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json/Newtonsoft.Json.DLL.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json.EXE.
LOG: Attempting download of new URL file:///E:/Octopus/Work/20180917122922-65287-1/staging/Newtonsoft.Json/Newtonsoft.Json.EXE.
LOG: All probing URLs attempted and failed.

</pre></html><meta http-equiv="Content-Type" content="charset=unicode-1-1-utf-8"><!-- saved from url=(0015)assemblybinder: --><html><pre>
*** Assembly Binder Log Entry  (9/17/2018 @ 1:29:39 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: DisplayName = Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
(Fully-specified)
LOG: Appbase = file:///C:/Windows/System32/WindowsPowerShell/v1.0/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = PowerShell.exe
Calling assembly : Microsoft.Rest.ClientRuntime.Azure, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Post-policy reference: Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
LOG: The same bind was seen before, and was failed with hr = 0x80070002.
ERR: Unrecoverable error occurred during pre-download check (hr = 0x80070002).

</pre></html><meta http-equiv="Content-Type" content="charset=unicode-1-1-utf-8"><!-- saved from url=(0015)assemblybinder: --><html><pre>
*** Assembly Binder Log Entry  (9/17/2018 @ 1:29:44 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: DisplayName = Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
(Fully-specified)
LOG: Appbase = file:///C:/Windows/System32/WindowsPowerShell/v1.0/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = PowerShell.exe
Calling assembly : Microsoft.Rest.ClientRuntime.Azure, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Post-policy reference: Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
LOG: The same bind was seen before, and was failed with hr = 0x80070002.
ERR: Unrecoverable error occurred during pre-download check (hr = 0x80070002).

</pre></html><meta http-equiv="Content-Type" content="charset=unicode-1-1-utf-8"><!-- saved from url=(0015)assemblybinder: --><html><pre>
*** Assembly Binder Log Entry  (9/17/2018 @ 1:29:49 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: DisplayName = Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
(Fully-specified)
LOG: Appbase = file:///C:/Windows/System32/WindowsPowerShell/v1.0/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = PowerShell.exe
Calling assembly : Microsoft.Rest.ClientRuntime.Azure, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Post-policy reference: Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
LOG: The same bind was seen before, and was failed with hr = 0x80070002.
ERR: Unrecoverable error occurred during pre-download check (hr = 0x80070002).

</pre></html><meta http-equiv="Content-Type" content="charset=unicode-1-1-utf-8"><!-- saved from url=(0015)assemblybinder: --><html><pre>
*** Assembly Binder Log Entry  (9/17/2018 @ 1:29:54 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Windows\system32\WindowsPowershell\v1.0\PowerShell.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: DisplayName = Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
(Fully-specified)
LOG: Appbase = file:///C:/Windows/System32/WindowsPowerShell/v1.0/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = PowerShell.exe
Calling assembly : Microsoft.Rest.ClientRuntime.Azure, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35.
===
LOG: This bind starts in LoadFrom load context.
WRN: Native image will not be probed in LoadFrom context. Native image will only be probed in default load context, like with Assembly.Load().
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Post-policy reference: Newtonsoft.Json, Version=9.0.0.0, Culture=neutral, PublicKeyToken=30ad4fe6b2a6aeed
LOG: The same bind was seen before, and was failed with hr = 0x80070002.
ERR: Unrecoverable error occurred during pre-download check (hr = 0x80070002).

</pre></html>

Hope that helps. What’s the expected behaviour here? should the dll be in E:/Octopus/Work/20180917122922-65287-1/staging?

Thanks again John!


(John Simons) #4

Hi,

Thanks heaps for all the information you have provided so far. We have been trying to replicate the issue you are seeing, we installed both 6.6.0 and 5.7.0 Azure Powershell modules but still cannot reproduce the issue.

Just to be sure, when you created the OctopusUseBundledAzureModules variable, you set it to False correct ?

should the dll be in E:/Octopus/Work/20180917122922-65287-1/staging ?

No it should not, we are calling the Login-AzureRmAccount and that PS command references the missing DLL, but that dependency should be there, actually the bundle we ship, does not reference v9.0.0 of Newtonsoft.Json, which really does not make sense!

You don’t have Newtonsoft.Json in the GAC ?

We can try to debug the PS script and see if we can figure out what is going on then, to enable script debugging you need to follow - https://octopus.com/docs/deployment-examples/custom-scripts/debugging-powershell-scripts, once you are debugging, try running Get-Module -ListAvailable -Name Azure* -Verbose, this hopefully should show the paths where the PS modules are being executed from.

If you have problems running it in debug, we can jump on a call to help out.

Regards
John


(Baffour) #5

Managed to get to the bottom of this eventually! We reinstalled Octopus on a fresh VM, which we had been looking to do anyway. This then gave me a similar error, except it was about System.Net.Http v4.1.1.0, when the Get-AzureRmEnvironment command is called. I was then told that this was the original failure we were getting until someone else in my team tried to fix it by tinkering with the VM, and eventually got the Newtonsoft error.

Investigated the dependencies using a .NET dependency viewer. So the problem was that our Application had a dependency on the Nuget package Microsoft.Azure.KeyVault v3.0.0. This depends on Microsoft.Rest.ClientRuntime.dll (AssemblyFileVersion v2.3.11.0) and Microsoft.Rest.ClientRuntime.Azure.dll (AssemblyFileVersion v3.3.12.0) targeting .NETStandard v.1.4 so they are included in the output folder when we publish, and therefore the nuget package, and then the staging folder. AzureRM.profile depends on the same two dlls, with the same versioning, but targeting .NET Framework v4.5.2. Each has a dependency on System.Net.Http but the versions that come with the cmdlets depend on v4.0.0.0 which is in the GAC, whilst the version in our staging folder depends on v4.1.1.0.
Therefore when the Octopus deployment script calls Get-AzureRmEnvironment, it picks up Microsoft.Rest.ClientRuntime dll from the staging folder, instead of the version from the cmdlets, and then fails to resolve that version of System.Net.Http. I managed to reproduce this simply by opening a powershell window in the staging folder and calling that command.

Luckily for us we’re not actually using the KeyVault package anymore, the dependency was just left in our project, so were able to just remove it.

What would be the fix if we couldn’t? Should Octopus be running its deployment script from another working directory to avoid the clashing with the web app’s dependencies? Would you class this as a bug in Octopus or something Microsoft needs to look at?


(Ben Pearce) #6

Hi Baffour,

Thanks for the information, I have been able to recreate the issue you are experiencing.
We have an issue for this now, that you can monitor for a fix. Feel free to add additional information to this issue that you feel is relevant.

Regards
Ben