Database creation is failing on the hosted Azure DevOps build agent

Question

Database creation is failing on the hosted Azure DevOps build agent

Closed this issue 5 years ago · 17 comments

Description

Tests fail on the Azure DevOps hosted build agent with VS2019 (windows-2019) because the database creation fails due to missing log files.

Using LocalDb to get a blank db for each test with the following base class which xUnit.net test classes inherit from:

public class TestBase{

    static SqlInstance<CommunicationContext> instance;


    static TestBase()
    {
        instance = new SqlInstance<CommunicationContext>(
            constructInstance: builder => new CommunicationContext(builder.Options));
    }

    public Task<SqlDatabase<CommunicationContext>> LocalDb(
        string databaseSuffix = null,
        [CallerMemberName] string memberName = null)
    {
        return instance.Build(GetType().Name, databaseSuffix, memberName);
    }
}

Using the LocalDb like the examples:

            using (var database = await LocalDb())
            {
                // Generate entities
                ...cut for brevity...
            }

Everything runs fine locally. Both in VS2019 with the Test Explorer and from the command line running dotnet test or dotnet test --configuration release

When running the test on the Azure DevOps hosted build agent with VS2019 (windows-2019) the tests fail because the database creation fails.

Azure DevOps logs

The complete logfile can be seen here:
https://gist.github.com/henriksen/e7562ff7018932d8d8dc62dc727970d4
The most relevant parts are repeated below

Output from `dotnet test` on the build server

