Windows Habitat Service Issue w/Permissions

Hey all, question for you guys.

Currently what I’m trying to do is create a Terraform script that handles loading a few plans in a Windows EC2 instance, namely core/sqlserver and a Proget package I’ve made myself. The inline commands are being called using winrm which was a part of the permission issues I was experiencing when trying to just load the core/sqlserver package via remote-exec in Terraform. This led me to using the Habitat Windows service which handles the core/sqlserver package just fine.

The problem with doing this was that the Proget package, while it works fine when loading the service when RDP’d in to the machine itself, it does not work properly when loading via the Windows Service and errors out in finding libraries that should be available to it. What I was wondering was if the Habitat Windows Service has a different set of permissions versus just loading a plan on a regular supervisor and if there was a workaround to getting the same set of permissions as a regular hab sup run.

Whoa this sounds like a super bizarre problem. Ok, so, I could use a little more context, first, are you using the habitat terraform module or only the remote exec module? Second, is - the Proget package, is this a habitat package specifically or something else? I am guessing Proget IS a hab package but I just want to make sure. So what you’re seeing is if you run hab svc load origin/proget while RDP’d to the node it all works, but if you try to use Proget via a windows service that’s when it dies?

Would you be able to share any of the log output from the failed run in the Windows Service? I personally don’t know if there are any permissions differences between the two - but- I know something better: I know who WOULD know :joy:. I’m gonna tap @mwrock on his monumental MS Hero shoulder on this one and see if he can drop some knowledge for us.

Hey again @eeyun, so yeah the Proget package is a habitat package. Your second statement is also correct, if I load it while RDP’d it works perfect but if it’s loaded while the Habitat Windows Service is running it dies when looking for a specific library. Logs are as follows. As you can see, it gives the Unhandled Exception: System.IO.FileNotFoundException: Could not load file or assembly 'InedoLib, Version=1000.0.0.0, Culture=neutral issue even though this isn’t a problem in a normal hab sup run.

