Sqlite DB Locked on Azure Dotnet Core Entity Framework

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)

This is most often caused by open or pending connection requests that couldn't be processed because of some earlier process grabbing up the lock. You can try the following implementation, using which connection and commands can be disposed correctly in order.

private static void ExecuteNonQuery(string queryString)
{
    using (var connection = new SQLiteConnection(
               ConnectionString))
    {
        using (var command = new SQLiteCommand(queryString, connection))
        {
            command.Connection.Open();
            command.ExecuteNonQuery();
        }
    }
}