question

WernerMairl-2597 avatar image
0 Votes"
WernerMairl-2597 asked ryanchill commented

Azure Web App Linux Container WEBSITES_ENABLE_APP_SERVICE_STORAGE=true Warmup timeout error

Hi

I have a docker container with a asp net core 3.1 app inside (using SQLite with files stored on /home/db.sqlite)


The app is up and running without problems - with WEBSITES_ENABLE_APP_SERVICE_STORAGE==false.


If i change this setting to true then the container start fails with a timout during warmup.

there is no additional info/exception :
- not in Application Inside
- not in Console Log (i have access to docker console log) and log filters are off


the app looks like frozen!

Any idea ?


btw: with "mount storage (preview)" i have the same problems, so the issue may releated to the mounting in general.


Other observations: my app should create sqlite files on the mount: they are there .. that means basic write access is working.

But no idea why the entire app is "frozen" and not able to produce a output (trace levels at maximum).

(Frozen means: WebHostbuilder.Run has started, EF-Migrations are executed and then NO HTTPresponses (Warmup and others).....


WITHOUT mount or WEBSITES_ENABLE_APP_SERVICE_STORAGE everything is working....

any help/idea is welcome

regards
Werner







azure-webapps
· 7
5 |1600 characters needed characters left characters exceeded
Toggle Comment visibility. Current Visibility: Visible to all users

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

ryanchill avatar image ryanchill ·

Hi @WernerMairl-2597, thanks for reaching out on Q&A. As a short-term quick fix, have you tried adjusting the container wait time to max by setting WEBSITES_CONTAINER_START_TIME_LIMIT = 1800? Under "mount storage (preview)", is your storage and dockerfile configured similar to the screenshot below?

I also realize that there was nothing in the logs, but could you include a snippet of the docker log when the container is starting up?

mount storage-preview


0 Votes 0 ·
WernerMairl-2597 avatar image WernerMairl-2597 ·

observation: 1. App stopped 2. deleted /home/LogFiles manually via Kudu/Bash 3. Rebuilded docker container (more traces/some try to fix, configured to ignore external (mounted storage). 4. app restart (starttime limit 90 seconds, default duration 15 seconds) btw: debug-logging to azure azure storage is on and has created content on the last sucessful run


app start


after 15 minutes: app not available, empty files inside /home/LogFiles, no debug output inside azu storage


2 hours later (long break): app available, logs available....: assumtion: there was NO process taking 2 hours, but during the two ours the container may be stopped by the runtime (F1 Plan) and the restart after ~2hours was working fine!


here the log from this startup (2 minutes including docker pull) https://gist.github.com/WernerMairl/2865d4f0f2cbaf7efa83d5101ad1bd15


0 Votes 0 ·
WernerMairl-2597 avatar image WernerMairl-2597 ·

Other observations: issues during Connectionstring-bindings CUSTOMCONSTR not transparent - but not always (needs more investigation)


Next step: changed configuration (connectsrtring setting) and restart => seems to need endless... next try: waiting for 1-2 hours


0 Votes 0 ·
WernerMairl-2597 avatar image WernerMairl-2597 ·

waiting 15 minutes and container is up and running..... here the log:


https://gist.github.com/WernerMairl/a87433d1adcf7753b592e9efbf61e8d5


Timestamp 2020-01-03 08:43:20.949: my restart via Config change Timestamp 2020-01-03 08:44:56.549: runtime gives up, warmup takes to long multiple "docker run" are following, without success (same problem) The last one at timestampt "2020-01-03 09:05:03.632" is successful... BUT WHY ???


at timestamp "Timestamp 2020-01-03 08:44:56.549" the ConsoleLog shows that WebHost.Run was called but NO OTHER output....


checking new ideas....


0 Votes 0 ·
WernerMairl-2597 avatar image WernerMairl-2597 ·

Finding 1/assumption:


i had implemented a QueuedHostedService using Microsoft.Extensions.Hosting and BackgroundService....


After deactivating this service inside DI the app start seems to be stable (1 minute)... needs more verification....


System.Environment.ProcessorCount inside my app returns "1"... basically that follows the original idea of docker... may be a sideeffect to the TaskScheduler engine.....


Finding2: Injection of connectionstrings is not stable. I get different values for connectionstrings inside my app after restart (restart caused by only ONE change on another appsetting).... needs mor investigations


0 Votes 0 ·
Show more comments

2 Answers

WernerMairl-2597 avatar image
0 Votes"
WernerMairl-2597 answered

thanks for answering!
assuming i have multiple problems on the same time... try to sort out and give more info!

my dockerfile basically looks like the following:

 FROM mcr.microsoft.com/dotnet/core/aspnet:3.1 AS base
 WORKDIR /app
 EXPOSE 80
    
 FROM mcr.microsoft.com/dotnet/core/sdk:3.1 as dotnet-build
 WORKDIR /src
    
 FROM dotnet-build as publish
 WORKDIR /src
 COPY . .
    
 ARG BUILD_VERBOSITY=quiet
 ARG BUILD_CONFIGURATION=Release
    
 RUN chmod +x ./cli-linux/build-inside-docker.sh
 RUN ./cli-linux/build-inside-docker.sh $BUILD_VERBOSITY $BUILD_CONFIGURATION
    
 FROM base AS final
    
 ENV ConnectionStrings:TrailDB="Data Source=/home/trail365_dockerized2.sqlite"
 ENV ConnectionStrings:IdentityDB="Data Source=/home/identity365_default.sqlite"
 ENV ConnectionStrings:TaskDB="Data Source=/home/task365_default.sqlite"
    
 WORKDIR /app
 COPY --from=publish /app .
 ENTRYPOINT ["dotnet", "MSS.Trail365.Web.dll"]

means: workdir points to /app... no need to use external storage.
the only place where i need external storage is inside connectionstrings.

5 |1600 characters needed characters left characters exceeded
Toggle Comment visibility. Current Visibility: Visible to all users

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

WernerMairl-2597 avatar image
0 Votes"
WernerMairl-2597 answered

Back to the roots....improved my understanding around azure appservices, configs and restarts... but the core issue is remaining:

if i'm touching files inside external storage (mount) then the process seems to be stopped/freezing without any warning exception whatever......

I have configured a console logger (DefaultLevel "Trace") that produces a lot of outputs on every run.

if i'm starting the app with a configuration that uses the external storage (mount) then the console log looks like:

 2020-01-03T15:31:41.384933633Z Start WebHost building...
 2020-01-03T15:31:44.788643822Z WebHost building completed!
 2020-01-03T15:31:44.916356770Z [40m[37mdbug[39m[22m[49m: Microsoft.AspNetCore.Hosting.Diagnostics[3]
 2020-01-03T15:31:44.916382871Z       Hosting starting
 2020-01-03T15:31:45.342696684Z TryGetSqliteFileInfo: cn='Data Source=/usr/local/ttt/traildb.sqlite'
 2020-01-03T15:31:45.394074712Z TryGetSqliteFileInfo: fileName(raw)='/usr/local/ttt/traildb.sqlite'
 2020-01-03T15:31:45.428541705Z TryGetSqliteFileInfo: fileName(full)='/usr/local/ttt/traildb.sqlite', exists=False, directory.exists=True
 2020-01-03T15:31:45.429057821Z TryGetSqliteFileInfo: cn='Data Source=/usr/local/ttt/identity365_2.sqlite'
 2020-01-03T15:31:45.429437633Z TryGetSqliteFileInfo: fileName(raw)='/usr/local/ttt/identity365_2.sqlite'
 2020-01-03T15:31:45.432625034Z TryGetSqliteFileInfo: fileName(full)='/usr/local/ttt/identity365_2.sqlite', exists=False, directory.exists=True
 2020-01-03T15:31:45.977938419Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Infrastructure[10401]
 2020-01-03T15:31:45.977974620Z       An 'IServiceProvider' was created for internal use by Entity Framework.
 2020-01-03T15:31:49.021498792Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Model.Validation[10600]
 2020-01-03T15:31:49.171148035Z [40m[32minfo[39m[22m[49m: Microsoft.EntityFrameworkCore.Infrastructure[10403]
 2020-01-03T15:31:49.171187236Z       Entity Framework Core 3.1.0 initialized 'TrailContext' using provider 'Microsoft.EntityFrameworkCore.Sqlite' with options: None
 2020-01-03T15:31:49.443511168Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20000]
 2020-01-03T15:31:49.443549270Z       Opening connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.481590875Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20004]
 2020-01-03T15:31:49.481624176Z       An error occurred using the connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.492641526Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Migrations[20400]
 2020-01-03T15:31:49.492657026Z       Migrating using database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.499777352Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20000]
 2020-01-03T15:31:49.499808253Z       Opening connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.502823448Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20004]
 2020-01-03T15:31:49.502854449Z       An error occurred using the connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.502963153Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20000]
 2020-01-03T15:31:49.502995854Z       Opening connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.508050314Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20004]
 2020-01-03T15:31:49.508086615Z       An error occurred using the connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:49.508872940Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20000]
 2020-01-03T15:31:49.508901841Z       Opening connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:55.674989889Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Connection[20001]
 2020-01-03T15:31:55.675035691Z       Opened connection to database 'main' on server '/usr/local/ttt/traildb.sqlite'.
 2020-01-03T15:31:55.721498564Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20103]
 2020-01-03T15:31:55.721533665Z       Creating DbCommand for 'ExecuteNonQuery'.
 2020-01-03T15:31:55.781808675Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20104]
 2020-01-03T15:31:55.781884878Z       Created DbCommand for 'ExecuteNonQuery' (31ms).
 2020-01-03T15:31:55.793603149Z [40m[37mdbug[39m[22m[49m: Microsoft.EntityFrameworkCore.Database.Command[20100]
 2020-01-03T15:31:55.793637850Z       Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='1800']
 2020-01-03T15:31:55.793655351Z       PRAGMA journal_mode = 'wal';
    
 2020-01-03T15:37:08.045257948Z Trail 365 0.7.977


Process ended at Timestamp: 2020-01-03T15:31:55.793655351!!!!


Timestamp 2020-01-03T15:37:08.045257948Z Trail 365 0.7.977 is the first line after restart seven minutes later









5 |1600 characters needed characters left characters exceeded
Toggle Comment visibility. Current Visibility: Visible to all users

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.