Git Synchronization Failed - Cannot access the file

PowerShell Universal
1 
Product: PowerShell Universal
Version: 3.6.4

Hello all,

I am currently trying to marry two freshly installed PowerShell Universal Servers together by synchronizing the configurations via git & GitLab. Unfortunately I have the following situation.

Server A) Was able to synchronize twice yesterday. After restarting the server, the error appears every minute now:

Git Synchronization Failed
The process cannot access the file ‘\C:\PowerShellUniversal\Git’ because it is being used by another process.

Server B) I have not been able to connect to this server yet. Also this server gets the same error message every minute:

Git Synchronization Failed
The process cannot access the file ‘\C:\PowerShellUniversal\Git’ because it is being used by another process.

The configuration file appsettings.json looks identical on both servers. Here is an excerpt of the Git configuration (anonymized):

  "Data": {
    "RepositoryPath": "C:\\PowerShellUniversal\\Git",
    "ConnectionString": "Server=my.server.com;Database=PSUniversal;Integrated Security=true;TrustServerCertificate=True;",
    "ConfigurationScript": "",
    "GitRemote": "https://mygitlab.server.com/gitlab/powershell/powershell-universal.git",
    "GitUserName": "myServiceUser",
    "GitPassword": "myAccessToken",
    "GitBranch": "main",
    "GitSyncBehaviour": "TwoWay"
  },

I don’t understand why PowerShell Universal can’t access the directory. And yes, …\Git is a directory without any content.

What have I already tried?

  • Create a new directory and put it in the configuration file → same effect.
  • used handle64.exe to find out if there is ANYTHING accessing the directory > no result found

Since it already worked twice on server A, I wonder what I’m doing wrong here. Is it possible that the error message is simply not correct and I am doing something completely different wrong or have overlooked?

Thanks for any input from you guys!

2

In the meantime I discovered the following entry in the event log:

Event ID 300
Source PowerShell (PowerShell)

Provider Health: The drive 'T:\' could not be found. The drive may not be ready or mapped. 

Details: 
	ProviderName=Microsoft.PowerShell.Core\FileSystem
	ExceptionClass=DriveNotFoundException
	ErrorCategory=
	ErrorId=
	ErrorMessage=The drive "T:\" could not be found. The drive may not be ready or may not be mapped.

	Severity=Warning

	SequenceNumber=47

	HostName=Default Host
	HostVersion=5.1.20348.859
	HostId=2d41999d-b616-43f6-a24f-cafbe9af90c0
	HostApplication=C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -Command & { [System.Reflection.Assembly]::LoadFrom('C:\Program Files (x86)\Universal\Host\host.dll'); [UniversalHost.AgentService]::StartModuleDiscovery('Windows PowerShell 5.1', 60239) }
	EngineVersion=5.1.20348.859
	RunspaceId=58e48c8e-4bb0-4636-93e2-246a4898e299
	PipelineId=2
	CommandName=
	CommandType=
	ScriptName=
	CommandPath=
	CommandLine=

I just don’t understand what it has to do with the missing T: drive. Is there some drive mapping not working properly?
Is there any way to find out why the mapping is not working? Apart from “might not be ready or might not be mapped”?

When I run the command mentioned under HostApplication with my local administrator user, the same error message appears in the event log

3

Seems simple enough and should be working fine. Can you share the full stack trace from the log file?

Also, I would recommend capturing a procmon trace to see if we can spot what is trying to access that directory.

4

Hello Adam,

thank you very much for your response.

Here is the requested log. I stopped the service for this, cleaned the logs and started the service again:

