🐙
【Docker】Microsoft SQL ServerのDBコンテナがすぐ停止してしまう
概要
プロジェクトの環境構築時、docker compose up -dで立ち上げたSQL ServerのDBコンテナがすぐに終了してしまう事象に遭遇しました。
解消するのに結構かかってしまったのでまとめます。
結論
マウントするディレクトリが誤っていた
修正前
volumes:
- volume:/var/opt/mssql/data
修正後
volumes:
- volume:/var/opt/mssql
調査
エラーログ
database | SQL Server 2022 will run as non-root by default.
database | This container is running as user root.
database | Your master database file is owned by root.
database | To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.
database | 2023-10-17 00:26:40.89 Server Setup step is FORCE copying system data file 'C:\templatedata\model_replicatedmaster.mdf' to '/var/opt/mssql/data/model_replicatedmaster.mdf'.
2023-10-17 00:26:40.96 Server Setup step is FORCE copying system data file 'C:\templatedata\model_replicatedmaster.ldf' to '/var/opt/mssql/data/model_replicatedmaster.ldf'.
2023-10-17 00:26:40.97 Server Setup step is FORCE copying system data file 'C:\templatedata\model_msdbdata.mdf' to '/var/opt/mssql/data/model_msdbdata.mdf'.
2023-10-17 00:26:41.00 Server Setup step is FORCE copying system data file 'C:\templatedata\model_msdblog.ldf' to '/var/opt/mssql/data/model_msdblog.ldf'.
2023-10-17 00:26:41.05 Server Microsoft SQL Server 2022 (RTM-CU9) (KB5030731) - 16.0.4085.2 (X64)
syndicatSep 27 2023 12:05:43
syndicatCopyright (C) 2022 Microsoft Corporation
syndicatDeveloper Edition (64-bit) on Linux (Ubuntu 20.04.6 LTS) <X64>
2023-10-17 00:26:41.06 Server UTC adjustment: 0:00
2023-10-17 00:26:41.06 Server (c) Microsoft Corporation.
2023-10-17 00:26:41.06 Server All rights reserved.
2023-10-17 00:26:41.06 Server Server process ID is 384.
2023-10-17 00:26:41.06 Server Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2023-10-17 00:26:41.06 Server Registry startup parameters:
syndicat -d /var/opt/mssql/data/master.mdf
syndicat -l /var/opt/mssql/data/mastlog.ldf
syndicat -e /var/opt/mssql/log/errorlog
2023-10-17 00:26:41.07 Server SQL Server detected 1 sockets with 2 cores per socket and 4 logical processors per socket, 4 total logical processors; using 4 logical processors based on SQL Server licensing. This is an informational message; no user action is required.
2023-10-17 00:26:41.07 Server SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2023-10-17 00:26:41.08 Server Detected 1584 MB of RAM. This is an informational message; no user action is required.
2023-10-17 00:26:41.09 Server Using conventional memory in the memory manager.
2023-10-17 00:26:41.09 Server Detected pause instruction latency: 140 cycles.
2023-10-17 00:26:41.09 Server Page exclusion bitmap is enabled.
2023-10-17 00:26:41.14 Server Buffer pool extension is not supported on Linux platform.
2023-10-17 00:26:41.15 Server Buffer Pool: Allocating 262144 bytes for 152053 hashPages.
2023-10-17 00:26:41.33 Server Buffer pool extension is already disabled. No action is necessary.
2023-10-17 00:26:41.80 Server Installing Client TLS certificates to the store.
2023-10-17 00:26:41.81 Server Error searching first file in /var/opt/mssql/security/ca-certificates: 3(The system cannot find the path specified.)
2023-10-17 00:26:41.82 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)
2023-10-17 00:26:41.89 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'].
2023-10-17 00:26:41.92 Server Query Store settings initialized with enabled = 1,
2023-10-17 00:26:41.94 Server The maximum number of dedicated administrator connections for this instance is '1'
2023-10-17 00:26:41.94 Server Node configuration: node 0: CPU mask: 0x000000000000000f:0 Active CPU mask: 0x000000000000000f:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.
2023-10-17 00:26:41.96 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.
2023-10-17 00:26:41.98 Server In-Memory OLTP initialized on lowend machine.
2023-10-17 00:26:42.00 Server [INFO] Created Extended Events session 'hkenginexesession'
2023-10-17 00:26:42.00 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.
2023-10-17 00:26:42.01 Server Total Log Writer threads: 2. This is an informational message; no user action is required.
2023-10-17 00:26:42.02 Server clwb is selected for pmem flush operation.
2023-10-17 00:26:42.03 Server Software Usage Metrics is disabled.
2023-10-17 00:26:42.05 spid18s [1]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2023-10-17 00:26:42.05 spid18s Starting up database 'master'.
2023-10-17 00:26:42.09 Server CLR version v4.0.30319 loaded.
ForceFlush feature is enabled for log durability.
2023-10-17 00:26:42.24 spid18s Service Master Key could not be decrypted using one of its encryptions. See sys.key_encryptions for details.
2023-10-17 00:26:42.24 spid18s An error occurred during Service Master Key initialization. SQLErrorCode=33095, State=14, LastOsError=2.
2023-10-17 00:26:42.26 spid21s [32767]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2023-10-17 00:26:42.26 spid21s Starting up database 'mssqlsystemresource'.
2023-10-17 00:26:42.26 spid18s [32762]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2023-10-17 00:26:42.27 spid21s The resource database build version is 16.00.4085. This is an informational message only. No user action is required.
2023-10-17 00:26:42.27 spid18s Starting up database 'model_replicatedmaster'.
2023-10-17 00:26:42.34 spid21s [3]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1. ConcurrentGAMUpdate: 1. ConcurrentSGAMUpdate: 1, CleanupUnderUserTransaction: 0. TranLevelPVS: 0
2023-10-17 00:26:42.35 spid21s Starting up database 'model'.
2023-10-17 00:26:42.36 spid18s The tail of the log for database model_replicatedmaster is being rewritten to match the new sector size of 4096 bytes. 2560 bytes at offset 99840 in file /var/opt/mssql/data/model_replicatedmaster.ldf will be written.
2023-10-17 00:26:42.36 spid21s Failed to get the volume information, -1073741772
2023-10-17 00:26:42.40 spid21s Failed to get the volume information, -1073741772
2023-10-17 00:26:42.41 spid21s Error: 17204, Severity: 16, State: 1.
2023-10-17 00:26:42.41 spid21s FCB::Open failed: Could not open file D:\dbs\sh\5uj5\0927_115209\cmd\2a\obj\x64retail\sql\mkmastr\databases\mkmastr.nativeproj\model.mdf for file number 1. OS error: 2(The
system cannot find the file specified.).
2023-10-17 00:26:42.43 spid18s Converting database 'model_replicatedmaster' from version 927 to the current version 957.
2023-10-17 00:26:42.43 spid21s Error: 5120, Severity: 16, State: 101.
2023-10-17 00:26:42.43 spid21s Unable to open the physical file "D:\dbs\sh\5uj5\0927_115209\cmd\2a\obj\x64retail\sql\mkmastr\databases\mkmastr.nativeproj\model.mdf". Operating system error 2: "2(The system cannot find the file specified.)".
2023-10-17 00:26:42.43 spid18s Database 'model_replicatedmaster' running the upgrade step from version 927 to version 928.
2023-10-17 00:26:42.44 spid28s A self-generated certificate was successfully loaded for encryption.
2023-10-17 00:26:42.46 spid28s Server is listening on [ 'any' <ipv6> 1433] accept sockets 1.
2023-10-17 00:26:42.46 spid21s Failed to get the volume information, -1073741772
2023-10-17 00:26:42.46 spid28s Server is listening on [ 'any' <ipv4> 1433] accept sockets 1.
2023-10-17 00:26:42.47 Server Server is listening on [ ::1 <ipv6> 1434] accept sockets 1.
2023-10-17 00:26:42.47 Server Server is listening on [ 127.0.0.1 <ipv4> 1434] accept sockets 1.
2023-10-17 00:26:42.48 Server Dedicated admin connection support was established for listening locally on port 1434.
2023-10-17 00:26:42.48 spid21s Failed to get the volume information, -1073741772
2023-10-17 00:26:42.48 spid21s Error: 17207, Severity: 16, State: 1.
2023-10-17 00:26:42.48 spid21s FileMgr::StartLogFiles: Operating system error 2(The system cannot find the file specified.) occurred while creating or opening file 'D:\dbs\sh\5uj5\0927_115209\cmd\2a\obj\x64retail\sql\mkmastr\databases\mkmastr.nativeproj\modellog.ldf'. Diagnose and correct the operating system error, and retry the operation.
2023-10-17 00:26:42.48 spid28s Server is listening on [ ::1 <ipv6> 1431] accept sockets 1.
2023-10-17 00:26:42.49 spid21s File activation failure. The physical file name "D:\dbs\sh\5uj5\0927_115209\cmd\2a\obj\x64retail\sql\mkmastr\databases\mkmastr.nativeproj\modellog.ldf" may be incorrect.
2023-10-17 00:26:42.49 spid28s Server is listening on [ 127.0.0.1 <ipv4> 1431] accept sockets 1.
2023-10-17 00:26:42.49 spid18s Database 'model_replicatedmaster' running the upgrade step from version 928 to version 929.
2023-10-17 00:26:42.49 spid21s Error: 945, Severity: 14, State: 2.
2023-10-17 00:26:42.49 spid21s Database 'model' cannot be opened due to inaccessible files or insufficient memory or disk space. See the SQL Server errorlog for details.
2023-10-17 00:26:42.50 spid28s SQL Server is now ready for client connections. This is an informational message; no user action is required.
2023-10-17 00:26:42.51 Server Common language runtime (CLR) functionality initialized.
Sqlcmd: Error: Microsoft ODBC Driver 17 for SQL Server : Login timeout expired.
database | Sqlcmd: Error: Microsoft ODBC Driver 17 for SQL Server : TCP Provider: Error code 0x2749.
database | Sqlcmd: Error: Microsoft ODBC Driver 17 for SQL Server : A network-related or instance-specific error has occurred while establishing a connection to SQL Server. Server is not found or not accessible. Check if instance name is correct and if SQL Server is configured to allow remote connections. For more information see SQL Server Books Online..
試したこと
こちらの記事を参考にvolumesを変更したところ、停止しなくなったためvolumesの問題だと判明しました。
volumes:
- './docker/db/data:/var/opt/mssql/data'
- './docker/db/log:/var/opt/mssql/log'
- './docker/db/secrets:/var/opt/mssql/secrets'
修正前では/var/opt/mssql/dataのみをマウントしていましたが、他のファイルもマウントする必要があるようです。
※公式にも書いてある
docker run -e 'ACCEPT_EULA=Y' -e 'MSSQL_SA_PASSWORD=<YourStrong!Passw0rd>' -p 1433:1433 -v sqlvolume:/var/opt/mssql -d mcr.microsoft.com/mssql/server:2022-latest
よってvolumesを冒頭のように修正したところ解消しました。
参考
Discussion