SQL server error

[talshafie]

Trying to deploy a single server Resgrid for a demo, however after running the docker up command below error is preventing me from logging into the application:

worker-1 | ClientConnectionId:989d275d-7df9-4c92-9302-459bd6111118 worker-1 | Error Number:208,State:1,Class:16 worker-1 | fail: Resgrid.Workers.Console.Program[0] worker-1 | System.Data.SqlClient.SqlException (0x80131904): Invalid object name 'dbo.Departments'. worker-1 | at System.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__126_0(Task1 result)
worker-1 | at System.Threading.Tasks.ContinuationResultTaskFromResultTask2.InnerInvoke() worker-1 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) worker-1 | --- End of stack trace from previous location --- worker-1 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) worker-1 | at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) worker-1 | --- End of stack trace from previous location --- worker-1 | at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 434 worker-1 | at Resgrid.Repositories.DataRepository.RepositoryBase1.b__5_0(DbConnection x) in /src/Repositories/Resgrid.Repositories.DataRepository/RepositoryBase.cs:line 45
worker-1 | at Resgrid.Repositories.DataRepository.RepositoryBase1.GetAllAsync() in /src/Repositories/Resgrid.Repositories.DataRepository/RepositoryBase.cs:line 57 worker-1 | at Resgrid.Services.DepartmentsService.GetAllAsync() in /src/Core/Resgrid.Services/DepartmentsService.cs:line 71 worker-1 | at Resgrid.Workers.Console.Tasks.StatusScheduleTask.ProcessAsync(StatusScheduleCommand command, IQuidjiboProgress progress, CancellationToken cancellationToken) in /src/Workers/Resgrid.Workers.Console/Tasks/StatusScheduleTask.cs:line 39 worker-1 | ClientConnectionId:989d275d-7df9-4c92-9302-459bd6111118 worker-1 | Error Number:208,State:1,Class:16 mongodb-1 | {"t":{"$date":"2025-03-07T05:41:39.422+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1741326099:422246][1:0x7fdaaa616700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 56, snapshot max: 56 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1267"}} worker-1 | [05:42:15 FTL] worker-1 | System.Data.SqlClient.SqlException (0x80131904): Invalid object name 'dbo.ScheduledTasks'. worker-1 | at System.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__126_0(Task1 result)
worker-1 | at System.Threading.Tasks.ContinuationResultTaskFromResultTask2.InnerInvoke() worker-1 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) worker-1 | --- End of stack trace from previous location --- worker-1 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) worker-1 | at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) worker-1 | --- End of stack trace from previous location --- worker-1 | at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 434 worker-1 | at Resgrid.Repositories.DataRepository.ScheduledTasksRepository.<GetAllUpcomingOrRecurringReportDeliveryTasksAsync>b__7_0(DbConnection x) in /src/Repositories/Resgrid.Repositories.DataRepository/ScheduledTasksRepository.cs:line 78 worker-1 | at Resgrid.Repositories.DataRepository.ScheduledTasksRepository.GetAllUpcomingOrRecurringReportDeliveryTasksAsync() in /src/Repositories/Resgrid.Repositories.DataRepository/ScheduledTasksRepository.cs:line 90

[welcome]

Thanks for opening this issue. A contributor should be by to give feedback soon. In the meantime, please check out the contributing guidelines.

[ucswift]

This appears related to #168 which I just pushed a fix for Resgrid/resgrid-setup@183162a. Please delete and reclone the resgrid-setup repo and try again.

[cw957]

I am also having this issue when attempting to log in. I am using the fixed version and still getting the this error. ERROR NUMBER:208, State:1, Class:16