2018-08-29 16:00:34,951 - Habitat windows service is starting launcher at: C:\hab\pkgs\core\hab-launcher\8150\20180813121640\bin\hab-launch.exe
2018-08-29 16:00:34,982 - Habitat windows service is starting launcher with args: run --no-color
2018-08-29 16:00:35,091 - hab-sup(MR): Supervisor Member-ID 2d55aa4cd9e643ec83145e0e11fed92a
2018-08-29 16:00:35,091 - hab-sup(MR): Starting gossip-listener on 0.0.0.0:9638
2018-08-29 16:00:35,138 - hab-sup(MR): Starting ctl-gateway on 127.0.0.1:9632
2018-08-29 16:00:35,138 - hab-sup(MR): Starting http-gateway on 0.0.0.0:9631
2018-08-29 16:00:35,748 - hab-sup(AG): » Installing core/sqlserver
2018-08-29 16:00:35,748 - hab-sup(AG): ☁ Determining latest version of core/sqlserver in the 'stable' channel
2018-08-29 16:00:35,779 - hab-sup(AG): ↓ Downloading core/sqlserver/14.0.1000/20180525091436
2018-08-29 16:00:44,953 - hab-sup(AG): ☛ Verifying core/sqlserver/14.0.1000/20180525091436
2018-08-29 16:00:46,968 - hab-sup(AG): ↓ Downloading core/dsc-core/0.1.0/20180406122924
2018-08-29 16:00:46,968 - hab-sup(AG): ☛ Verifying core/dsc-core/0.1.0/20180406122924
2018-08-29 16:00:47,000 - hab-sup(AG): ✓ Installed core/dsc-core/0.1.0/20180406122924
2018-08-29 16:00:53,328 - hab-sup(AG): ✓ Installed core/sqlserver/14.0.1000/20180525091436
2018-08-29 16:00:53,328 - hab-sup(AG): ★ Install of core/sqlserver/14.0.1000/20180525091436 complete with 2 new packages installed.
2018-08-29 16:00:53,344 - hab-sup(AG): The core/sqlserver service was successfully loaded
2018-08-29 16:00:55,407 - hab-sup(MR): Starting core/sqlserver
2018-08-29 16:00:55,422 - sqlserver.default(UCW): Watching user.toml
2018-08-29 16:00:55,454 - sqlserver.default(HK): init, compiled to C:\hab\svc\sqlserver\hooks\init
2018-08-29 16:00:55,469 - sqlserver.default(HK): run, compiled to C:\hab\svc\sqlserver\hooks\run
2018-08-29 16:00:55,469 - sqlserver.default(HK): post-run, compiled to C:\hab\svc\sqlserver\hooks\post-run
2018-08-29 16:00:55,485 - sqlserver.default(HK): post-stop, compiled to C:\hab\svc\sqlserver\hooks\post-stop
2018-08-29 16:00:55,485 - sqlserver.default(HK): Hooks compiled
2018-08-29 16:00:55,485 - sqlserver.default(SR): Hooks recompiled
2018-08-29 16:00:55,485 - default(CF): Updated firewall.ps1 9cbfb15707757682660d5f0f5664f1f7b11c664bd0c04d111874ba8926349b1a
2018-08-29 16:00:55,485 - default(CF): Updated windows_login.sql bc09e3581c03fa8f83dacbf370ecf2ba920cf566d06d48508a709cf02437411b
2018-08-29 16:00:55,500 - default(CF): Updated sql_login.sql 59d2fd3bc1aa97faf66d76832320940311aedc9bf5b2e78067990d3c96a60fdd
2018-08-29 16:00:55,500 - default(CF): Updated config.ini c6607a426fddd30bde3cbdfc65f9f2fc68fffcd23b5f711b124ce331ccc7cf85
2018-08-29 16:00:55,500 - sqlserver.default(SR): Configuration recompiled
2018-08-29 16:00:55,500 - sqlserver.default(SR): Initializing
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): Microsoft .NET Framework CasPol 4.7.2053.0
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): for Microsoft .NET Framework version 4.7.2053.0
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): Copyright (C) Microsoft Corporation.  All rights reserved.
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): WARNING: The .NET Framework does not apply CAS policy by default. Any settings 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): shown or modified by CasPol will only affect applications that opt into using 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): CAS policy. 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): Please see http://go.microsoft.com/fwlink/?LinkId=131738 for more information. 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:00:57,188 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:00:57,579 - sqlserver.default hook[init]:(HK): Success
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): Microsoft .NET Framework CasPol 4.7.2053.0
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): for Microsoft .NET Framework version 4.7.2053.0
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): Copyright (C) Microsoft Corporation.  All rights reserved.
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): WARNING: The .NET Framework does not apply CAS policy by default. Any settings 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): shown or modified by CasPol will only affect applications that opt into using 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): CAS policy. 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): Please see http://go.microsoft.com/fwlink/?LinkId=131738 for more information. 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:01:00,938 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:01:02,360 - sqlserver.default hook[init]:(HK): Success
2018-08-29 16:01:03,329 - sqlserver.default hook[init]:(HK): SQL Server 2017 transmits information about your installation experience, as well as other usage and performance data, to Microsoft to help improve the product. To learn more about SQL Server 2017 data processing and privacy controls, please see the Privacy Statement.
2018-08-29 16:03:53,842 - sqlserver.default hook[init]:(HK): Microsoft (R) SQL Server 2017 14.00.1000.169
2018-08-29 16:03:53,842 - sqlserver.default hook[init]:(HK): Copyright (c) 2017 Microsoft.  All rights reserved.
2018-08-29 16:03:53,842 - sqlserver.default hook[init]:(HK): 
2018-08-29 16:03:55,561 - sqlserver.default hook[init]:(HK): Checking for xNetworking PS module...
2018-08-29 16:03:55,561 - sqlserver.default hook[init]:(HK): Checking for nuget package provider...
2018-08-29 16:04:12,765 - sqlserver.default hook[init]:(HK): Installing Nuget provider...
2018-08-29 16:04:18,187 - sqlserver.default hook[init]:(HK): Checking for xNetworking PS module...
2018-08-29 16:04:18,187 - sqlserver.default hook[init]:(HK): Installing xNetworking PS Module...
2018-08-29 16:04:23,265 - sqlserver.default hook[init]:(HK): Compiling DSC mof for NewFirewallRule ...
2018-08-29 16:04:26,515 - sqlserver.default hook[init]:(HK): Applying DSC configuration for C:\hab\svc\sqlserver\config\firewall.ps1 ...
2018-08-29 16:04:30,312 - sqlserver.default(SV): Starting service as user=ec2amaz-0g884gr$, group=<anonymous>
2018-08-29 16:04:31,281 - sqlserver.default hook[post-run]:(HK): waiting for sql server to start accepting connections...
2018-08-29 16:04:32,156 - sqlserver.default(O): sqlserver is running
2018-08-29 16:04:34,406 - sqlserver.default hook[post-run]:(HK): Starting application user setup...
2018-08-29 16:04:34,609 - sqlserver.default hook[post-run]:(HK): 1> 2> 3> 4> 5> 6> Application user setup complete
2018-08-29 16:04:34,687 - hab-sup(AG): » Installing bluepipeline/proget
2018-08-29 16:04:34,687 - hab-sup(AG): ☁ Determining latest version of bluepipeline/proget in the 'unstable' channel
2018-08-29 16:04:34,718 - hab-sup(AG): ↓ Downloading bluepipeline/proget/5.1.4/20180827180834
2018-08-29 16:04:35,296 - hab-sup(AG): ☛ Verifying bluepipeline/proget/5.1.4/20180827180834
2018-08-29 16:04:38,937 - hab-sup(AG): ✓ Installed bluepipeline/proget/5.1.4/20180827180834
2018-08-29 16:04:38,937 - hab-sup(AG): ★ Install of bluepipeline/proget/5.1.4/20180827180834 complete with 1 new packages installed.
2018-08-29 16:04:38,952 - hab-sup(AG): The bluepipeline/proget service was successfully loaded
2018-08-29 16:04:41,015 - hab-sup(MR): Starting bluepipeline/proget
2018-08-29 16:04:41,015 - proget.default(UCW): Watching user.toml
2018-08-29 16:04:41,062 - sqlserver.default(HK): Hooks compiled
2018-08-29 16:04:41,062 - default(CF): Updated config.ini c6607a426fddd30bde3cbdfc65f9f2fc68fffcd23b5f711b124ce331ccc7cf85
2018-08-29 16:04:41,062 - sqlserver.default(SR): Configuration recompiled
2018-08-29 16:04:41,812 - sqlserver.default(O): sqlserver stopping...
2018-08-29 16:04:42,624 - sqlserver.default(O): sqlserver has stopped
2018-08-29 16:04:42,671 - proget.default(SR): The group 'sqlserver.default' satisfies the `database` bind
2018-08-29 16:04:42,671 - proget.default(SR): The group 'sqlserver.default' satisfies the `database` bind
2018-08-29 16:04:42,687 - proget.default(HK): init, compiled to C:\hab\svc\proget\hooks\init
2018-08-29 16:04:42,687 - proget.default(HK): run, compiled to C:\hab\svc\proget\hooks\run
2018-08-29 16:04:42,687 - proget.default(HK): Hooks compiled
2018-08-29 16:04:42,687 - proget.default(SR): Hooks recompiled
2018-08-29 16:04:42,687 - default(CF): Updated ProGet.config 99a86236dd6c702c08ad5b9ae218d25306bfb897601a407ff372a3c18fc15bff
2018-08-29 16:04:42,702 - proget.default(SR): Configuration recompiled
2018-08-29 16:04:42,702 - proget.default(SR): Initializing
2018-08-29 16:04:43,827 - proget.default hook[init]:(HK): Copying ProGet to C:\ProGet
2018-08-29 16:04:45,109 - sqlserver.default(O): sqlserver is running
2018-08-29 16:04:46,484 - proget.default hook[init]:(HK): Creating Database (if nessecary).
2018-08-29 16:04:46,905 - proget.default hook[init]:(HK): Running ProGet DB scripts.
2018-08-29 16:04:47,171 - proget.default hook[init]:(HK): Database is not initialized; initializing...
2018-08-29 16:04:47,218 - proget.default hook[init]:(HK): Database initialized.
2018-08-29 16:04:47,374 - proget.default hook[init]:(HK): Rule bound to data type.
2018-08-29 16:04:47,374 - proget.default hook[init]:(HK): The new rule has been bound to column(s) of the specified user data type.
2018-08-29 16:04:51,530 - proget.default hook[init]:(HK): Configuring ProGet DB connection.
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): 
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): 
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK):     Directory: C:\ProgramData\Inedo
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): 
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): 
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): Mode                LastWriteTime         Length Name                          
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): ----                -------------         ------ ----                          
2018-08-29 16:04:51,577 - proget.default hook[init]:(HK): d-----        8/29/2018   4:04 PM                SharedConfig                  
2018-08-29 16:04:51,593 - proget.default hook[init]:(HK): 
2018-08-29 16:04:51,593 - proget.default hook[init]:(HK): 
2018-08-29 16:04:51,609 - proget.default(SV): Starting service as user=ec2amaz-0g884gr$, group=<anonymous>
2018-08-29 16:04:52,687 - proget.default(O): Attempting to use shared configuration for ProGet.
2018-08-29 16:04:52,702 - proget.default(O): Shared configuration file loaded from C:\ProgramData\Inedo\SharedConfig\ProGet.config.
2018-08-29 16:04:52,780 - proget.default(O): No encryption key is configured. Credentials will be stored in plain text.
2018-08-29 16:04:52,843 - proget.default(O): Starting the messenger...
2018-08-29 16:04:52,890 - proget.default(O): Messenger endpoint is pipe://INEDOPROGETSVC-ctrl
2018-08-29 16:04:55,171 - proget.default(O): Reading standard license list...
2018-08-29 16:04:55,171 - proget.default(O): Importing license list into database...
2018-08-29 16:04:56,062 - proget.default(O): License import complete.
2018-08-29 16:04:56,077 - proget.default(O): Initializing Scheduled Job Dispatcher...
2018-08-29 16:04:56,077 - proget.default(O): Scheduled Job Dispatcher initialized.
2018-08-29 16:04:56,077 - proget.default(O): Running Scheduled Job Dispatcher...
2018-08-29 16:04:56,093 - proget.default(O): Checking for scheduled jobs...
2018-08-29 16:04:56,108 - proget.default(O): Ensuring that all required scheduled jobs are configured...
2018-08-29 16:04:56,155 - proget.default(O): Creating missing ExecutionLogRetention task...
2018-08-29 16:04:56,171 - proget.default(O): Creating missing VulnerabilityDownloader task...
2018-08-29 16:04:56,171 - proget.default(O): Scheduled jobs updated.
2018-08-29 16:04:56,265 - proget.default(O): Scheduled Job Dispatcher completed.
2018-08-29 16:04:57,765 - proget.default(E): 
2018-08-29 16:04:57,765 - proget.default(E): Unhandled Exception: System.IO.FileNotFoundException: Could not load file or assembly 'InedoLib, Version=1000.0.0.0, Culture=neutral, PublicKeyToken=112cfb71329714a6' or one of its dependencies. The system cannot find the file specified.
2018-08-29 16:04:57,765 - proget.default(E):    at System.RuntimeTypeHandle.GetTypeByName(String name, Boolean throwOnError, Boolean ignoreCase, Boolean reflectionOnly, StackCrawlMarkHandle stackMark, IntPtr pPrivHostBinder, Boolean loadTypeFromPartialName, ObjectHandleOnStack type)
2018-08-29 16:04:57,765 - proget.default(E):    at System.RuntimeTypeHandle.GetTypeByName(String name, Boolean throwOnError, Boolean ignoreCase, Boolean reflectionOnly, StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean loadTypeFromPartialName)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Type.GetType(String typeName, Boolean throwOnError)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Web.Hosting.HostingEnvironment.CreateInstance(String assemblyQualifiedName)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Web.Hosting.HostingEnvironment.CreateInstance(String assemblyQualifiedName)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Web.Hosting.ApplicationHost.CreateApplicationHost(Type hostType, String virtualDir, String physicalDir)
2018-08-29 16:04:57,765 - proget.default(E):    at Inedo.Web.Server.IntegratedServer.ProcessRequests()
2018-08-29 16:04:57,765 - proget.default(E):    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
2018-08-29 16:04:57,765 - proget.default(E):    at System.Threading.ThreadHelper.ThreadStart()
2018-08-29 16:04:58,577 - hab-launch(SV): Child for service 'proget.default' with PID 3192 exited with code exit code: 0
2018-08-29 16:04:58,890 - proget.default(SV): Starting service as user=ec2amaz-0g884gr$, group=<anonymous>
2018-08-29 16:04:59,733 - proget.default(O): Attempting to use shared configuration for ProGet.
2018-08-29 16:04:59,733 - proget.default(O): Shared configuration file loaded from C:\ProgramData\Inedo\SharedConfig\ProGet.config.
2018-08-29 16:04:59,733 - proget.default(O): No encryption key is configured. Credentials will be stored in plain text.
2018-08-29 16:04:59,780 - proget.default(O): Starting the messenger...
2018-08-29 16:04:59,780 - proget.default(O): Messenger endpoint is pipe://INEDOPROGETSVC-ctrl
2018-08-29 16:04:59,827 - proget.default(O): Reading standard license list...
2018-08-29 16:04:59,827 - proget.default(O): Importing license list into database...
``

