Broken docker compose output for SQL Server container logs

mloskot · August 5, 2023, 2:54pm

I’m running container from mcr.microsoft.com/mssql/server:2022-latest images using docker compose and the log stream output is completely messed, regardless of command line environment used.
What could be the reason? Is this the container image issue or Docker Compose on Windows issue?

Git Bash

image823×697 15.5 KB
PowerShell 7

image843×380 10.1 KB
Commnad Prompt

image791×688 25 KB

rimelek · August 6, 2023, 9:03am

That is really odd.

– Have you tried to check the logs using docker logs instead of docker compose logs?
– Have you tried other images to see if it happens with those too?

update:

Thanks to @meyay I realized you are most likely using Linux containers already so I removed my last question from the list.

meyay · August 6, 2023, 10:02am

I use this minimal compose file to test the output:

services:
  mssql:
    image: mcr.microsoft.com/mssql/server:2022-latest
    environment:
      ACCEPT_EULA: "true"

Regardless whether I run it inside a Linux vm with docker-ce using a putty terminal, or Docker Desktop 4.21.1 (I tried 4.20.1 as well) using a Powershell terminal, the output looks like this:

docker compose up
[+] Running 4/4
 - mssql Pulled                                                                                                                                 30.4s
   - bbfe84ab0c13 Pull complete                                                                                                                  6.3s
   - fd849ceae6e5 Pull complete                                                                                                                 25.0s
   - d40626ee3ec6 Pull complete                                                                                                                 29.0s
[+] Running 2/2
 - Network mssql_default    Created                                                                                                              0.1s
 - Container mssql-mssql-1  Created                                                                                                              0.8s
Attaching to mssql-mssql-1
mssql-mssql-1  | SQL Server 2022 will run as non-root by default.
mssql-mssql-1  | This container is running as user mssql.
mssql-mssql-1  | To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.
mssql-mssql-1  | 2023-08-06 09:34:57.62 Server      Setup step is copying system data file 'C:\templatedata\master.mdf' to '/var/opt/mssql/data/master.mdf'.
2023-08-06 09:34:58.12 Server      Did not find an existing master data file /var/opt/mssql/data/master.mdf, copying the missing default master and other system database files. If you have moved the database location, but not moved the database files, startup may fail. To repair: shutdown SQL Server, move the master database to configured location, and restart.
2023-08-06 09:34:58.16 Server      Setup step is copying system data file 'C:\templatedata\mastlog.ldf' to '/var/opt/mssql/data/mastlog.ldf'.
2023-08-06 09:34:58.29 Server      Setup step is copying system data file 'C:\templatedata\model.mdf' to '/var/opt/mssql/data/model.mdf'.
2023-08-06 09:34:58.38 Server      Setup step is copying system data file 'C:\templatedata\modellog.ldf' to '/var/opt/mssql/data/modellog.ldf'.
2023-08-06 09:34:58.39 Server      Setup step is copying system data file 'C:\templatedata\msdbdata.mdf' to '/var/opt/mssql/data/msdbdata.mdf'.
2023-08-06 09:34:58.41 Server      Setup step is copying system data file 'C:\templatedata\msdblog.ldf' to '/var/opt/mssql/data/msdblog.ldf'.
2023-08-06 09:34:58.42 Server      Setup step is copying system data file 'C:\templatedata\model_replicatedmaster.mdf' to '/var/opt/mssql/data/model_replicatedmaster.mdf'.
2023-08-06 09:34:58.43 Server      Setup step is copying system data file 'C:\templatedata\model_replicatedmaster.ldf' to '/var/opt/mssql/data/model_replicatedmaster.ldf'.
2023-08-06 09:34:58.44 Server      Setup step is copying system data file 'C:\templatedata\model_msdbdata.mdf' to '/var/opt/mssql/data/model_msdbdata.mdf'.
2023-08-06 09:34:58.47 Server      Setup step is copying system data file 'C:\templatedata\model_msdblog.ldf' to '/var/opt/mssql/data/model_msdblog.ldf'.
2023-08-06 09:34:58.84 Server      Microsoft SQL Server 2022 (RTM-CU5) (KB5026806) - 16.0.4045.3 (X64)
mssql-msMay 26 2023 12:52:08
mssql-msCopyright (C) 2022 Microsoft Corporation
mssql-msDeveloper Edition (64-bit) on Linux (Ubuntu 20.04.6 LTS) <X64>
2023-08-06 09:34:58.84 Server      UTC adjustment: 0:00
2023-08-06 09:34:58.84 Server      (c) Microsoft Corporation.
2023-08-06 09:34:58.84 Server      All rights reserved.
2023-08-06 09:34:58.85 Server      Server process ID is 536.
2023-08-06 09:34:58.85 Server      Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2023-08-06 09:34:58.85 Server      Registry startup parameters:
mssql-ms -d /var/opt/mssql/data/master.mdf
mssql-ms -l /var/opt/mssql/data/mastlog.ldf
mssql-ms -e /var/opt/mssql/log/errorlog

