Sqlite DB Locked on Azure Dotnet Core Entity Framework

Question

I have a simple asp.net core web app (v2.1), that I deployed to a B1 (and I tried B2) Azure App Service on Linux. When I call dbContext.SaveChanges(), after adding one very simple entity, the request takes about 30 seconds before throwing the following error:

Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.

Here is the code. _dbContext is injected with scoped lifetime.

public async Task<IActionResult> SignIn([Bind("Email,Password,RedirectUrl")] SignInModel model) {
    if (ModelState.IsValid) {
        var user = _dbContext.Users.Include(u => u.Claims).FirstOrDefault(u => u.UserName == model.Email);

        ...

        user.LastLogin = DateTimeOffset.Now;
        await _dbContext.SaveChangesAsync();

        ...

        return Redirect(String.IsNullOrWhiteSpace(model.RedirectUrl) ? "/" : model.RedirectUrl); 
    }
    else {
        return View(model);
    }
}

During the 30 seconds, I see, via SSH, that a journal file exists beside by SQLite DB file. It's eventually deleted.

UPDATE: Here are the logs. You can see, that after a single update call, a lock exception is thrown exactly 30 seconds later. 30 seconds is the SQL command timeout. I'm watching the file system using a remote SSH shell, and the journal file is there for ~30 seconds. It's like the combination of the network share used by the app service, and the SQLite file locking logic, is broken or very slow.

2018-12-20T15:06:27.660624755Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
2018-12-20T15:06:27.660656156Z       Request starting HTTP/1.1 POST http://insecuresite.azurewebsites.net/Account/SignIn application/x-www-form-urlencoded 56
2018-12-20T15:06:27.660797960Z [15:06:27 DBG] InsecureSite.Middleware.MyCookieAuthHandler:Constructor called.
2018-12-20T15:06:27.660875561Z [15:06:27 DBG] InsecureSite.Middleware.MyCookieAuthHandler:Constructor called.
2018-12-20T15:06:27.660885462Z [15:06:27 DBG] InsecureSite.Middleware.MyCookieAuthHandler:HandleAuthenticateAsync called.
2018-12-20T15:06:27.660890662Z [15:06:27 DBG] InsecureSite.Middleware.MyCookieAuthHandler:HandleAuthenticateAsync called.
2018-12-20T15:06:27.661837484Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
2018-12-20T15:06:27.661856585Z       Route matched with {action = "SignIn", controller = "Account"}. Executing action InsecureSite.Controllers.AccountController.SignIn (InsecureSite)
2018-12-20T15:06:27.662465200Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
2018-12-20T15:06:27.662478400Z       Executing action method InsecureSite.Controllers.AccountController.SignIn (InsecureSite) with arguments (InsecureSite.Models.SignInModel) - Validation state: Valid
2018-12-20T15:06:27.667736726Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Infrastructure[10403]
2018-12-20T15:06:27.667751427Z       Entity Framework Core 2.1.4-rtm-31024 initialized 'AppDbContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite' with options: None
2018-12-20T15:06:27.716864407Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20101]
2018-12-20T15:06:27.716886507Z       Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
2018-12-20T15:06:27.716892507Z       PRAGMA foreign_keys=ON;
2018-12-20T15:06:27.776374136Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20101]
2018-12-20T15:06:27.776410837Z       Executed DbCommand (59ms) [Parameters=[@__model_Email_0='?' (Size = 18)], CommandType='Text', CommandTimeout='30']
2018-12-20T15:06:27.776514640Z       SELECT "u"."UserId", "u"."FirstName", "u"."LastLogin", "u"."LastName", "u"."PasswordHash", "u"."UserName"
2018-12-20T15:06:27.776526140Z       FROM "Users" AS "u"
2018-12-20T15:06:27.776531140Z       WHERE "u"."UserName" = @__model_Email_0
2018-12-20T15:06:27.776536040Z       ORDER BY "u"."UserId"
2018-12-20T15:06:27.776540740Z       LIMIT 1
2018-12-20T15:06:27.778553489Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20101]
2018-12-20T15:06:27.778567689Z       Executed DbCommand (1ms) [Parameters=[@__model_Email_0='?' (Size = 18)], CommandType='Text', CommandTimeout='30']
2018-12-20T15:06:27.778840096Z       SELECT "u.Claims"."UserClaimId", "u.Claims"."Claim", "u.Claims"."UserId", "u.Claims"."Value"
2018-12-20T15:06:27.778852696Z       FROM "UserClaims" AS "u.Claims"
2018-12-20T15:06:27.778857796Z       INNER JOIN (
2018-12-20T15:06:27.778862596Z           SELECT "u0"."UserId"
2018-12-20T15:06:27.778869696Z           FROM "Users" AS "u0"
2018-12-20T15:06:27.778874396Z           WHERE "u0"."UserName" = @__model_Email_0
2018-12-20T15:06:27.778879897Z           ORDER BY "u0"."UserId"
2018-12-20T15:06:27.780228429Z           LIMIT 1
2018-12-20T15:06:27.780242129Z       ) AS "t" ON "u.Claims"."UserId" = "t"."UserId"
2018-12-20T15:06:27.780247829Z       ORDER BY "t"."UserId"
2018-12-20T15:06:27.789636555Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20101]
2018-12-20T15:06:27.789651955Z       Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
2018-12-20T15:06:27.789657656Z       PRAGMA foreign_keys=ON;
2018-12-20T15:06:27.794111763Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20101]
2018-12-20T15:06:27.794126763Z       Executed DbCommand (4ms) [Parameters=[@p1='?', @p0='?'], CommandType='Text', CommandTimeout='30']
2018-12-20T15:06:27.794132363Z       UPDATE "Users" SET "LastLogin" = @p0
2018-12-20T15:06:27.794280267Z       WHERE "UserId" = @p1;
2018-12-20T15:06:27.794298667Z       SELECT changes();

