Got a really odd one here. One of my clients has reported that one of their databases is shutting itself down most nights. I've checked the logs and he is correct. The thing is there's not a huge amount of consistency to it. It's always the same database, but timings seem to vary.
Windows Server 2008 R2. Progress 10.2B07.
It has gone each morning for the last four days, 03:33, 06:14, 07:25, 03:01.
Logfile errors don't seem to be completely consistent.
[2016/08/31@03:31:08.474+0100] P-5840 T-9220 I SRV 2: (739) Logout usernum 59, userid index_support, on ZP-Index.
[2016/08/31@03:31:18.620+0100] P-5868 T-8224 I BROKER 0: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.623+0100] P-5576 T-5728 I BIW 21: (2520) Stopped.
[2016/08/31@03:31:18.624+0100] P-5576 T-5728 I : (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:18.639+0100] P-2128 T-5744 I SRV 1: (2520) Stopped.
[2016/08/31@03:31:18.655+0100] P-7456 T-7460 I APW 25: (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:18.655+0100] P-7680 T-7684 I APW 27: (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:18.656+0100] P-6720 T-6716 I APW 23: (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:18.657+0100] P-1020 T-5980 I APW 24: (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:18.664+0100] P-7672 T-13564 I FMAGENT26: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.676+0100] P-5840 T-4668 I SRV 2: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.680+0100] P-5840 T-9220 I SRV 2: (2520) Stopped.
[2016/08/31@03:31:18.687+0100] P-8284 T-8324 I SRV 3: (2520) Stopped.
[2016/08/31@03:31:18.688+0100] P-11360 T-11364 I SRV 6: (2520) Stopped.
[2016/08/31@03:31:18.696+0100] P-2280 T-9168 I SRV 4: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.702+0100] P-9904 T-9344 I SRV 5: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.704+0100] P-2280 T-3492 I SRV 4: (2520) Stopped.
[2016/08/31@03:31:18.709+0100] P-2040 T-7264 I SRV 7: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.714+0100] P-10836 T-9908 I SRV 8: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.716+0100] P-8564 T-8772 I SRV 9: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/31@03:31:18.747+0100] P-8564 T-1668 I SRV 9: (2520) Stopped.
[2016/08/31@03:31:18.752+0100] P-9904 T-11008 I SRV 5: (2520) Stopped.
[2016/08/31@03:31:18.754+0100] P-10836 T-9256 I SRV 8: (2520) Stopped.
[2016/08/31@03:31:18.757+0100] P-2040 T-7856 I SRV 7: (2520) Stopped.
[2016/08/31@03:31:18.855+0100] P-7672 T-7676 I FMAGENT26: (453) Logout by DB_Agent on batch.
[2016/08/31@03:31:20.009+0100] P-5868 T-5872 I BROKER 0: (15192) The database will complete shutdown within approximately 60 seconds.
[2016/08/31@03:31:20.009+0100] P-5868 T-5872 I BROKER 0: (2249) Begin ABNORMAL shutdown code 2
[2016/08/31@03:31:20.087+0100] P-6444 T-6548 I WDOG 22: (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:21.023+0100] P-5868 T-5872 I BROKER 0: (5179) Registry error 1717: Could not register 'AUDIT_PROGRESS' events with the Event Viewer.
[2016/08/31@03:31:21.023+0100] P-5868 T-5872 I BROKER 0: (2263) Resending shutdown request to 4 user(s).
[2016/08/31@03:31:22.770+0100] P-14592 T-7896 I ABL 28: (453) Logout by WH35 on CON:.
[2016/08/31@03:31:22.770+0100] P-13020 T-12036 I ABL 29: (453) Logout by WH14 on CON:.
[2016/08/31@03:31:23.721+0100] P-7628 T-9436 I ABL 31: (453) Logout by WH27 on CON:.
[2016/08/31@03:31:23.753+0100] P-13536 T-15224 I ABL 43: (453) Logout by WH14 on CON:.
[2016/08/31@03:31:24.065+0100] P-5868 T-5872 I BROKER 0: (5179) Registry error 1717: Could not register 'AUDIT_PROGRESS' events with the Event Viewer.
[2016/08/31@03:31:24.065+0100] P-5868 T-5872 I BROKER 0: (453) Logout by SYSTEM on batch.
[2016/08/31@03:31:25.110+0100] P-5868 T-5872 I BROKER : (5179) Registry error 1717: Could not register 'AUDIT_PROGRESS' events with the Event Viewer.
[2016/08/31@03:31:25.110+0100] P-5868 T-5872 I BROKER : (334) Multi-user session end.
[2016/08/30@06:11:01.676+0100] P-5220 T-1468 I SRV 4: (739) Logout usernum 57, userid index_support, on ZP-Index.
[2016/08/30@06:11:39.728+0100] P-6508 T-6320 I WDOG 22: (2527) Disconnecting dead user 29.
[2016/08/30@06:13:40.677+0100] P-1524 T-10144 I ABL 29: (452) Login by WH23 on CON:.
[2016/08/30@06:13:40.681+0100] P-1524 T-10144 I ABL 29: (12699) Database audit Options:
[2016/08/30@06:14:09.735+0100] P-6508 T-6320 I WDOG 22: (2256) SYSTEM ERROR: User 37 died during microtransaction.
[2016/08/30@06:14:09.736+0100] P-6508 T-6320 I WDOG 22: (2520) Stopped.
[2016/08/30@06:14:09.739+0100] P-6508 T-6320 I : (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:09.752+0100] P-6360 T-6392 I BIW 21: (2520) Stopped.
[2016/08/30@06:14:09.752+0100] P-6360 T-6392 I : (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:09.759+0100] P-8484 T-8488 I SRV 1: (453) Logout by Wayne.caffrey on ZP-Index.
[2016/08/30@06:14:09.816+0100] P-6600 T-6644 I APW 25: (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:09.816+0100] P-2628 T-6572 I APW 24: (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:09.816+0100] P-4632 T-1640 I APW 26: (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:09.817+0100] P-6532 T-1880 I APW 23: (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:09.818+0100] P-5468 T-6708 I ABL 34: (453) Logout by WH43 on CON:.
[2016/08/30@06:14:09.819+0100] P-11768 T-7488 I ABL 31: (453) Logout by WH5 on CON:.
[2016/08/30@06:14:09.819+0100] P-1524 T-10144 I ABL 29: (453) Logout by WH23 on CON:.
[2016/08/30@06:14:09.819+0100] P-7580 T-4448 I ABL 39: (453) Logout by WH40 on CON:.
[2016/08/30@06:14:09.819+0100] P-9568 T-3284 I ABL 35: (453) Logout by WH13 on CON:.
[2016/08/30@06:14:09.821+0100] P-7360 T-8740 I SRV 3: (2520) Stopped.
[2016/08/30@06:14:09.837+0100] P-2132 T-8548 I SRV 5: (2520) Stopped.
[2016/08/30@06:14:09.837+0100] P-12608 T-12100 I SRV 8: (2520) Stopped.
[2016/08/30@06:14:09.837+0100] P-9852 T-10188 I SRV 7: (2520) Stopped.
[2016/08/30@06:14:09.902+0100] P-5220 T-1468 I SRV 4: (2520) Stopped.
[2016/08/30@06:14:09.912+0100] P-9512 T-9516 I SRV 2: (2520) Stopped.
[2016/08/30@06:14:09.912+0100] P-11304 T-11156 I SRV 6: (2520) Stopped.
[2016/08/30@06:14:09.974+0100] P-13668 T-8208 I ABL 38: (2252) Begin transaction backout.
[2016/08/30@06:14:09.974+0100] P-13668 T-8208 I ABL 38: (2253) Transaction backout completed.
[2016/08/30@06:14:09.955+0100] P-1216 T-13916 I BACKUP 28: (5462) End backup of Data file(s).
[2016/08/30@06:14:10.015+0100] P-1216 T-13916 I BACKUP 28: (1726) Backup cancelled, disconnected by server.
[2016/08/30@06:14:10.017+0100] P-1216 T-13916 I BACKUP 28: (453) Logout by index_support on CON:.
[2016/08/30@06:14:10.075+0100] P-6728 T-6744 I FMAGENT27: (453) Logout by DB_Agent on batch.
[2016/08/30@06:14:10.817+0100] P-11676 T-10652 I ABL 40: (453) Logout by WH14 on CON:.
[2016/08/30@06:14:10.817+0100] P-13668 T-8208 I ABL 38: (453) Logout by WH28 on CON:.
[2016/08/30@06:14:10.817+0100] P-10720 T-12492 I ABL 32: (453) Logout by WH38 on CON:.
[2016/08/30@06:14:10.820+0100] P-13092 T-13728 I ABL 30: (453) Logout by WH53 on CON:.
[2016/08/30@06:14:10.824+0100] P-4512 T-13568 I ABL 36: (453) Logout by WH14 on CON:.
[2016/08/30@06:14:10.885+0100] P-6944 T-13564 I ABL 33: (2252) Begin transaction backout.
[2016/08/30@06:14:10.885+0100] P-6944 T-13564 I ABL 33: (2253) Transaction backout completed.
[2016/08/30@06:14:11.049+0100] P-5684 T-5688 I BROKER 0: (15192) The database will complete shutdown within approximately 60 seconds.
[2016/08/30@06:14:11.049+0100] P-5684 T-5688 I BROKER 0: (2249) Begin ABNORMAL shutdown code 2
[2016/08/30@06:14:11.826+0100] P-6944 T-13564 I ABL 33: (453) Logout by WH30 on CON:.
[2016/08/30@06:14:12.049+0100] P-5684 T-5688 I BROKER 0: (2525) Disconnecting dead server -1.
[2016/08/30@06:14:13.049+0100] P-5684 T-5688 I BROKER 0: (2527) Disconnecting dead user 37.
[2016/08/30@06:14:14.049+0100] P-5684 T-5688 I BROKER 0: (453) Logout by SYSTEM on batch.
[2016/08/30@06:14:15.104+0100] P-5684 T-5688 I BROKER : (334) Multi-user session end.
[2016/08/29@07:25:34.687+0100] P-6740 T-6744 I WDOG 22: (2256) SYSTEM ERROR: User 37 died during microtransaction.
[2016/08/29@07:25:34.688+0100] P-6772 T-1592 I SRV 1: (2520) Stopped.
[2016/08/29@07:25:34.690+0100] P-6232 T-1348 I SRV 2: (2520) Stopped.
[2016/08/29@07:25:34.718+0100] P-7052 T-7056 I APW 27: (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:34.719+0100] P-6780 T-6784 I APW 23: (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:34.719+0100] P-6740 T-6744 I WDOG 22: (2520) Stopped.
[2016/08/29@07:25:34.720+0100] P-6740 T-6744 I : (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:34.720+0100] P-6840 T-6844 I APW 24: (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:34.725+0100] P-6912 T-6916 I APW 25: (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:34.725+0100] P-6704 T-6708 I BIW 21: (2520) Stopped.
[2016/08/29@07:25:34.726+0100] P-6704 T-6708 I : (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:34.742+0100] P-10992 T-10244 I ABL 35: (2252) Begin transaction backout.
[2016/08/29@07:25:34.742+0100] P-10992 T-10244 I ABL 35: (2253) Transaction backout completed.
[2016/08/29@07:25:34.815+0100] P-8252 T-7952 I SRV 4: (2520) Stopped.
[2016/08/29@07:25:34.816+0100] P-7308 T-7320 I BACKUP 28: (5462) End backup of Data file(s).
[2016/08/29@07:25:34.820+0100] P-7308 T-7320 I BACKUP 28: (1726) Backup cancelled, disconnected by server.
[2016/08/29@07:25:34.821+0100] P-7308 T-7320 I BACKUP 28: (453) Logout by index_support on CON:.
[2016/08/29@07:25:34.857+0100] P-9752 T-9380 I SRV 3: (2520) Stopped.
[2016/08/29@07:25:34.885+0100] P-7060 T-7064 I FMAGENT26: (453) Logout by DB_Agent on batch.
[2016/08/29@07:25:35.098+0100] P-8400 T-8368 I ABL 30: (2252) Begin transaction backout.
[2016/08/29@07:25:35.098+0100] P-8400 T-8368 I ABL 30: (2253) Transaction backout completed.
[2016/08/29@07:25:35.142+0100] P-1760 T-2524 I ABL 33: (2252) Begin transaction backout.
[2016/08/29@07:25:35.142+0100] P-1760 T-2524 I ABL 33: (2253) Transaction backout completed.
[2016/08/29@07:25:35.722+0100] P-10992 T-10244 I ABL 35: (453) Logout by WH23 on CON:.
[2016/08/29@07:25:35.722+0100] P-1760 T-2524 I ABL 33: (453) Logout by WH40 on CON:.
[2016/08/29@07:25:35.723+0100] P-10008 T-9008 I ABL 34: (453) Logout by WH38 on CON:.
[2016/08/29@07:25:35.724+0100] P-4536 T-9476 I ABL 36: (453) Logout by WH9 on CON:.
[2016/08/29@07:25:35.727+0100] P-9688 T-8232 I ABL 32: (453) Logout by WH43 on CON:.
[2016/08/29@07:25:35.728+0100] P-8400 T-8368 I ABL 30: (453) Logout by WH30 on CON:.
[2016/08/29@07:25:35.757+0100] P-5944 T-11124 I ABL 39: (453) Logout by WH50 on CON:.
[2016/08/29@07:25:35.757+0100] P-11168 T-8056 I ABL 38: (453) Logout by WH28 on CON:.
[2016/08/29@07:25:35.923+0100] P-5736 T-5740 I BROKER 0: (15192) The database will complete shutdown within approximately 60 seconds.
[2016/08/29@07:25:35.924+0100] P-5736 T-5740 I BROKER 0: (2249) Begin ABNORMAL shutdown code 2
[2016/08/29@07:25:36.924+0100] P-5736 T-5740 I BROKER 0: (2527) Disconnecting dead user 31.
[2016/08/29@07:25:37.925+0100] P-5736 T-5740 I BROKER 0: (2527) Disconnecting dead user 37.
[2016/08/29@07:25:38.925+0100] P-5736 T-5740 I BROKER 0: (2263) Resending shutdown request to 1 user(s).
[2016/08/29@07:25:48.780+0100] P-10268 T-9668 I ABL 29: (453) Logout by WH5 on CON:.
[2016/08/29@07:25:48.926+0100] P-5736 T-5740 I BROKER 0: (453) Logout by SYSTEM on batch.
[2016/08/29@07:25:49.966+0100] P-5736 T-5740 I BROKER : (334) Multi-user session end.
[2016/08/28@03:01:02.511+0100] P-9412 T-9416 I SRV 2: (739) Logout usernum 59, userid index_support, on ZP-Index.
[2016/08/28@03:01:21.708+0100] P-5648 T-4224 I BROKER 0: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.734+0100] P-5804 T-6320 I BIW 21: (2520) Stopped.
[2016/08/28@03:01:21.735+0100] P-5804 T-6320 I : (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:21.748+0100] P-7212 T-7216 I APW 26: (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:21.748+0100] P-6612 T-1932 I APW 23: (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:21.751+0100] P-6620 T-2400 I APW 25: (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:21.751+0100] P-4120 T-4180 I APW 24: (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:21.814+0100] P-7264 T-2632 I SRV 1: (2520) Stopped.
[2016/08/28@03:01:21.815+0100] P-7220 T-10728 I FMAGENT27: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.826+0100] P-9412 T-19992 I SRV 2: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.875+0100] P-7692 T-9976 I SRV 3: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.878+0100] P-12436 T-7592 I SRV 9: (2520) Stopped.
[2016/08/28@03:01:21.878+0100] P-15680 T-15684 I SRV 10: (2520) Stopped.
[2016/08/28@03:01:21.879+0100] P-14112 T-14116 I SRV 8: (2520) Stopped.
[2016/08/28@03:01:21.881+0100] P-9984 T-7924 I SRV 4: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.882+0100] P-9612 T-12680 I SRV 5: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.882+0100] P-16116 T-16164 I SRV 11: (2520) Stopped.
[2016/08/28@03:01:21.883+0100] P-7692 T-7560 I SRV 3: (2520) Stopped.
[2016/08/28@03:01:21.883+0100] P-12292 T-11096 I SRV 7: (2520) Stopped.
[2016/08/28@03:01:21.883+0100] P-9984 T-8068 I SRV 4: (2520) Stopped.
[2016/08/28@03:01:21.883+0100] P-12180 T-17780 I SRV 6: (9438) CTRL_SHUTDOWN_EVENT console event received.
[2016/08/28@03:01:21.887+0100] P-9612 T-6556 I SRV 5: (2520) Stopped.
[2016/08/28@03:01:21.887+0100] P-9412 T-9416 I SRV 2: (2520) Stopped.
[2016/08/28@03:01:21.889+0100] P-12180 T-12144 I SRV 6: (2520) Stopped.
[2016/08/28@03:01:21.990+0100] P-6728 T-6740 I WDOG 22: (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:22.037+0100] P-7220 T-7224 I FMAGENT27: (453) Logout by DB_Agent on batch.
[2016/08/28@03:01:23.044+0100] P-5648 T-5652 I BROKER 0: (15192) The database will complete shutdown within approximately 60 seconds.
[2016/08/28@03:01:23.187+0100] P-5648 T-5652 I BROKER 0: (2249) Begin ABNORMAL shutdown code 2
[2016/08/28@03:01:24.201+0100] P-5648 T-5652 I BROKER 0: (2263) Resending shutdown request to 1 user(s).
[2016/08/28@03:01:25.839+0100] P-8772 T-6568 I ABL 30: (453) Logout by WH29 on CON:.
[2016/08/28@03:01:26.229+0100] P-5648 T-5652 I BROKER 0: (5179) Registry error 1717: Could not register 'AUDIT_PROGRESS' events with the Event Viewer.
[2016/08/28@03:01:26.229+0100] P-5648 T-5652 I BROKER 0: (453) Logout by SYSTEM on batch.
[2016/08/28@03:01:27.274+0100] P-5648 T-5652 I BROKER : (5179) Registry error 1717: Could not register 'AUDIT_PROGRESS' events with the Event Viewer.
[2016/08/28@03:01:27.274+0100] P-5648 T-5652 I BROKER : (334) Multi-user session end.
I'm at a loss where to look to be honest. The only consistent thing seems to be that the database backups are running at this time, but not necessarily on that database. The sessions usually have 8 or 9 databases connected at a time (I know), and the other databases are running fine.
KB on error 2256 isn't too helpful.
Just spotted I posted about this problem before. Thought it sounded familiar.
> [2016/08/30@06:11:39.728+0100] P-6508 T-6320 I WDOG 22: (2527) Disconnecting dead user 29.
> [2016/08/30@06:14:09.735+0100] P-6508 T-6320 I WDOG 22: (2256) SYSTEM ERROR: User 37 died during microtransaction.
Who were these users?
They are users but they have generic user names which is most frustrating. Night staff tend to be agency staff so it's very hard to tie this down.
And no any errors from these users?
BTW, did anybody already say that not using AI log is a bad thing? ;-)
I've managed to track down who the users are and one appears frequently so I've asked the client to find out what he's doing.
I know not using AI is a bad thing. Unfortunately this is out of my control.
> BROKER 0: (9438) CTRL_SHUTDOWN_EVENT console event received.
Database shutdowns after receiving CTRL_SHUTDOWN_EVENT
knowledgebase.progress.com/.../17917
<quote>
The CTRL_SHUTDOWN_EVENT is sent from Windows to all running processes when the system is shut down. They stop whatever they were doing, as does the database.
</quote>
So it looks like there's 2 things happening.
1) The microtransaction issue I need to get to the bottom of
2) They are rebooting the server for some reason.
The kbase also mentions Windows updates as a possibility:
> In Windows environments this is typically triggered by Windows Updates as opposed to a physical reboot. This can be confirmed in the System Event Viewer Log entries.
Thanks Aidan. Yes I saw that although the reboot with no errors seems to be happening too frequently for updates to be the cause. I could be wrong.
> The microtransaction issue
Microtransaction is a tiny part of the whole update process.
Part of microtransaction when a session does not lock latches is even smaller. It happens when a session allocates the additional resources (maily memory) on the client's side.
It's very unlikely to kill a session exactly at this moment - especially twice per two days as in your case.
User can die during microtransaction due to an error while allocating the resources but there are no errors issued by the user.
There are no transaction backout messages issued either by user itself or by watchdog but microtransaction is a part of transaction.
Curiouser and curiouser! - Alice said.
So - the situations where the reboot is being issued is due to normal server maintenance such as updates and recycling the Citrix farm. We need to reschedule this as it clashes with backups.
The microtransaction is very curious and I need to know what the users are doing.
Unfortunately the way they restart the db is by rebooting the whole server. Ouch.
The plot thickens. At 3am or so the datacentre run VM backups. I wonder.
And this is the same time as Progress backups happen. This is a right mess. Time to sort the scheduling out pronto.
Isn't the CTRL_SHUTDOWN event Windows actually shutting down?
Thanks yes it is. They neglected to tell me they rebooted the server. The Microtransaction ones are the problem.
Can you look to see how long the users that died during the microtransaction were connected ?
They weren't connected for long really. I think that it's the VM backups that are causing the issue. I will be asking them to exclude the database directory from the backups and see if it sorts the problem. One good thing about all of this is that I've reduced the probkup time from 6 hours+ to just over an hour by deleting the backup file first. Nice easy win! :)
> I've reduced the probkup time from 6 hours+ to just over an hour by deleting the backup file first.
Probkup online takes a long time to complete
knowledgebase.progress.com/.../000029180
Probkup with the -bf 1 will be fast as well
So rejigging the backup schedule and reducing the run time so it doesn't overlap with the Veeam snapshots seems to have stopped the 2256 errors. Thanks for all the ideas folks.