Note: even on docker-ce the log lines Setup step is copying system data file 'C:\templatedata\... show Windows filesystem paths.

I am sure it’s safe to say, that its not a generel problem of the image, or Powershell.

mloskot · August 7, 2023, 10:36pm

Yes, it is fine there:

I have tried and reproduced the same issue using these three:

mcr.microsoft.com/mssql/server:2022-latest
mcr.microsoft.com/mssql/server:2019-latest
mcr.microsoft.com/mssql/server:2017-latest

Additionally, I switched my Windows 11 back to use Windows Console Host instead of Windows Terminal, then tired the old Command Prompt, and same issue occurred:

I tried the Windows Console Host mode as a test that the issue is not due to my custom settings of Windows Terminal (e.g. Terminus font, theme, powerline-go used, whatever it could be).

I don’t have Linux environment handy to try it as alternative, so thanks @meyay for checking that.

UPDATE: I’ve decided to copy this report to Broken docker compose output for SQL Server container logs · Issue #850 · microsoft/mssql-docker · GitHub

mloskot · August 9, 2023, 10:07am

Someone posted a comment to my GitHub issue saying the output is also messed up on Linux, see Broken docker compose output for SQL Server container logs · Issue #850 · microsoft/mssql-docker · GitHub

rimelek · August 9, 2023, 6:00pm

I tried it on my VPS and got a similar behavior.

SQL Server 2022 will run as non-root by default.
test-mssql-1  | This container is running as user mssql.
test-mssql-1  | Your master database file is owned by mssql.
test-mssql-1  | To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.
test-mssql-1  | 2023-08-09 17:35:10.08 Server      Microsoft SQL Server 2022 (RTM-CU5) (KB5026806) - 16.0.4045.3 (X64)
test-mssMay 26 2023 12:52:08
test-mssCopyright (C) 2022 Microsoft Corporation
test-mssDeveloper Edition (64-bit) on Linux (Ubuntu 20.04.6 LTS) <X64>
2023-08-09 17:35:10.08 Server      UTC adjustment: 0:00
2023-08-09 17:35:10.08 Server      (c) Microsoft Corporation.
2023-08-09 17:35:10.08 Server      All rights reserved.
2023-08-09 17:35:10.08 Server      Server process ID is 432.
2023-08-09 17:35:10.08 Server      Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2023-08-09 17:35:10.08 Server      Registry startup parameters:
test-mss -d /var/opt/mssql/data/master.mdf
test-mss -l /var/opt/mssql/data/mastlog.ldf
test-mss -e /var/opt/mssql/log/errorlog

As you can see some lines start with “test-mss”, even though the service name is “mssql” because I used @meyay’s example and some lines start with “test-mssql-1”, and other lines with a date as if multiple lines were interpreted by compose as one but that doesn’t explain “test-mss”.

In fact, @meyay’s output had the same problem it is just hard to catch it since logs starting with dates are usually normal, but not in case of compose.

The same log output using docker logs instead of docker compose logs is this:

SQL Server 2022 will run as non-root by default.
This container is running as user mssql.
Your master database file is owned by mssql.
To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.
2023-08-09 17:35:10.08 Server      Microsoft SQL Server 2022 (RTM-CU5) (KB5026806) - 16.0.4045.3 (X64)
	May 26 2023 12:52:08
	Copyright (C) 2022 Microsoft Corporation
	Developer Edition (64-bit) on Linux (Ubuntu 20.04.6 LTS) <X64>
2023-08-09 17:35:10.08 Server      UTC adjustment: 0:00
2023-08-09 17:35:10.08 Server      (c) Microsoft Corporation.
2023-08-09 17:35:10.08 Server      All rights reserved.
2023-08-09 17:35:10.08 Server      Server process ID is 432.
2023-08-09 17:35:10.08 Server      Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2023-08-09 17:35:10.08 Server      Registry startup parameters:
	 -d /var/opt/mssql/data/master.mdf
	 -l /var/opt/mssql/data/mastlog.ldf
	 -e /var/opt/mssql/log/errorlog

Now let’s see the json file from which docker reads the logs. The following command works only on Linux without Docker Desktop:

sudo docker inspect test-mssql-1 --format '{{ .LogPath }}' > out.json