Interesting. The key difference between running hab sup run interactively and via a windows service is that the windows service runs under the local SYSTEM account by default. Now that user should have pretty majestic permissions but you could try changing the service logon to your own creds just to see if that is the issue.

I’m guessing it is looking for a file called InedoLib.dll. You might check to see if that file exists on disk and where. Looks like it is a .net assembly so it could possibly be in the GAC but I’d look in the same directory as the proget binary your run hook calls.

Also, sometimes processmonitor is helpful in debugging these scenarios. You can have it filter all file activity from the running process and a path that ends in inedolib.dll and see where it is looking and failing to find it.

2 Likes

Hey Matt, thanks for the help! I’ll give what you suggested a shot and see where I can get. IndeloLib.dll does indeed exist as evident by the fact that hab sup run is able to find it. It’s located in the directory where the files are (C:\ProGet). I’ll give what you mentioned a shot though and see where I get.

Is that the same directory of the proget binary you invoke in the run hook?

Yes.

Where cfg.config.install_dir is C:\Proget

$dir = "{{cfg.config.install_dir}}\Service" 

if(Test-Path $dir ) {
  cd $dir
  ./ProGet.Service.exe run
}

is the dll in c:\proget of c:\proget\service? I think procmon will be a good tool to help drill in here.

Yes and sure I'll take a poke at it and see where I can get!