worker-1 | [05:31:27 FTL]
worker-1 | System.Data.SqlClient.SqlException (0x80131904): Invalid object name 'dbo.Departments'.
worker-1 | at System.Data.SqlClient.SqlCommand.<>c.b__126_0(Task1 result) worker-1 | at System.Threading.Tasks.ContinuationResultTaskFromResultTask2.InnerInvoke()
worker-1 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
worker-1 | --- End of stack trace from previous location ---
worker-1 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
worker-1 | at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
worker-1 | --- End of stack trace from previous location ---
worker-1 | at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 434
worker-1 | at Resgrid.Repositories.DataRepository.RepositoryBase1.<GetAllAsync>b__5_0(DbConnection x) in /src/Repositories/Resgrid.Repositories.DataRepository/RepositoryBase.cs:line 45 worker-1 | at Resgrid.Repositories.DataRepository.RepositoryBase1.GetAllAsync() in /src/Repositories/Resgrid.Repositories.DataRepository/RepositoryBase.cs:line 57
worker-1 | ClientConnectionId:96cde7f0-b79e-4c32-870b-062bc6170e77
worker-1 | Error Number:208,State:1,Class:16

[ucswift]

@cw957 can you get the logs from earlier in the docker-compose process? It should be one of the first set of logs coming from the db container.

[cw957]

here is the start of the db container.

mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.026+00:00"},"s":"I", "c":"CONTROL", "id":23285, "ctx":"main","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.026+00:00"},"s":"I", "c":"NETWORK", "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"STORAGE", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":1,"port":27017,"dbPath":"/data/db","architecture":"64-bit","host":"b4bb113b7d8e"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"CONTROL", "id":23403, "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"4.4.18","gitVersion":"8ed32b5c2c68ebe7f8ae2ebe8d23f36037a17dea","openSSLVersion":"OpenSSL 1.1.1f 31 Mar 2020","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"CONTROL", "id":51765, "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Ubuntu","version":"20.04"}}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"CONTROL", "id":21951, "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"net":{"bindIp":"*"},"security":{"authorization":"enabled"}}}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"W", "c":"STORAGE", "id":22271, "ctx":"initandlisten","msg":"Detected unclean shutdown - Lock file is not empty","attr":{"lockFile":"/data/db/mongod.lock"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"STORAGE", "id":22270, "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/data/db","storageEngine":"wiredTiger"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"W", "c":"STORAGE", "id":22302, "ctx":"initandlisten","msg":"Recovering data from the last clean checkpoint."}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"STORAGE", "id":22297, "ctx":"initandlisten","msg":"Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem","tags":["startupWarnings"]}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.027+00:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=7279M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
redis-1 | 1:C 11 Mar 2025 23:37:07.156 # WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see jemalloc/jemalloc#1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.445+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:445300][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 7"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.462+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:462908][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 7 through 7"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.496+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:496598][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Main recovery loop: starting at 6/7552 to 7/256"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.496+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:496990][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 6 through 7"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.519+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:519483][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 7 through 7"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.534+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:534053][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Set global recovery timestamp: (0, 0)"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.534+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:534080][1:0x7f0ac0dfecc0], txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Set global oldest timestamp: (0, 0)"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.537+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1741736227:537819][1:0x7f0ac0dfecc0], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 3, snapshot max: 3 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 139"}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.549+00:00"},"s":"I", "c":"STORAGE", "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":522}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.549+00:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.551+00:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.563+00:00"},"s":"W", "c":"CONTROL", "id":22178, "ctx":"initandlisten","msg":"/sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'","tags":["startupWarnings"]}
mongodb-1 | {"t":{"$date":"2025-03-11T23:37:07.565+00:00"},"s":"I", "c":"STORAGE", "id":20536, "ctx":"initandlisten","msg":"Flow Control is enabled on this deployment"}

[ucswift]