2019-07-12T07:14:29.8313051Z ##[command]"C:\windows\system32\cmd.exe" /D /E:ON /V:OFF /S /C "CALL "d:\a\_temp\a11b0a2a-d31c-4089-985c-3ebc28d92fc9.cmd""
2019-07-12T07:14:31.4513307Z Build started, please wait...
2019-07-12T07:14:33.6194892Z Build completed.
2019-07-12T07:14:33.6196083Z 
2019-07-12T07:14:33.6221979Z Test run for D:\a\1\s\LocalDbRepo\bin\Debug\netcoreapp2.2\LocalDbRepo.dll(.NETCoreApp,Version=v2.2)
2019-07-12T07:14:33.9493992Z Microsoft (R) Test Execution Command Line Tool Version 15.9.0
2019-07-12T07:14:33.9495081Z Copyright (c) Microsoft Corporation.  All rights reserved.
2019-07-12T07:14:33.9495871Z 
2019-07-12T07:14:34.4629404Z Starting test execution, please wait...
2019-07-12T07:14:55.2637431Z [xUnit.net 00:00:18.99]     LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException [FAIL]
2019-07-12T07:14:55.3076292Z Failed   LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException
2019-07-12T07:14:55.3082063Z Error Message:
2019-07-12T07:14:55.3083234Z  System.Exception : Failed to ExecuteCommand
2019-07-12T07:14:55.3084984Z commandText: 
2019-07-12T07:14:55.3086090Z create database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException] on
2019-07-12T07:14:55.3087302Z (
2019-07-12T07:14:55.3088240Z     name = [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException],
2019-07-12T07:14:55.3089120Z     filename = 'd:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf'
2019-07-12T07:14:55.3089830Z )
2019-07-12T07:14:55.3090362Z for attach;
2019-07-12T07:14:55.3090841Z 
2019-07-12T07:14:55.3091550Z alter database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException]
2019-07-12T07:14:55.3092257Z     modify file (name=template, newname='GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException')
2019-07-12T07:14:55.3093037Z alter database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException]
2019-07-12T07:14:55.3093948Z     modify file (name=template_log, newname='GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log')
2019-07-12T07:14:55.3094511Z 
2019-07-12T07:14:55.3095133Z connectionString: Data Source=(LocalDb)\CommunicationContext;Database=master
2019-07-12T07:14:55.3095658Z 
2019-07-12T07:14:55.3097175Z ---- System.Data.SqlClient.SqlException : Could not open new database 'GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException'. CREATE DATABASE is aborted.
2019-07-12T07:14:55.3097919Z Database 'GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException' does not exist. Make sure that the name is entered correctly.
2019-07-12T07:14:55.3098573Z File activation failure. The physical file name "d:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf" may be incorrect.
2019-07-12T07:14:55.3100291Z The log cannot be rebuilt when the primary file is read-only.
2019-07-12T07:14:55.3101235Z Stack Trace:
2019-07-12T07:14:55.3101848Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\projects\localdb\src\LocalDb\SqlExtensions.cs:line 40
2019-07-12T07:14:55.3102993Z    at Wrapper.CreateDatabaseFromFile(String name, Task fileCopyTask) in C:\projects\localdb\src\LocalDb\Wrapper.cs:line 160
2019-07-12T07:14:55.3103531Z    at EfLocalDb.SqlInstance`1.Build(String dbName, IEnumerable`1 data) in C:\projects\localdb\src\EfLocalDb\SqlInstance.cs:line 233
2019-07-12T07:14:55.3104343Z    at LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException() in D:\a\1\s\LocalDbRepo\Pipelines\GetConversationByIdHandlerTests.cs:line 46
2019-07-12T07:14:55.3104995Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T07:14:55.3105859Z ----- Inner Stack Trace -----
2019-07-12T07:14:55.3107113Z    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
2019-07-12T07:14:55.3107966Z    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
2019-07-12T07:14:55.3108397Z    at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
2019-07-12T07:14:55.3108985Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQueryInternal(IAsyncResult asyncResult)
2019-07-12T07:14:55.3109477Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQuery(IAsyncResult asyncResult)
2019-07-12T07:14:55.3110553Z    at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2019-07-12T07:14:55.3111564Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T07:14:55.3112388Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\projects\localdb\src\LocalDb\SqlExtensions.cs:line 35
2019-07-12T07:14:55.3559749Z [xUnit.net 00:00:19.09]     LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenTwoConversations_SelectsJustTheOne [FAIL]
2019-07-12T07:14:55.4437665Z Failed   LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenTwoConversations_SelectsJustTheOne
2019-07-12T07:14:55.4438554Z Error Message:
2019-07-12T07:14:55.4439236Z  System.Exception : Failed to ExecuteCommand
2019-07-12T07:14:55.4439769Z commandText: 
2019-07-12T07:14:55.4441174Z create database [GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne] on
2019-07-12T07:14:55.4441623Z (
2019-07-12T07:14:55.4442070Z     name = [GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne],
2019-07-12T07:14:55.4442541Z     filename = 'd:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne.mdf'
2019-07-12T07:14:55.4443117Z )
2019-07-12T07:14:55.4443526Z for attach;
2019-07-12T07:14:55.4443969Z 
2019-07-12T07:14:55.4444392Z alter database [GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne]
2019-07-12T07:14:55.4444896Z     modify file (name=template, newname='GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne')
2019-07-12T07:14:55.4445374Z alter database [GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne]
2019-07-12T07:14:55.4445825Z     modify file (name=template_log, newname='GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne_log')
2019-07-12T07:14:55.4446943Z 
2019-07-12T07:14:55.4447519Z connectionString: Data Source=(LocalDb)\CommunicationContext;Database=master
2019-07-12T07:14:55.4447985Z 
2019-07-12T07:14:55.4448925Z ---- System.Data.SqlClient.SqlException : Could not open new database 'GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne'. CREATE DATABASE is aborted.
2019-07-12T07:14:55.4449566Z Database 'GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne' does not exist. Make sure that the name is entered correctly.
2019-07-12T07:14:55.4450361Z File activation failure. The physical file name "d:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne_log.ldf" may be incorrect.
2019-07-12T07:14:55.4450836Z The log cannot be rebuilt when the primary file is read-only.
2019-07-12T07:14:55.4451268Z Stack Trace:
2019-07-12T07:14:55.4451695Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\projects\localdb\src\LocalDb\SqlExtensions.cs:line 40
2019-07-12T07:14:55.4452279Z    at Wrapper.CreateDatabaseFromFile(String name, Task fileCopyTask) in C:\projects\localdb\src\LocalDb\Wrapper.cs:line 160
2019-07-12T07:14:55.4452899Z    at EfLocalDb.SqlInstance`1.Build(String dbName, IEnumerable`1 data) in C:\projects\localdb\src\EfLocalDb\SqlInstance.cs:line 233
2019-07-12T07:14:55.4453541Z    at LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenTwoConversations_SelectsJustTheOne() in D:\a\1\s\LocalDbRepo\Pipelines\GetConversationByIdHandlerTests.cs:line 23
2019-07-12T07:14:55.4454379Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T07:14:55.4455980Z ----- Inner Stack Trace -----
2019-07-12T07:14:55.4459599Z    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
2019-07-12T07:14:55.4460437Z    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
2019-07-12T07:14:55.4461154Z    at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
2019-07-12T07:14:55.4461681Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQueryInternal(IAsyncResult asyncResult)
2019-07-12T07:14:55.4462287Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQuery(IAsyncResult asyncResult)
2019-07-12T07:14:55.4462765Z    at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2019-07-12T07:14:55.4463267Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T07:14:55.4463762Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\projects\localdb\src\LocalDb\SqlExtensions.cs:line 35
2019-07-12T07:14:55.4583687Z 
2019-07-12T07:14:55.4585107Z Test Run Failed.
2019-07-12T07:14:55.4585457Z Total tests: 2. Passed: 0. Failed: 2. Skipped: 0.
2019-07-12T07:14:55.4586279Z Test execution time: 20.8861 Seconds

