Just a very quick post today. At the weekend I blogged about creating SQL 2019 containers with named volumes enabling you to persist your data and yesterday about creating a random workload using PowerShell and a big T-SQL script.
The interesting thing about creating workload is that you can break things :-)
When I created a SQL 2019 container with the data files mapped to a directory on my laptops C Drive with a docker-compose like this
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
| version: '3.7'
services:
2019-CTP23:
image: mcr.microsoft.com/mssql/server:2019-CTP2.3-ubuntu
ports:
- "15591:1433"
- "5022:5022"
environment:
SA_PASSWORD: "Password0!"
ACCEPT_EULA: "Y"
volumes:
- C:\MSSQL\BACKUP\KEEP:/var/opt/mssql/backups
- C:\MSSQL\DockerFiles\datafiles:/var/opt/sqlserver
- C:\MSSQL\DockerFiles\system:/var/opt/mssql
|
restore the AdventureWorks database to use the /var/opt/sqlserver directory and run a workload after a while the container stops and when you examine the logs you find
I had a whole load of these errors
1
2
3
4
5
6
7
8
| 2019-04-02 20:48:24.73 spid58 Error: 17053, Severity: 16, State: 1.
2019-04-02 20:48:24.73 spid58 FCB::MakePreviousWritesDurable: Operating system error (null) encountered.
2019-04-02 20:48:24.74 spid58 Error: 9001, Severity: 21, State: 1.
2019-04-02 20:48:24.74 spid58 The log for database 'AdventureWorks2014' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
2019-04-02 20:48:25.05 spid58 Error: 9001, Severity: 21, State: 16.
2019-04-02 20:48:25.05 spid58 The log for database 'AdventureWorks2014' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
2019-04-02 20:48:25.06 spid52 Error: 9001, Severity: 21, State: 16.
2019-04-02 20:48:25.06 spid52 The log for database 'AdventureWorks2014' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
|
Then some of these
1
2
| 019-04-02 20:55:16.26 spid53 Error: 17053, Severity: 16, State: 1.
2019-04-02 20:55:16.26 spid53 /var/opt/sqlserver/AdventureWorks2014_Data.mdf: Operating system error 31(A device attached to the system is not functioning.) encountered.
|
Then it went really bad
1
2
3
4
5
6
| 2019-04-02 20:55:16.35 spid53 Error: 3314, Severity: 21, State: 3.
2019-04-02 20:55:16.35 spid53 During undoing of a logged operation in database 'AdventureWorks2014' (page (0:0) if any), an error occurred at log record ID (65:6696:25). Typically, the specific failure is logged previously as an error in the operating system error log. Restore the database or file from
a backup, or repair the database.
2019-04-02 20:55:16.37 spid53 Database AdventureWorks2014 was shutdown due to error 3314 in routine 'XdesRMReadWrite::RollbackToLsn'. Restart for non-snapshot databases will be attempted after all connections to the database are aborted.
Restart packet created for dbid 5.
2019-04-02 20:55:16.41 spid53 Error during rollback. shutting down database (location: 1).
|
1
| after that it tried to restart the database
|
1
2
3
4
5
6
7
8
9
| 2019-04-02 20:55:16.44 spid53 Error: 3314, Severity: 21, State: 3.
2019-04-02 20:55:16.44 spid53 During undoing of a logged operation in database 'AdventureWorks2014' (page (0:0) if any), an error occurred at log record ID (65:6696:25). Typically, the specific failure is logged previously as an error in the operating system error log. Restore the database or file from
a backup, or repair the database.
2019-04-02 20:55:16.49 spid53 Error: 3314, Severity: 21, State: 5.
2019-04-02 20:55:16.49 spid53 During undoing of a logged operation in database 'AdventureWorks2014' (page (0:0) if any), an error occurred at log record ID (65:6696:1). Typically, the specific failure
is logged previously as an error in the operating system error log. Restore the database or file from a backup, or repair the database.
Restart packet processing for dbid 5.
2019-04-02 20:55:17.04 spid52 [5]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 0.
2019-04-02 20:55:17.06 spid52 Starting up database 'AdventureWorks2014'.
|
But that caused
1
2
3
| 2019-04-02 20:55:17.90 spid76 Error: 9001, Severity: 21, State: 16.
2019-04-02 20:55:17.90 spid76 The log for database 'master' is not available. Check the operating
system error log for related error messages. Resolve any errors and restart the database.
|
Master eh? Now what will you do?
1
2
3
4
5
6
| 2019-04-02 20:55:25.55 spid52 29 transactions rolled forward in database 'AdventureWorks2014' (5:0). This is an informational message only. No user action is required.
2019-04-02 20:55:25.90 spid52 1 transactions rolled back in database 'AdventureWorks2014' (5:0). This is an informational message only. No user action is required.
2019-04-02 20:55:25.90 spid52 Recovery is writing a checkpoint in database 'AdventureWorks2014' (5). This is an informational message only. No user action is required.
2019-04-02 20:55:26.16 spid52 Recovery completed for database AdventureWorks2014 (database ID 5) in 7 second(s) (analysis 424 ms, redo 5305 ms, undo 284 ms.) This is an informational message only. No user action is required.
2019-04-02 20:55:26.21 spid52 Parallel redo is shutdown for database 'AdventureWorks2014' with worker pool size [1].
2019-04-02 20:55:26.27 spid52 CHECKDB for database 'AdventureWorks2014' finished without errors on 2018-03-24 00:38:39.313 (local time). This is an informational message only; no user action is required.
|
Interesting, then back to this.
1
2
3
4
5
| 2019-04-02 21:00:00.57 spid51 Error: 17053, Severity: 16, State: 1.
2019-04-02 21:00:00.57 spid51 FCB::MakePreviousWritesDurable: Operating system error (null) encountered.
2019-04-02 21:00:00.62 spid51 Error: 9001, Severity: 21, State: 1.
2019-04-02 21:00:00.62 spid51 The log for database 'AdventureWorks2014' is not available. Check the operating system error log for related error messages. Resolve any errors and restart the database.
2019-04-02 21:00:00.64 spid51 Error: 9001, Severity: 21, State: 16.
|
It did all that again before
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
| This program has encountered a fatal error and cannot continue running at Tue Apr 2 21:04:08 2019
The following diagnostic information is available:
Reason: 0x00000004
Message: RETAIL ASSERT: Expression=(false) File=Thread.cpp Line=4643 Description=Timed out waiting for thread terminate/suspend/resume.
Stacktrace: 000000006af30187 000000006af2836a 000000006ae4a4d1
000000006ae48c55 000000006af6ab5e 000000006af6ac04
00000002809528df
Process: 7 - sqlservr
Thread: 129 (application thread 0x1e8)
Instance Id: 215cfcc9-8f69-4869-9a52-5aa44a415a83
Crash Id: 53e98400-33f1-4786-98fd-484f0c8d9a7e
Build stamp: 0e53295d0e1704ae5b221538dd6e2322cd46134e0cc32be49c887ca84cdb8c10
Distribution: Ubuntu 16.04.6 LTS
Processors: 2
Total Memory: 4906205184 bytes
Timestamp: Tue Apr 2 21:04:08 2019
Ubuntu 16.04.6 LTS
Capturing core dump and information to /var/opt/mssql/log...
/usr/bin/find: '/proc/7/task/516': No such file or directory
dmesg: read kernel buffer failed: Operation not permitted
No journal files were found.
No journal files were found.
Attempting to capture a dump with paldumper
WARNING: Capture attempt failure detected
Attempting to capture a filtered dump with paldumper
WARNING: Attempt to capture dump failed. Reference /var/opt/mssql/log/core.sqlservr.7.temp/log/paldumper-debug.log for details
Attempting to capture a dump with gdb
WARNING: Unable to capture crash dump with GDB. You may need to
allow ptrace debugging, enable the CAP_SYS_PTRACE capability, or
run as root.
|
failing to capture it’s dump!! Oops :-)
I had to recreate the containers without using the named volumes and then I could run my workload :-)
Nothing particularly useful about this blog post other than an interesting look at the error log when things go wrong :-)