{
  "log": "SQL Server 2022 will run as non-root by default.\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:36.405720176Z"
}
{
  "log": "This container is running as user mssql.\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:36.40588804Z"
}
{
  "log": "To learn more visit https://go.microsoft.com/fwlink/?linkid=2099216.\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:36.405892559Z"
}
{
  "log": "2023-08-09 17:31:38.51 Server      Setup step is copying system data file 'C:\\templatedata\\master.mdf' to '/var/opt/mssql/data/master.mdf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.533812778Z"
}
{
  "log": "\r2023-08-09 17:31:38.53 Server      Did not find an existing master data file /var/opt/mssql/data/master.mdf, copying the missing default master and other system database files. If you have moved the database location, but not moved the database files, startup may fail. To repair: shutdown SQL Server, move the master database to configured location, and restart.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.542461053Z"
}
{
  "log": "\r2023-08-09 17:31:38.53 Server      Setup step is copying system data file 'C:\\templatedata\\mastlog.ldf' to '/var/opt/mssql/data/mastlog.ldf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.543662355Z"
}
{
  "log": "\r2023-08-09 17:31:38.54 Server      Setup step is copying system data file 'C:\\templatedata\\model.mdf' to '/var/opt/mssql/data/model.mdf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.546403885Z"
}
{
  "log": "\r2023-08-09 17:31:38.54 Server      Setup step is copying system data file 'C:\\templatedata\\modellog.ldf' to '/var/opt/mssql/data/modellog.ldf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.554910214Z"
}
{
  "log": "\r2023-08-09 17:31:38.55 Server      Setup step is copying system data file 'C:\\templatedata\\msdbdata.mdf' to '/var/opt/mssql/data/msdbdata.mdf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.564959846Z"
}
{
  "log": "\r2023-08-09 17:31:38.57 Server      Setup step is copying system data file 'C:\\templatedata\\msdblog.ldf' to '/var/opt/mssql/data/msdblog.ldf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.578635346Z"
}
{
  "log": "\r2023-08-09 17:31:38.57 Server      Setup step is copying system data file 'C:\\templatedata\\model_replicatedmaster.mdf' to '/var/opt/mssql/data/model_replicatedmaster.mdf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.581838792Z"
}
{
  "log": "\r2023-08-09 17:31:38.58 Server      Setup step is copying system data file 'C:\\templatedata\\model_replicatedmaster.ldf' to '/var/opt/mssql/data/model_replicatedmaster.ldf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.588932692Z"
}
{
  "log": "\r2023-08-09 17:31:38.58 Server      Setup step is copying system data file 'C:\\templatedata\\model_msdbdata.mdf' to '/var/opt/mssql/data/model_msdbdata.mdf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.593084045Z"
}
{
  "log": "\r2023-08-09 17:31:38.60 Server      Setup step is copying system data file 'C:\\templatedata\\model_msdblog.ldf' to '/var/opt/mssql/data/model_msdblog.ldf'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.608003127Z"
}
{
  "log": "\r2023-08-09 17:31:38.62 Server      Microsoft SQL Server 2022 (RTM-CU5) (KB5026806) - 16.0.4045.3 (X64) \r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.628282369Z"
}
{
  "log": "\r\tMay 26 2023 12:52:08 \r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.628510938Z"
}
{
  "log": "\r\tCopyright (C) 2022 Microsoft Corporation\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.628895849Z"
}
{
  "log": "\r\tDeveloper Edition (64-bit) on Linux (Ubuntu 20.04.6 LTS) <X64>\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.629619996Z"
}
{
  "log": "\r2023-08-09 17:31:38.62 Server      UTC adjustment: 0:00\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.630169467Z"
}
{
  "log": "\r2023-08-09 17:31:38.62 Server      (c) Microsoft Corporation.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.630936485Z"
}
{
  "log": "\r2023-08-09 17:31:38.62 Server      All rights reserved.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.631613414Z"
}
{
  "log": "\r2023-08-09 17:31:38.62 Server      Server process ID is 436.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.633211179Z"
}
{
  "log": "\r2023-08-09 17:31:38.62 Server      Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.634781504Z"
}
{
  "log": "\r2023-08-09 17:31:38.63 Server      Registry startup parameters: \r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.63562254Z"
}
{
  "log": "\r\t -d /var/opt/mssql/data/master.mdf\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.635996592Z"
}
{
  "log": "\r\t -l /var/opt/mssql/data/mastlog.ldf\r\n",
  "stream": "stdout",
  "time": "2023-08-09T17:31:38.636381735Z"
}

So some log messages actually start with \r\t and that’s when I see the compise output lines starting with an incomplete container name like “test-mss”. Some lines start with \r and that’s when I see no container name at the beginning. The perfectly working lines start with regular texts not \r or \r\t.

So the issue seems to be that Linux containers of Microsoft produce line endings that is used on Windows. I think compose still could have handled it better so since we can’t accept we get proper outputs. That’s why we check the logs in the first place.

So I think you did well opening an issue on GitHub, but it could be reported in the Compose repository as well.

meyay · August 9, 2023, 6:50pm

Good catch && good idea to look at the logs in json format!

Topic		Replies	Views
Problem running container on Windows 10 home edition after hello world Docker Desktop docker	4	841	April 16, 2020
Docker stuck at Using 'xplog70.dll' version '2017.140.3192' to execute extended stored procedure 'xp_msver' Docker Desktop docker , windows	1	3120	August 4, 2021
Docker desktop running image doesn´t start all container like docker-compose up Docker Desktop docker , docker-compose , linux	0	484	March 18, 2024
Instability in the latest Docker for Windows (Windows containers version) Docker Desktop docker	0	1154	December 14, 2016
Volume in SQL Server Windows Container not working Windows Server 2016	0	1036	July 20, 2022

Broken docker compose output for SQL Server container logs

Related topics