2023-01-13 15:16:31.228 +01:00 [INF] Start installing Hangfire SQL objects...
2023-01-13 15:16:31.393 +01:00 [INF] Hangfire SQL objects installed.
2023-01-13 15:16:31.668 +01:00 [DBG] Hosting starting
2023-01-13 15:16:31.708 +01:00 [INF] User profile is available. Using 'C:\Users\svc.glo.p.pou_t1\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
2023-01-13 15:16:31.773 +01:00 [DBG] Reading data from file 'C:\Users\svc.glo.p.pou_t1\AppData\Local\ASP.NET\DataProtection-Keys\key-8f4095e4-c009-4a21-9bb1-d984d6cf8538.xml'.
2023-01-13 15:16:31.775 +01:00 [DBG] Reading data from file 'C:\Users\svc.glo.p.pou_t1\AppData\Local\ASP.NET\DataProtection-Keys\key-b82f6f9c-37e3-42c0-bc06-7877d5df59e0.xml'.
2023-01-13 15:16:31.780 +01:00 [DBG] Found key {8f4095e4-c009-4a21-9bb1-d984d6cf8538}.
2023-01-13 15:16:31.783 +01:00 [DBG] Found key {b82f6f9c-37e3-42c0-bc06-7877d5df59e0}.
2023-01-13 15:16:31.789 +01:00 [DBG] Considering key {8f4095e4-c009-4a21-9bb1-d984d6cf8538} with expiration date 2023-04-05 08:56:43Z as default key.
2023-01-13 15:16:31.790 +01:00 [DBG] Forwarded activator type request from Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor, Microsoft.AspNetCore.DataProtection, Version=6.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
2023-01-13 15:16:31.792 +01:00 [DBG] Decrypting secret element using Windows DPAPI.
2023-01-13 15:16:31.793 +01:00 [DBG] Forwarded activator type request from Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=6.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
2023-01-13 15:16:31.796 +01:00 [DBG] Opening CNG algorithm 'AES' from provider 'null' with chaining mode CBC.
2023-01-13 15:16:31.798 +01:00 [DBG] Opening CNG algorithm 'SHA256' from provider 'null' with HMAC.
2023-01-13 15:16:31.802 +01:00 [DBG] Using key {8f4095e4-c009-4a21-9bb1-d984d6cf8538} as the default key.
2023-01-13 15:16:31.803 +01:00 [DBG] Key ring with default key {8f4095e4-c009-4a21-9bb1-d984d6cf8538} was loaded during application startup.
2023-01-13 15:16:31.968 +01:00 [DBG] Registered SignalR Protocol: json, implemented by Microsoft.AspNetCore.SignalR.Protocol.JsonHubProtocol.
2023-01-13 15:16:31.979 +01:00 [INF] Starting heartbeat job.
2023-01-13 15:16:32.074 +01:00 [INF] Starting heartbeat job.
2023-01-13 15:16:32.193 +01:00 [DBG] Registered model binder providers, in the following order: ["Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BinderTypeModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ServicesModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.HeaderModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FloatingPointTypeModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.EnumTypeModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DateTimeModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CancellationTokenModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ByteArrayModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormFileModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormCollectionModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.KeyValuePairModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DictionaryModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ArrayModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CollectionModelBinderProvider","Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ComplexObjectModelBinderProvider"]
2023-01-13 15:16:32.381 +01:00 [WRN] Failed to process the job '320200': an exception occurred. Retry attempt 1 of 10 will be performed in 00:00:17.
System.ObjectDisposedException: Cannot access a disposed context instance. A common cause of this error is disposing a context instance that was resolved from dependency injection and then later trying to use the same context instance elsewhere in your application. This may occur if you are calling 'Dispose' on the context instance, or wrapping it in a using statement. If you are using dependency injection, you should let the dependency injection container take care of disposing context instances.
Object name: 'PsuDbContext'.
   at Microsoft.EntityFrameworkCore.DbContext.CheckDisposed()
   at Microsoft.EntityFrameworkCore.DbContext.get_Database()
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.OnFirstExecution()
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
   at System.Linq.Enumerable.TryGetSingle[TSource](IEnumerable`1 source, Boolean& found)
   at lambda_method344(Closure , QueryContext )
   at Microsoft.EntityFrameworkCore.Query.Internal.QueryCompiler.Execute[TResult](Expression query)
   at Microsoft.EntityFrameworkCore.Query.Internal.EntityQueryProvider.Execute[TResult](Expression expression)
   at System.Linq.Queryable.Any[TSource](IQueryable`1 source)
   at PowerShellUniversal.SQL.SqlTable`1.<>c.<Exists>b__15_0(IQueryable`1 m) in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal.SQL\Database.cs:line 589
   at PowerShellUniversal.SQL.SqlTable`1.DisposeAfterCall[X](Func`2 call) in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal.SQL\Database.cs:line 664
   at PowerShellUniversal.SQL.SqlTable`1.Exists() in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal.SQL\Database.cs:line 589
   at UniversalAutomation.GitSyncService.Sync(Boolean force) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitSyncService.cs:line 77
2023-01-13 15:16:32.469 +01:00 [WRN] Failed to process the job '320207': an exception occurred. Retry attempt 1 of 10 will be performed in 00:00:33.
System.NullReferenceException: Object reference not set to an instance of an object.
   at Microsoft.Data.SqlClient.SqlConnection.get_TypeSystem()
   at Microsoft.Data.SqlClient.SqlDataReader..ctor(SqlCommand command, CommandBehavior behavior)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)
   at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
   at Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.Common.DbCommand.ExecuteReader()
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.InitializeReader(Enumerator enumerator)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.<>c.<MoveNext>b__19_0(DbContext _, Enumerator enumerator)
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.<>c__DisplayClass31_0`2.<Execute>b__0(DbContext context, TState state)
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.ExecuteImplementation[TState,TResult](Func`3 operation, Func`3 verifySucceeded, TState state)
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()
   at System.Collections.Generic.LargeArrayBuilder`1.AddRange(IEnumerable`1 items)
   at System.Collections.Generic.EnumerableHelpers.ToArray[T](IEnumerable`1 source)
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at PowerShellUniversal.SQL.SqlTable`1.<>c.<ToArray>b__18_0(IQueryable`1 m) in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal.SQL\Database.cs:line 604
   at PowerShellUniversal.SQL.SqlTable`1.DisposeAfterCall[X](Func`2 call) in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal.SQL\Database.cs:line 664
   at PowerShellUniversal.SQL.SqlTable`1.ToArray() in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal.SQL\Database.cs:line 604
   at UniversalAutomation.Services.AppTokenService.Load() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\Authentication\AppTokenService.cs:line 26
2023-01-13 15:16:32.592 +01:00 [DBG] Repository directory already exists. Validating whether it is a valid git repository.
2023-01-13 15:16:32.599 +01:00 [ERR] Failed to reschedule git sync.
System.NullReferenceException: Object reference not set to an instance of an object.
   at UniversalAutomation.HeartBeatService.Run() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\HeartBeatService.cs:line 0
2023-01-13 15:16:32.621 +01:00 [INF] Finished heartbeat job.
2023-01-13 15:16:32.680 +01:00 [DBG] Repository directory is valid repository.
2023-01-13 15:16:32.700 +01:00 [DBG] Starting sync...
2023-01-13 15:16:32.719 +01:00 [DBG] Git has remote. Starting pull
2023-01-13 15:16:32.730 +01:00 [ERR] Failed to reschedule git sync.
System.NullReferenceException: Object reference not set to an instance of an object.
   at UniversalAutomation.HeartBeatService.Run() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\HeartBeatService.cs:line 0
2023-01-13 15:16:32.763 +01:00 [INF] Now listening on: http://[::]:5000
2023-01-13 15:16:32.764 +01:00 [DBG] Loaded hosting startup assembly Universal.Server
2023-01-13 15:16:32.765 +01:00 [INF] Application started. Hosting environment: Production; Content root path: C:\Program Files (x86)\PowershellUniversal\
2023-01-13 15:16:32.765 +01:00 [DBG] Hosting started
2023-01-13 15:16:32.776 +01:00 [INF] Finished heartbeat job.
2023-01-13 15:16:32.835 +01:00 [DBG] Loading license information.
2023-01-13 15:16:33.015 +01:00 [ERR] Failed to sync: Sequence contains no elements    at System.Linq.ThrowHelper.ThrowNoElementsException()
   at System.Linq.Enumerable.First[TSource](IEnumerable`1 source)
   at PowerShellUniversal.MemoryTable`1.First() in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal\MemoryTable.cs:line 45
   at UniversalAutomation.Git.GitService.GetProxyOptions() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitService.cs:line 175
   at UniversalAutomation.Git.GitService.Pull() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitService.cs:line 556
   at UniversalAutomation.GitSyncService.TrySync(GitStatus status, Boolean force, GitSettings settings) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitSyncService.cs:line 160
   at UniversalAutomation.GitSyncService.Sync(Boolean force) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitSyncService.cs:line 91

Here is an excerpt from above that I consider relevant:

2023-01-13 15:16:32.680 +01:00 [DBG] Repository directory is valid repository.
2023-01-13 15:16:32.700 +01:00 [DBG] Starting sync...
2023-01-13 15:16:32.719 +01:00 [DBG] Git has remote. Starting pull
2023-01-13 15:16:32.730 +01:00 [ERR] Failed to reschedule git sync.
System.NullReferenceException: Object reference not set to an instance of an object.
   at UniversalAutomation.HeartBeatService.Run() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\HeartBeatService.cs:line 0
2023-01-13 15:16:32.763 +01:00 [INF] Now listening on: http://[::]:5000
2023-01-13 15:16:32.764 +01:00 [DBG] Loaded hosting startup assembly Universal.Server
2023-01-13 15:16:32.765 +01:00 [INF] Application started. Hosting environment: Production; Content root path: C:\Program Files (x86)\PowershellUniversal\
2023-01-13 15:16:32.765 +01:00 [DBG] Hosting started
2023-01-13 15:16:32.776 +01:00 [INF] Finished heartbeat job.
2023-01-13 15:16:32.835 +01:00 [DBG] Loading license information.
2023-01-13 15:16:33.015 +01:00 [ERR] Failed to sync: Sequence contains no elements    at System.Linq.ThrowHelper.ThrowNoElementsException()
   at System.Linq.Enumerable.First[TSource](IEnumerable`1 source)
   at PowerShellUniversal.MemoryTable`1.First() in C:\actions-runner\_work\universal\universal\src\PowerShellUniversal\MemoryTable.cs:line 45
   at UniversalAutomation.Git.GitService.GetProxyOptions() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitService.cs:line 175
   at UniversalAutomation.Git.GitService.Pull() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitService.cs:line 556
   at UniversalAutomation.GitSyncService.TrySync(GitStatus status, Boolean force, GitSettings settings) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitSyncService.cs:line 160
   at UniversalAutomation.GitSyncService.Sync(Boolean force) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\GitSyncService.cs:line 91

ProcMon does not find any process accessing the directory, apart from Universal.Server and PowerShell. However, PowerShell also comes through the Universal service, example:

"C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe"  -NonInteractive -NoProfile -Command "& { [System.Reflection.Assembly]::LoadFrom('C:\Program Files (x86)\PowershellUniversal\Host\host.dll') | Out-Null; [UniversalHost.AgentService]::StartApi(64606, 5760, 64600) }"

PS: The SQL error in the full log - is this negligible or should we clean the database?

Thanks thanks thanks!

5

Any ideas?

6

Hey adam,

I have already opened a support case for this problem yesterday. Unfortunately, no one has responded there yet either. Does this look like a major problem or would it help if I just remove the entire installation and start over?

7

Did you get anywhere with this?
My setup was working and a simple restart of the service resulted in something similar.
I’m getting that same error in the EventLog, Could not find the drive T:\

Im using external GIT sync

8

Hey,

I was able to fix the problem by cleaning the entire database (deleting all tables), uninstalling PowerShell Universal and deleting all configuration files that remain (i.e. all POU directories).

After that I started to rebuild everything with a single server. The git sync worked for now and I set up the second server again (copy+paste the config file from server 1 to server 2 before I started the service for the first time). Up to this point everything worked fine.

Yesterday I then set up a webserver certificate on both servers and restricted access to https. To do this, I then also restarted the service on both servers, as you did. Both servers had the same error message again (Eventlog ID 300, Provider Health: Could not find the drive 'T:'. The drive might not be ready or might not be mapped… ).

I haven’t been able to analyze the problem further yet, but I just saw that there are 17 endpoints known on server 1 and 19 on server 2, so something seems to be wrong again.

In the endpoint.ps1 (GitLab) I see currently 19 endpoints, so server 2 seems to synchronize correctly.

When I compare both event logs, the errors occurred yesterday on both systems within a similar time period.

Server 1:
13:39:52
13:39:55
13:39:57
14:12:40
14:13:19
14:20:37
14:20:55
14:22:27
14:22:40
14:54:26

vs.

Server2:
13:53:10
14:57:48
14:57:50
14:59:34

Server 1 has more entries in the event log because I usually press sync now there to be able to test after I have changes in GitLab.

What else do I notice?

  1. under Settings > Git
    1.2. Server 1 last sync was at 2:22 PM (so is still in the period of eventlog messages).
    1.3. Server 2 is still working
  2. I no longer receive notifications via the bell in POU on server 1 that an error has occurred.
    2.1. When I press syn now nothing happens on server 1. Neither an error in POU, nor in the event log are stored. As if the button would have no more use…
    2.2 Server 2 syncs cleanly when I make a change in GitLab.

What do I try next?
I’m thinking of the following steps:
Server 1:

  1. stop service
  2. remove local repository and manually reclone with git.
  3. start service
  4. cross your fingers

What have you already tried?

9

I was just able to solve my problem in a relatively simple way…

The web interface of server 1 was in editor mode, the mode you have available when a two-way git sync is set up.

After I clicked Cancel Edit there, the sync started again without any problems. I think I will open an issue for this and suggest to make this logic different.

Is this the case for you as well?

10

Hey @memphisraynz,

I have opened an issue and it has already been added by Adam to Milestone 3.8, I hope this will help you too

Edit mode pauses Git Sync · Issue #2007 · ironmansoftware/issues (github.com)