Thanks for that! But the logs we need will be from the db container and not the MongoDB on (too many db's I know).

[cw957]

I hope this helps you.
The db-1 is

db-1 | SQL Server 2022 will run as non-root by default.
db-1 | This container is running as user root.
db-1 | Your master database file is owned by root.
db-1 | To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.
events-1 | [INFO wait] Host [db:1433] not yet available...
web-1 | [INFO wait] Host [db:1433] not yet available...
api-1 | [INFO wait] Host [db:1433] not yet available...
worker-1 | [INFO wait] Host [db:1433] not yet available...
worker-1 | [INFO wait] Host [db:1433] not yet available...
api-1 | [INFO wait] Host [db:1433] not yet available...
web-1 | [INFO wait] Host [db:1433] not yet available...
events-1 | [INFO wait] Host [db:1433] not yet available...
db-1 | 2025-03-11 23:11:11.78 Server Setup step is FORCE copying system data file 'C:\templatedata\model_replicatedmaster.mdf' to '/var/opt/mssql/data/model_replicatedmaster.mdf'.
2025-03-11 23:11:11.79 Server Setup step is FORCE copying system data file 'C:\templatedata\model_replicatedmaster.ldf' to '/var/opt/mssql/data/model_replicatedmaster.ldf'.
2025-03-11 23:11:11.80 Server Setup step is FORCE copying system data file 'C:\templatedata\model_msdbdata.mdf' to '/var/opt/mssql/data/model_msdbdata.mdf'.
2025-03-11 23:11:11.81 Server Setup step is FORCE copying system data file 'C:\templatedata\model_msdblog.ldf' to '/var/opt/mssql/data/model_msdblog.ldf'.
2025-03-11 23:11:11.83 Server Microsoft SQL Server 2022 (RTM-CU12) (KB5033663) - 16.0.4115.5 (X64)
db-1 Mar 4 2024 08:56:10
db-1 Copyright (C) 2022 Microsoft Corporation
db-1 Express Edition (64-bit) on Linux (Ubuntu 22.04.4 LTS)
2025-03-11 23:11:11.84 Server UTC adjustment: 0:00
2025-03-11 23:11:11.84 Server (c) Microsoft Corporation.
2025-03-11 23:11:11.84 Server All rights reserved.
2025-03-11 23:11:11.84 Server Server process ID is 616.
2025-03-11 23:11:11.84 Server Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2025-03-11 23:11:11.84 Server Registry startup parameters:
db-1 -d /var/opt/mssql/data/master.mdf
db-1 -l /var/opt/mssql/data/mastlog.ldf
db-1 -e /var/opt/mssql/log/errorlog
2025-03-11 23:11:11.84 Server SQL Server detected 1 sockets with 12 cores per socket and 24 logical processors per socket, 24 total logical processors; using 8 logical processors based on SQL Server licensing. This is an informational message; no user action is required.
2025-03-11 23:11:11.84 Server SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2025-03-11 23:11:11.84 Server Detected 12467 MB of RAM. This is an informational message; no user action is required.
2025-03-11 23:11:11.84 Server Using conventional memory in the memory manager.
2025-03-11 23:11:11.84 Server Detected pause instruction latency: 47 cycles.
2025-03-11 23:11:11.84 Server SQL Server detected the following NUMA node configuration (NUMA Node number 0, Processor Group number 0, CPU Mask 0x0000000000ffffff).
2025-03-11 23:11:11.84 Server Page exclusion bitmap is enabled.
2025-03-11 23:11:11.88 Server Buffer pool extension is not supported on Linux platform.
2025-03-11 23:11:11.88 Server Buffer Pool: Allocating 2097152 bytes for 1891470 hashPages.
2025-03-11 23:11:11.95 Server Buffer pool extension is already disabled. No action is necessary.
worker-1 | [INFO wait] Host [db:1433] not yet available...
api-1 | [INFO wait] Host [db:1433] not yet available...
events-1 | [INFO wait] Host [db:1433] not yet available...
web-1 | [INFO wait] Host [db:1433] not yet available...
2025-03-11 23:11:12.16 Server Installing Client TLS certificates to the store.
2025-03-11 23:11:12.16 Server CPU vectorization level(s) detected: SSE SSE2 SSE3 SSSE3 SSE41 SSE42 AVX AVX2 POPCNT BMI1 BMI2 AVX512 (F CD BW DQ VL IFMA VBMI VBMI2 VNNI BITALG VPOQCNTDQ BF16)
2025-03-11 23:11:12.21 Server Successfully initialized the TLS configuration. Allowed TLS protocol versions are ['1.0 1.1 1.2']. Allowed TLS ciphers are ['ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:!DHE-RSA-AES256-GCM-SHA384:!DHE-RSA-AES128-GCM-SHA256:!DHE-RSA-AES256-SHA:!DHE-RSA-AES128-SHA'].
2025-03-11 23:11:12.22 Server Query Store settings initialized with enabled = 1,
2025-03-11 23:11:12.23 Server The maximum number of dedicated administrator connections for this instance is '1'
2025-03-11 23:11:12.23 Server Node configuration: node 0: CPU mask: 0x00000000000000ff:0 Active CPU mask: 0x00000000000000ff:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.
2025-03-11 23:11:12.25 Server Using dynamic lock allocation. Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node. This is an informational message only. No user action is required.
2025-03-11 23:11:12.25 Server Lock partitioning is enabled. This is an informational message only. No user action is required.
2025-03-11 23:11:12.27 Server In-Memory OLTP initialized on standard machine.
2025-03-11 23:11:12.29 Server [INFO] Created Extended Events session 'hkenginexesession'
2025-03-11 23:11:12.29 Server Database Instant File Initialization: enabled. For security and performance considerations see the topic 'Database Instant File Initialization' in SQL Server Books Online. This is an informational message only. No user action is required.
ForceFlush is enabled for this instance.
2025-03-11 23:11:12.30 Server Total Log Writer threads: 2. This is an informational message; no user action is required.
2025-03-11 23:11:12.30 Server clwb is selected for pmem flush operation.
2025-03-11 23:11:12.30 Server Software Usage Metrics is disabled.
2025-03-11 23:11:12.31 spid27s [1]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-03-11 23:11:12.32 spid27s Starting up database 'master'.
2025-03-11 23:11:12.35 Server CLR version v4.0.30319 loaded.
ForceFlush feature is enabled for log durability.
2025-03-11 23:11:12.39 spid27s 81 transactions rolled forward in database 'master' (1:0). This is an informational message only. No user action is required.
2025-03-11 23:11:12.40 spid27s 0 transactions rolled back in database 'master' (1:0). This is an informational message only. No user action is required.
2025-03-11 23:11:12.40 spid27s Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
2025-03-11 23:11:12.48 spid27s SQL Server Audit is starting the audits. This is an informational message. No user action is required.
2025-03-11 23:11:12.48 spid27s SQL Server Audit has started the audits. This is an informational message. No user action is required.
2025-03-11 23:11:12.48 spid27s XE session 'system_health' started.
2025-03-11 23:11:12.50 spid27s XE session 'telemetry_xevents' started.
2025-03-11 23:11:12.51 spid27s SQL Trace ID 1 was started by login "sa".
2025-03-11 23:11:12.53 spid27s Server name is '6f2ba64848da'. This is an informational message only. No user action is required.
2025-03-11 23:11:12.55 Server External governance manager initialized
2025-03-11 23:11:12.55 spid42s Always On: The availability replica manager is starting. This is an informational message only. No user action is required.
2025-03-11 23:11:12.55 spid27s [4]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-03-11 23:11:12.56 spid42s Always On: The availability replica manager is waiting for the instance of SQL Server to allow client connections. This is an informational message only. No user action is required.
2025-03-11 23:11:12.56 spid27s Starting up database 'msdb'.
2025-03-11 23:11:12.56 spid29s [32767]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-03-11 23:11:12.56 spid29s Starting up database 'mssqlsystemresource'.
2025-03-11 23:11:12.57 spid29s The resource database build version is 16.00.4115. This is an informational message only. No user action is required.
2025-03-11 23:11:12.57 Server Common language runtime (CLR) functionality initialized.
2025-03-11 23:11:12.58 spid29s [3]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-03-11 23:11:12.58 spid29s Starting up database 'model'.
2025-03-11 23:11:12.61 spid27s 2 transactions rolled forward in database 'msdb' (4:0). This is an informational message only. No user action is required.
2025-03-11 23:11:12.62 spid27s 0 transactions rolled back in database 'msdb' (4:0). This is an informational message only. No user action is required.
2025-03-11 23:11:12.62 spid27s Recovery is writing a checkpoint in database 'msdb' (4). This is an informational message only. No user action is required.
2025-03-11 23:11:12.65 spid29s Clearing tempdb database.
2025-03-11 23:11:12.75 spid29s [2]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-03-11 23:11:12.75 spid29s Starting up database 'tempdb'.
2025-03-11 23:11:12.79 spid39s A self-generated certificate was successfully loaded for encryption.
2025-03-11 23:11:12.79 spid39s Server is listening on [ 'any' 1433] accept sockets 1.
2025-03-11 23:11:12.79 spid39s Server is listening on [ 'any' 1433] accept sockets 1.
2025-03-11 23:11:12.80 spid39s Dedicated administrator connection support was not started because it is disabled on this edition of SQL Server. If you want to use a dedicated administrator connection, restart SQL Server using the trace flag 7806. This is an informational message only. No user action is required.
2025-03-11 23:11:12.80 spid39s Server is listening on [ ::1 1431] accept sockets 1.
2025-03-11 23:11:12.80 spid39s Server is listening on [ 127.0.0.1 1431] accept sockets 1.
2025-03-11 23:11:12.80 spid39s SQL Server is now ready for client connections. This is an informational message; no user action is required.
2025-03-11 23:11:12.81 spid45s The Service Broker endpoint is in disabled or stopped state.
2025-03-11 23:11:12.81 spid45s The Database Mirroring endpoint is in disabled or stopped state.
2025-03-11 23:11:12.82 spid45s Service Broker manager has started.
2025-03-11 23:11:12.82 spid27s Recovery is complete. This is an informational message only. No user action is required

[cw957]

@ucswift Any update on this bug?

[camprosic]

Also still experiencing this exact behaviour with same logs - HTTP 500 error when trying to login for first time

[kc9mne]

I just did the installation today and got the same result here is the console of the DB container for comparison.

seems like the only error is something about the "Service Master Key" being in error.

resgrid:~/resgrid$ docker compose run db
SQL Server 2022 will run as non-root by default.
This container is running as user root.
Your master database file is owned by root.
To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.
2025-04-04 22:04:47.42 Server The licensing PID was successfully processed. The new edition is [Express Edition].
2025-04-04 22:04:47.57 Server Setup step is FORCE copying system data file 'C:\templatedata\model_replicatedmaster.mdf' to '/var/opt/mssql/data/model_replicatedmaster.mdf'.
2025-04-04 22:04:47.58 Server Setup step is FORCE copying system data file 'C:\templatedata\model_replicatedmaster.ldf' to '/var/opt/mssql/data/model_replicatedmaster.ldf'.
2025-04-04 22:04:47.59 Server Setup step is FORCE copying system data file 'C:\templatedata\model_msdbdata.mdf' to '/var/opt/mssql/data/model_msdbdata.mdf'.
2025-04-04 22:04:47.60 Server Setup step is FORCE copying system data file 'C:\templatedata\model_msdblog.ldf' to '/var/opt/mssql/data/model_msdblog.ldf'.
2025-04-04 22:04:47.62 Server Microsoft SQL Server 2022 (RTM-CU12) (KB5033663) - 16.0.4115.5 (X64)
Mar 4 2024 08:56:10
Copyright (C) 2022 Microsoft Corporation
Express Edition (64-bit) on Linux (Ubuntu 22.04.4 LTS)
2025-04-04 22:04:47.62 Server UTC adjustment: 0:00
2025-04-04 22:04:47.63 Server (c) Microsoft Corporation.
2025-04-04 22:04:47.63 Server All rights reserved.
2025-04-04 22:04:47.63 Server Server process ID is 464.
2025-04-04 22:04:47.63 Server Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2025-04-04 22:04:47.63 Server Registry startup parameters:
-d /var/opt/mssql/data/master.mdf
-l /var/opt/mssql/data/mastlog.ldf
-e /var/opt/mssql/log/errorlog
2025-04-04 22:04:47.63 Server SQL Server detected 1 sockets with 4 cores per socket and 8 logical processors per socket, 8 total logical processors; using 8 logical processors based on SQL Server licensing. This is an informational message; no user action is required.
2025-04-04 22:04:47.64 Server SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2025-04-04 22:04:47.64 Server Detected 12456 MB of RAM. This is an informational message; no user action is required.
2025-04-04 22:04:47.64 Server Using conventional memory in the memory manager.
2025-04-04 22:04:47.64 Server Detected pause instruction latency: 64 cycles.
2025-04-04 22:04:47.64 Server SQL Server detected the following NUMA node configuration (NUMA Node number 0, Processor Group number 0, CPU Mask 0x00000000000000ff).
2025-04-04 22:04:47.64 Server Page exclusion bitmap is enabled.
2025-04-04 22:04:47.67 Server Buffer pool extension is not supported on Linux platform.
2025-04-04 22:04:47.68 Server Buffer Pool: Allocating 2097152 bytes for 1922807 hashPages.
2025-04-04 22:04:47.80 Server Buffer pool extension is already disabled. No action is necessary.
2025-04-04 22:04:48.22 Server Installing Client TLS certificates to the store.
2025-04-04 22:04:48.23 Server CPU vectorization level(s) detected: SSE SSE2 SSE3 SSSE3 SSE41 SSE42 AVX AVX2 POPCNT BMI1 BMI2 AVX512 (F CD BW DQ VL IFMA VBMI VBMI2 VNNI BITALG VPOQCNTDQ)
2025-04-04 22:04:48.27 Server Successfully initialized the TLS configuration. Allowed TLS protocol versions are ['1.0 1.1 1.2']. Allowed TLS ciphers are ['ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:!DHE-RSA-AES256-GCM-SHA384:!DHE-RSA-AES128-GCM-SHA256:!DHE-RSA-AES256-SHA:!DHE-RSA-AES128-SHA'].
2025-04-04 22:04:48.29 Server Query Store settings initialized with enabled = 1,
2025-04-04 22:04:48.30 Server The maximum number of dedicated administrator connections for this instance is '1'
2025-04-04 22:04:48.31 Server Node configuration: node 0: CPU mask: 0x00000000000000ff:0 Active CPU mask: 0x00000000000000ff:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.
2025-04-04 22:04:48.33 Server Using dynamic lock allocation. Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node. This is an informational message only. No user action is required.
2025-04-04 22:04:48.35 Server In-Memory OLTP initialized on standard machine.
2025-04-04 22:04:48.37 Server [INFO] Created Extended Events session 'hkenginexesession'
2025-04-04 22:04:48.38 Server Database Instant File Initialization: enabled. For security and performance considerations see the topic 'Database Instant File Initialization' in SQL Server Books Online. This is an informational message only. No user action is required.
ForceFlush is enabled for this instance.
2025-04-04 22:04:48.39 Server Total Log Writer threads: 2. This is an informational message; no user action is required.
2025-04-04 22:04:48.40 Server clwb is selected for pmem flush operation.
2025-04-04 22:04:48.40 Server Software Usage Metrics is disabled.
2025-04-04 22:04:48.41 spid27s [1]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-04-04 22:04:48.41 spid27s Starting up database 'master'.
2025-04-04 22:04:48.43 Server CLR version v4.0.30319 loaded.
ForceFlush feature is enabled for log durability.
2025-04-04 22:04:48.47 spid27s 39 transactions rolled forward in database 'master' (1:0). This is an informational message only. No user action is required.
2025-04-04 22:04:48.48 spid27s 0 transactions rolled back in database 'master' (1:0). This is an informational message only. No user action is required.
2025-04-04 22:04:48.48 spid27s Recovery is writing a checkpoint in database 'master' (1). This is an informational message only. No user action is required.
2025-04-04 22:04:48.54 spid27s Service Master Key could not be decrypted using one of its encryptions. See sys.key_encryptions for details.
2025-04-04 22:04:48.54 spid27s An error occurred during Service Master Key initialization. SQLErrorCode=33095, State=14, LastOsError=2.
2025-04-04 22:04:48.57 spid27s SQL Server Audit is starting the audits. This is an informational message. No user action is required.
2025-04-04 22:04:48.57 spid27s SQL Server Audit has started the audits. This is an informational message. No user action is required.
2025-04-04 22:04:48.57 spid27s XE session 'system_health' started.
2025-04-04 22:04:48.61 spid27s XE session 'telemetry_xevents' started.
2025-04-04 22:04:48.62 spid27s SQL Trace ID 1 was started by login "sa".
2025-04-04 22:04:48.63 spid27s Server name is '78f30b41b0ae'. This is an informational message only. No user action is required.
2025-04-04 22:04:48.66 spid40s Always On: The availability replica manager is starting. This is an informational message only. No user action is required.
2025-04-04 22:04:48.66 spid27s [4]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-04-04 22:04:48.66 spid29s [32767]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-04-04 22:04:48.66 spid40s Always On: The availability replica manager is waiting for the instance of SQL Server to allow client connections. This is an informational message only. No user action is required.
2025-04-04 22:04:48.67 spid27s Starting up database 'msdb'.
2025-04-04 22:04:48.67 spid29s Starting up database 'mssqlsystemresource'.
2025-04-04 22:04:48.68 spid29s The resource database build version is 16.00.4115. This is an informational message only. No user action is required.
2025-04-04 22:04:48.70 spid29s [3]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-04-04 22:04:48.70 spid29s Starting up database 'model'.
2025-04-04 22:04:48.73 Server Common language runtime (CLR) functionality initialized.
2025-04-04 22:04:48.74 spid27s Recovery is writing a checkpoint in database 'msdb' (4). This is an informational message only. No user action is required.
2025-04-04 22:04:48.76 spid29s Clearing tempdb database.
2025-04-04 22:04:48.78 Server External governance manager initialized
2025-04-04 22:04:48.85 spid29s [2]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2025-04-04 22:04:48.86 spid29s Starting up database 'tempdb'.
2025-04-04 22:04:48.91 spid45s The Service Broker endpoint is in disabled or stopped state.
2025-04-04 22:04:48.91 spid45s The Database Mirroring endpoint is in disabled or stopped state.
2025-04-04 22:04:48.92 spid45s Service Broker manager has started.
2025-04-04 22:04:49.28 spid39s A self-generated certificate was successfully loaded for encryption.
2025-04-04 22:04:49.28 spid39s Server is listening on [ 'any' 1433] accept sockets 1.
2025-04-04 22:04:49.28 spid39s Server is listening on [ 'any' 1433] accept sockets 1.
2025-04-04 22:04:49.28 spid39s Dedicated administrator connection support was not started because it is disabled on this edition of SQL Server. If you want to use a dedicated administrator connection, restart SQL Server using the trace flag 7806. This is an informational message only. No user action is required.
2025-04-04 22:04:49.29 spid39s Server is listening on [ ::1 1431] accept sockets 1.
2025-04-04 22:04:49.29 spid39s Server is listening on [ 127.0.0.1 1431] accept sockets 1.
2025-04-04 22:04:49.29 spid39s Recovery is complete. This is an informational message only. No user action is required.
2025-04-04 22:04:49.29 spid39s SQL Server is now ready for client connections. This is an informational message; no user action is required.
2025-04-04 22:04:53.57 spid28s Attribute synchronization initialized
2025-04-04 22:04:53.57 spid28s Attribute synchronization manager initialized