Hey @mwrock. How exactly would you go about modifying the service login credentials. Currently trying to change it to my own credentials but I’m looking at the config and the habitat.ps1 file but found nothing involving setting credentials. Any ideas? As a clarifying question did you mean change the service credentials using a separate Powershell script or using a configuration in the service itself.

The easiest way is to right click on the habitat service in the Windows service manager and select properties. Then go to the login tab and enter your credentials.

Hmm. Seems that changing the credentials to what’s normally used when RDP’d in does nothing, the error remains oddly enough. I’m going to give procmon a shot.

So upon looking into it with Procmon, it’s definitely looking in the GAC like you said but there’s no reason it should be, the libraries it needs are all in the same directory as the exe that’s being run. Even when changing the credentials it looks into that directory where it doesn’t exist. Not sure why this would happen especially when a local run has it working fine.

The GAC has the highest precedence and that is where the runtime will look first. Do you see it probing other directories after the GAC directories? There are various entries in the exe.config file that could potentially affect where the process probes for assemblies. See https://docs.microsoft.com/en-us/dotnet/framework/deployment/how-the-runtime-locates-assemblies for a run down of the probing logic. By the way, is this proget binary the same one you get from the Inedo Hub: ProGetInstaller.exe?

The binaries are from the manual installation packages.