Testing SqlLocalDb Creation

Trying to create a database with SqlLocalDb works fine:

SqlLocalDB c "GetConversationByIdHandlerTests_Handle_GivenConversationWithAssignedUser_IncludedAssignedUser"
SqlLocalDB s "GetConversationByIdHandlerTests_Handle_GivenConversationWithAssignedUser_IncludedAssignedUser"
SqlLocalDB v
SqlLocalDB trace on

yields

2019-07-12T07:14:06.2456096Z LocalDB instance "GetConversationByIdHandlerTests_Handle_GivenConversationWithAssignedUser_IncludedAssignedUser" created with version 13.1.4001.0.
2019-07-12T07:14:06.2457235Z 
2019-07-12T07:14:07.8730659Z LocalDB instance "GetConversationByIdHandlerTests_Handle_GivenConversationWithAssignedUser_IncludedAssignedUser" started.
2019-07-12T07:14:07.8732775Z 
2019-07-12T07:14:07.8917039Z Windows API call "RegGetValueW" returned error code: 0.
2019-07-12T07:14:07.8918311Z 
2019-07-12T07:14:07.9082783Z LocalDB Instance API tracing turned ON.

Database files left behind after test

Build agent

In the TEMP directory after the tests the test databases are missing their logfiles:

2019-07-12T07:14:55.5032803Z  Directory of d:\a\_temp\LocalDb\CommunicationContext
2019-07-12T07:14:55.5033223Z 
2019-07-12T07:14:55.5033727Z 07/12/2019  07:14 AM    <DIR>          .
2019-07-12T07:14:55.5034174Z 07/12/2019  07:14 AM    <DIR>          ..
2019-07-12T07:14:55.5034750Z 07/12/2019  07:14 AM         3,145,728 GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf
2019-07-12T07:14:55.5035316Z 07/12/2019  07:14 AM         3,145,728 GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne.mdf
2019-07-12T07:14:55.5035812Z 07/12/2019  07:14 AM         3,145,728 template.mdf
2019-07-12T07:14:55.5036186Z 07/12/2019  07:14 AM           524,288 template_log.ldf
2019-07-12T07:14:55.5037221Z                4 File(s)      9,961,472 bytes
2019-07-12T07:14:55.5037580Z                2 Dir(s)  13,057,638,400 bytes free

Locally

Running the tests locally leaves both the .mdf file and the .ldf file

> dir $env:temp\LocalDb\CommunicationContext

Mode                LastWriteTime     Length Name
----                -------------     ------ ----
-a----       12.07.2019     09:03     3,00MB GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf
-a----       12.07.2019     09:03   504,00KB GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf
-a----       12.07.2019     09:03     3,00MB GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne.mdf
-a----       12.07.2019     09:03   504,00KB GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne_log.ldf
-a----       12.07.2019     09:03     3,00MB template.mdf
-a----       12.07.2019     09:03   512,00KB template_log.ldf

Minimal Repro

I've created a minimal repo here:
https://github.com/henriksen/localDbRepo

Submit a PR that fixes the bug

Am going to try changing the create database script to include the .ldf file as well. Will update with a PR if that works out.

Answer 1 · 2019-07-12T11:02:09.000Z

Trying some things.

Changed the create database script to use attach_rebuild_log :

create database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException] on
(
    name = [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException],
    filename = 'd:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf'
)
for ATTACH_REBUILD_LOG;

Which created the logfiles

 Directory of d:\a\_temp\LocalDb\CommunicationContext

07/12/2019  09:12 AM    <DIR>          .
07/12/2019  09:12 AM    <DIR>          ..
07/12/2019  09:12 AM         3,145,728 GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf
07/12/2019  09:12 AM           524,288 GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf
07/12/2019  09:12 AM         3,145,728 GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne.mdf
07/12/2019  09:12 AM           524,288 GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne_log.ldf
07/12/2019  09:12 AM         3,145,728 template.mdf
07/12/2019  09:12 AM           524,288 template_log.ldf