2018-12-20T15:06:57.833069471Z [41m[30mfail[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Transaction[20205]
2018-12-20T15:06:57.833107571Z       An error occurred using a transaction.
2018-12-20T15:06:57.833113572Z Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
2018-12-20T15:06:57.833118772Z    at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
2018-12-20T15:06:57.833123772Z    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
2018-12-20T15:06:57.833128672Z    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
2018-12-20T15:06:57.833133672Z    at Microsoft.Data.Sqlite.SqliteConnectionExtensions.ExecuteNonQuery(SqliteConnection connection, String commandText)
2018-12-20T15:06:57.833138672Z    at Microsoft.Data.Sqlite.SqliteTransaction.Commit()
2018-12-20T15:06:57.833143372Z    at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Commit()
2018-12-20T15:06:57.853805669Z [41m[30mfail[39m[22m[49m: Microsoft.EntityFrameworkCore.Update[10000]
2018-12-20T15:06:57.853833569Z       An exception occurred in the database while saving changes for context type 'InsecureSite.Data.AppDbContext'.
2018-12-20T15:06:57.853928072Z       Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
2018-12-20T15:06:57.853938272Z          at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
2018-12-20T15:06:57.853943572Z          at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
2018-12-20T15:06:57.854041474Z          at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
2018-12-20T15:06:57.854051475Z          at Microsoft.Data.Sqlite.SqliteConnectionExtensions.ExecuteNonQuery(SqliteConnection connection, String commandText)
2018-12-20T15:06:57.854056675Z          at Microsoft.Data.Sqlite.SqliteTransaction.Commit()
2018-12-20T15:06:57.854137377Z          at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Commit()
2018-12-20T15:06:57.854146577Z          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(DbContext _, ValueTuple`2 parameters, CancellationToken cancellationToken)
2018-12-20T15:06:57.854208178Z          at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IReadOnlyList`1 entriesToSave, CancellationToken cancellationToken)
2018-12-20T15:06:57.854283180Z          at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
2018-12-20T15:06:57.854292080Z          at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
2018-12-20T15:06:57.854299081Z Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
2018-12-20T15:06:57.854366282Z    at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
2018-12-20T15:06:57.854384483Z    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
2018-12-20T15:06:57.854389683Z    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
2018-12-20T15:06:57.854455384Z    at Microsoft.Data.Sqlite.SqliteConnectionExtensions.ExecuteNonQuery(SqliteConnection connection, String commandText)
2018-12-20T15:06:57.854463685Z    at Microsoft.Data.Sqlite.SqliteTransaction.Commit()
2018-12-20T15:06:57.854468185Z    at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Commit()
2018-12-20T15:06:57.854529686Z    at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(DbContext _, ValueTuple`2 parameters, CancellationToken cancellationToken)
2018-12-20T15:06:57.854652489Z    at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IReadOnlyList`1 entriesToSave, CancellationToken cancellationToken)
2018-12-20T15:06:57.854673890Z    at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
2018-12-20T15:06:57.854748391Z    at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
2018-12-20T15:06:57.858109772Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
2018-12-20T15:06:57.858123973Z       Executed action InsecureSite.Controllers.AccountController.SignIn (InsecureSite) in 30193.6715ms
2018-12-20T15:06:57.860885139Z [41m[30mfail[39m[22m[49m: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
2018-12-20T15:06:57.860899939Z       An unhandled exception has occurred while executing the request.
2018-12-20T15:06:57.860905239Z Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
2018-12-20T15:06:57.861009242Z    at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
2018-12-20T15:06:57.861018942Z    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior)
2018-12-20T15:06:57.861023842Z    at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery()
2018-12-20T15:06:57.861120545Z    at Microsoft.Data.Sqlite.SqliteConnectionExtensions.ExecuteNonQuery(SqliteConnection connection, String commandText)
2018-12-20T15:06:57.861130145Z    at Microsoft.Data.Sqlite.SqliteTransaction.Commit()
2018-12-20T15:06:57.861134745Z    at Microsoft.EntityFrameworkCore.Storage.RelationalTransaction.Commit()
2018-12-20T15:06:57.861237547Z    at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(DbContext _, ValueTuple`2 parameters, CancellationToken cancellationToken)
2018-12-20T15:06:57.861311249Z    at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IReadOnlyList`1 entriesToSave, CancellationToken cancellationToken)
2018-12-20T15:06:57.861320149Z    at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
2018-12-20T15:06:57.861392851Z    at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
2018-12-20T15:06:57.861401851Z    at InsecureSite.Controllers.AccountController.SignIn(SignInModel model) in /home/site/repository/InsecureSite/Controllers/AccountController.cs:line 57
2018-12-20T15:06:57.861463253Z    at Microsoft.AspNetCore.Mvc.Internal.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
2018-12-20T15:06:57.861472053Z    at System.Threading.Tasks.ValueTask`1.get_Result()
2018-12-20T15:06:57.861541855Z    at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeActionMethodAsync()
2018-12-20T15:06:57.861550055Z    at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeNextActionFilterAsync()
2018-12-20T15:06:57.861554655Z    at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Rethrow(ActionExecutedContext context)
2018-12-20T15:06:57.861629257Z    at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
2018-12-20T15:06:57.861639057Z    at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeInnerFilterAsync()
2018-12-20T15:06:57.861718659Z    at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeNextResourceFilter()
2018-12-20T15:06:57.861727059Z    at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Rethrow(ResourceExecutedContext context)
2018-12-20T15:06:57.861791861Z    at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
2018-12-20T15:06:57.861800861Z    at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeFilterPipelineAsync()
2018-12-20T15:06:57.861805561Z    at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeAsync()
2018-12-20T15:06:57.861810161Z    at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
2018-12-20T15:06:57.861880363Z    at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
2018-12-20T15:06:57.861888363Z    at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context)
2018-12-20T15:06:57.861948164Z    at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.Invoke(HttpContext context)
2018-12-20T15:06:57.862056667Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
2018-12-20T15:06:57.862066767Z       Route matched with {action = "Error", controller = "Home"}. Executing action InsecureSite.Controllers.HomeController.Error (InsecureSite)
2018-12-20T15:06:57.867899207Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
2018-12-20T15:06:57.867914108Z       Executing action method InsecureSite.Controllers.HomeController.Error (InsecureSite) - Validation state: Valid
2018-12-20T15:06:57.868025910Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
2018-12-20T15:06:57.868045011Z       Executed action method InsecureSite.Controllers.HomeController.Error (InsecureSite), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0771ms.
2018-12-20T15:06:57.868147613Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor[1]
2018-12-20T15:06:57.868157914Z       Executing ViewResult, running view Error.
2018-12-20T15:06:57.869182938Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor[4]
2018-12-20T15:06:57.869196139Z       Executed ViewResult - view Error executed in 7.5623ms.
2018-12-20T15:06:57.869201439Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
2018-12-20T15:06:57.869206339Z       Executed action InsecureSite.Controllers.HomeController.Error (InsecureSite) in 7.9125ms
2018-12-20T15:06:57.869222639Z [40m[32minfo[39m[22m[49m: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
2018-12-20T15:06:57.869228039Z       Request finished in 30208.5835ms 500 text/html; charset=utf-8

2018-12-20T15:08:44  No new trace in the past 1 min(s).

There is not any other requests hitting this web app. I am the only one making requests.

Controllers can read data from the DB file without errors. I see that a couple queries right before the failed write take 3ms and 6ms.

I saw there was an issue with locking and multiple threads, but it is fixed, and I'm on a later version from the fix (2.1.4)

Answer 1

Can you share your update method? sometimes database is locked because C# code does not use database connection/transaction appropriately.

I suggest you have a look at your update method and see if database connection and transaction is used correctly. microsoft documentation might help

using (var context = new BloggingContext())
{
    using (var transaction = context.Database.BeginTransaction())
    {
        try
        {
            context.Blogs.Add(new Blog { Url = "http://blogs.msdn.com/dotnet" });
            context.SaveChanges();

            context.Blogs.Add(new Blog { Url = "http://blogs.msdn.com/visualstudio" });
            context.SaveChanges();

            var blogs = context.Blogs
                .OrderBy(b => b.Url)
                .ToList();

            // Commit transaction if all commands succeed, transaction will auto-rollback
            // when disposed if either commands fails
            transaction.Commit();
        }
        catch (Exception)
        {
            // TODO: Handle failure
        }
    }
}

Answer 2

A solution for temporary databases

If the database file resides somewhere under /home (e.g. /home/Data/mydb.db or /home/site/wwwroot/mydb.db) the 'database is locked' error will occur. I think this is due that all files under /home are persisted and reside in Azure Storage. Explained here

As solution use a different path. E.g. /tmp/mydb.db. Or Path.Combine(Path.GetTempPath(), dbName);

Caveat: The db will be lost when the application restarts. So you can create the db in the temporary folder, then copy the db file to a persisted folder. Then access the db in the persisted folder with read only access. Add Mode=ReadOnly to the SQlite connection string (at least when using Microsoft.Data.Sqlite.SqliteConnection).

I fear there is no better solution when requiring Linux as OS. Microsoft should change this behaviour.

Answer 3

To someone who still facing this issue: Like @Josh mentioned, this is related to the Linux Azure App Service.

I also have a project, which is developed on my windows machine, and it works well, but when published to a Linux based Azure App Service, it will throw this error even for one simple INSERT from one request, I also confirmed from the App Service monitor that there is no con-current requests at that time.

I haven't figured out more details about the reason, but after changed the App Service to a Windows based, everything works well.