https://inedo.com/support/documentation/proget/installation/installation-guide/manual
https://inedo.com/proget/download/manual/5.1.4

I can see what you mean by the process potentially probing the wrong places for assemblies, I’ll see if it’s possible to point it to looking in a local directory.

I was super curious and downloaded the proget binaries and extracted them to c:\proget. I also ran the database updater to initialize sql. This seems to run perfectly for me inside the Habitat windows service. My actual package just has a run hook containing:

c:\proget\proget.service.exe run

I created a C:\ProgramData\inedo\SharedConfig\proget.config that has:

<InedoAppConfig>
  <ConnectionString>Data Source=localhost\hab_sql_server; Initial Catalog=ProGet; Integrated Security=False;User Id=sa;Password=Pass@word1;</ConnectionString>
  <WebServer Enabled="false" />
</InedoAppConfig>

So it is indeed odd it is not finding your dep. I wonder if the actual dll is corrupted. What if you blew away your c:\proget dir and extract the install zip there.

Interesting. It’s odd that it works like that for you, wouldn’t the checksum of the archive not be the same if the dlls were corrupt? My plan simply downloads the zip file and extracts it into C:\Proget. The rest of the config you made seems the same as mine, so does the run hook. I’ll try manually dumping in the files and then playing with the run hook a bit.

yeah. I’m not convinced that is the issue and it would be weird. But its worth extracting fresh into that directory just to rule it out.

Interesting, okay so I tried it exactly as you had it, it seems that having the WebServer flag enabled (true) causes the issue to happen, if set to false it works just fine. I need the webserver enabled and I think that’s what triggering it to require those libraries. I also tried dumping in fresh files but the error remains.

Are you using the integrated web service or IIS?