but gave me a different error:

2019-07-12T09:12:19.5074850Z [xUnit.net 00:00:16.83]     LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException [FAIL]
2019-07-12T09:12:19.5468569Z Failed   LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException
2019-07-12T09:12:19.5469614Z Error Message:
2019-07-12T09:12:19.5470160Z  System.Exception : Failed to ExecuteCommand
2019-07-12T09:12:19.5470555Z commandText: 
2019-07-12T09:12:19.5471029Z create database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException] on
2019-07-12T09:12:19.5471238Z (
2019-07-12T09:12:19.5471400Z     name = [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException],
2019-07-12T09:12:19.5471817Z     filename = 'd:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf'
2019-07-12T09:12:19.5472182Z )
2019-07-12T09:12:19.5472455Z for ATTACH_REBUILD_LOG;
2019-07-12T09:12:19.5472718Z 
2019-07-12T09:12:19.5472992Z alter database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException]
2019-07-12T09:12:19.5473322Z     modify file (name=template, newname='GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException')
2019-07-12T09:12:19.5473679Z alter database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException]
2019-07-12T09:12:19.5474179Z     modify file (name=template_log, newname='GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log')
2019-07-12T09:12:19.5474457Z 
2019-07-12T09:12:19.5474616Z connectionString: Data Source=(LocalDb)\CommunicationContext;Database=master
2019-07-12T09:12:19.5474767Z 
2019-07-12T09:12:19.5474923Z ---- System.Data.SqlClient.SqlException : To use ALTER DATABASE, the database must be in a writable state in which a checkpoint can be executed.
2019-07-12T09:12:19.5475620Z To use ALTER DATABASE, the database must be in a writable state in which a checkpoint can be executed.
2019-07-12T09:12:19.5475861Z Stack Trace:
2019-07-12T09:12:19.5476006Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\dev\justify\LocalDb\src\LocalDb\SqlExtensions.cs:line 40
2019-07-12T09:12:19.5477330Z    at Wrapper.ExecuteOnMasterAsync(String command) in C:\dev\justify\LocalDb\src\LocalDb\Wrapper.cs:line 212
2019-07-12T09:12:19.5477680Z    at Wrapper.CreateDatabaseFromTemplate(String name) in C:\dev\justify\LocalDb\src\LocalDb\Wrapper.cs:line 108
2019-07-12T09:12:19.5477886Z    at EfLocalDb.SqlInstance`1.Build(String dbName, IEnumerable`1 data) in C:\dev\justify\LocalDb\src\EfLocalDb\SqlInstance.cs:line 198
2019-07-12T09:12:19.5478127Z    at LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException() in D:\a\1\s\LocalDbRepo\Pipelines\GetConversationByIdHandlerTests.cs:line 46
2019-07-12T09:12:19.5478355Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T09:12:19.5478645Z ----- Inner Stack Trace -----
2019-07-12T09:12:19.5478940Z    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
2019-07-12T09:12:19.5479163Z    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
2019-07-12T09:12:19.5479365Z    at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
2019-07-12T09:12:19.5479577Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQueryInternal(IAsyncResult asyncResult)
2019-07-12T09:12:19.5479756Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQuery(IAsyncResult asyncResult)
2019-07-12T09:12:19.5479941Z    at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2019-07-12T09:12:19.5480139Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T09:12:19.5480881Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\dev\justify\LocalDb\src\LocalDb\SqlExtensions.cs:line 35

Answer 2 · 2019-07-12T11:03:56.000Z

Do u get the same error with the v3 beta?

Answer 3 · 2019-07-12T11:04:52.000Z

Let me check, haven't tried that

Answer 4 · 2019-07-12T11:06:01.000Z

@SimonCropp Is that the deferStart branch?

Answer 5 · 2019-07-12T11:10:27.000Z

There should be a beta on nuget

Answer 6 · 2019-07-12T11:11:13.000Z

I'll try that one then 👍

Answer 7 · 2019-07-12T11:29:11.000Z

Also what is the sql version. Ie is it running the current CU https://github.com/SimonCropp/LocalDb/blob/master/readme.md#sql-server-updates

Answer 8 · 2019-07-12T12:16:07.000Z

Both on my machine (where it works) and on the hosted build agent the databases are created with version 13.1.4001.0, which is SQL 2016 SP1. I'm guessing that's the versions that ships with VS 2019.

Answer 9 · 2019-07-12T12:17:34.000Z

Using the beta had no effect. Same error as originally.
Log file: https://gist.github.com/henriksen/0b6b8effed04239de5031351958ebf88

Answer 10 · 2019-07-12T12:40:24.000Z

Kinda grasping at straws here, but since the error said the db needed to be in a writable state I tried forcing it with SET READ_WRITE, but that didn't help either.

2019-07-12T12:23:44.3332264Z [xUnit.net 00:00:15.92]     LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException [FAIL]
2019-07-12T12:23:44.3757203Z Failed   LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException
2019-07-12T12:23:44.3758254Z Error Message:
2019-07-12T12:23:44.3759426Z  System.Exception : Failed to ExecuteCommand
2019-07-12T12:23:44.3759931Z commandText: 
2019-07-12T12:23:44.3760217Z create database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException] on
2019-07-12T12:23:44.3760447Z (
2019-07-12T12:23:44.3760625Z     name = [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException],
2019-07-12T12:23:44.3760851Z     filename = 'd:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf'
2019-07-12T12:23:44.3761071Z ),
2019-07-12T12:23:44.3761180Z (
2019-07-12T12:23:44.3761327Z     name = [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log],
2019-07-12T12:23:44.3761535Z     filename = 'd:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf'
2019-07-12T12:23:44.3761741Z )
2019-07-12T12:23:44.3762018Z for attach;
2019-07-12T12:23:44.3762144Z 
2019-07-12T12:23:44.3762336Z ALTER DATABASE [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException] SET READ_WRITE;
2019-07-12T12:23:44.3762484Z 
2019-07-12T12:23:44.3762658Z alter database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException]
2019-07-12T12:23:44.3762846Z     modify file (name=template, newname='GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException')
2019-07-12T12:23:44.3764075Z alter database [GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException]
2019-07-12T12:23:44.3764321Z     modify file (name=template_log, newname='GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log')
2019-07-12T12:23:44.3764473Z 
2019-07-12T12:23:44.3764800Z connectionString: Data Source=(LocalDb)\CommunicationContext;Database=master
2019-07-12T12:23:44.3765222Z 
2019-07-12T12:23:44.3766941Z ---- System.Data.SqlClient.SqlException : Unable to open the physical file "d:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf". Operating system error 5: "5(Access is denied.)".
2019-07-12T12:23:44.3767710Z Unable to open the physical file "d:\a\_temp\LocalDb\CommunicationContext\GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf". Operating system error 5: "5(Access is denied.)".
2019-07-12T12:23:44.3768245Z Could not restart database "GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException". Reverting to the previous status.
2019-07-12T12:23:44.3769193Z ALTER DATABASE statement failed.
2019-07-12T12:23:44.3769823Z To use ALTER DATABASE, the database must be in a writable state in which a checkpoint can be executed.
2019-07-12T12:23:44.3770083Z To use ALTER DATABASE, the database must be in a writable state in which a checkpoint can be executed.
2019-07-12T12:23:44.3770297Z Stack Trace:
2019-07-12T12:23:44.3770506Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\dev\justify\LocalDb\src\LocalDb\SqlExtensions.cs:line 40
2019-07-12T12:23:44.3770710Z    at Wrapper.ExecuteOnMasterAsync(String command) in C:\dev\justify\LocalDb\src\LocalDb\Wrapper.cs:line 218
2019-07-12T12:23:44.3770928Z    at Wrapper.CreateDatabaseFromTemplate(String name) in C:\dev\justify\LocalDb\src\LocalDb\Wrapper.cs:line 114
2019-07-12T12:23:44.3771160Z    at EfLocalDb.SqlInstance`1.Build(String dbName, IEnumerable`1 data) in C:\dev\justify\LocalDb\src\EfLocalDb\SqlInstance.cs:line 198
2019-07-12T12:23:44.3771380Z    at LocalDbRepo.Pipelines.GetConversationByIdHandlerTests.Handle_GivenInvalidConversationId_ThrowKeyNotFoundException() in D:\a\1\s\LocalDbRepo\Pipelines\GetConversationByIdHandlerTests.cs:line 46
2019-07-12T12:23:44.3771611Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T12:23:44.3772073Z ----- Inner Stack Trace -----
2019-07-12T12:23:44.3772245Z    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
2019-07-12T12:23:44.3772457Z    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
2019-07-12T12:23:44.3772684Z    at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
2019-07-12T12:23:44.3772886Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQueryInternal(IAsyncResult asyncResult)
2019-07-12T12:23:44.3773076Z    at System.Data.SqlClient.SqlCommand.EndExecuteNonQuery(IAsyncResult asyncResult)
2019-07-12T12:23:44.3773282Z    at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2019-07-12T12:23:44.3773472Z --- End of stack trace from previous location where exception was thrown ---
2019-07-12T12:23:44.3773675Z    at SqlExtensions.ExecuteCommandAsync(SqlConnection connection, String commandText) in C:\dev\justify\LocalDb\src\LocalDb\SqlExtensions.cs:line 35

Answer 11 · 2019-07-12T12:50:25.000Z

Weird, and I don't know if related or relevant, but the database file size is significantly larger on the VS Build agent than on my local machine...

Build agent

2019-07-12T12:23:45.3107881Z  Directory of d:\a\_temp\LocalDb\CommunicationContext
2019-07-12T12:23:45.3109013Z 
2019-07-12T12:23:45.3109751Z 07/12/2019  12:23 PM    <DIR>          .
2019-07-12T12:23:45.3110296Z 07/12/2019  12:23 PM    <DIR>          ..
2019-07-12T12:23:45.3110891Z 07/12/2019  12:23 PM         3,145,728 GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf
2019-07-12T12:23:45.3111486Z 07/12/2019  12:23 PM           524,288 GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf
2019-07-12T12:23:45.3112355Z 07/12/2019  12:23 PM         3,145,728 GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne.mdf
2019-07-12T12:23:45.3113021Z 07/12/2019  12:23 PM           524,288 GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne_log.ldf
2019-07-12T12:23:45.3113550Z 07/12/2019  12:23 PM         3,145,728 template.mdf
2019-07-12T12:23:45.3113882Z 07/12/2019  12:23 PM           524,288 template_log.ldf
2019-07-12T12:23:45.3114122Z                6 File(s)     11,010,048 bytes
2019-07-12T12:23:45.3114348Z                2 Dir(s)  13,056,020,480 bytes free

Local machine

> dir $env:temp\LocalDb\CommunicationContext\

Mode                LastWriteTime     Length Name
----                -------------     ------ ----
-a----       12.07.2019     14:43     3,00MB GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException.mdf
-a----       12.07.2019     14:43   768,00KB GetConversationByIdHandlerTests_Handle_GivenInvalidConversationId_ThrowKeyNotFoundException_log.ldf
-a----       12.07.2019     14:43     3,00MB GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne.mdf
-a----       12.07.2019     14:43   768,00KB GetConversationByIdHandlerTests_Handle_GivenTwoConversations_SelectsJustTheOne_log.ldf
-a----       12.07.2019     14:43     3,00MB template.mdf
-a----       12.07.2019     14:43   512,00KB template_log.ldf

Which is weird since it's the same program that runs in both places. It tells me there's a difference, but I don't know what it might be...

Answer 12 · 2019-07-12T14:02:12.000Z

Posted on the Microsoft Developer Community as well to see if someone there can help.

Answer 13 · 2019-07-13T05:51:46.000Z

i took a guess at the problem and deployed a new version. can u try version 3.0.0-beta.4

Answer 14 · 2019-07-13T21:24:31.000Z

Good guess! That worked like a charm! Weird that the agent temp dir behaves differently than the %TEMP% dir. 🤔
Thank you for taking the time! I very much appreciate it.

Answer 15 · 2019-07-14T01:25:48.000Z

Glad to hear. V3 stable should be done in 2-3 days.

Btw i notice u r using xunit. Have a read of this https://github.com/SimonCropp/LocalDb/blob/master/pages/logging.md specifically the bit about https://github.com/SimonCropp/XunitLogger

Answer 16 · 2019-07-14T21:45:56.000Z

Thanks for the logging tip! Was looking into that. Really wanted to get the SQL statements used into the log files, this gives me an in to that. Appreciate it!

Answer 17 · 2019-07-17T00:15:00.000Z

btw if u still want to use the agent temp drive (which is faster) you can try running this ps script at startup

$paths = @('D:\Agent', 'D:\Agent\Work', 'D:\Agent\Work\_Temp')

$paths | % {
    $d = [System.IO.Directory]::CreateDirectory($_)
    $acl = Get-Acl $d.FullName
    $ar = new-object System.Security.AccessControl.FileSystemAccessRule("Everyone", "FullControl", "ContainerInherit, ObjectInherit", "None", "Allow")
    $acl.AddAccessRule($ar)
    Set-Acl $d.FullName -AclObject $acl
}