Проблема с установкой обновлений

Из-за того, что база данных очень большая, и сервер БД запущен на тормозной виртуальной машине, при обновлении БД в процессе установки обновлений часто по таймауту обновление БД отменяется. После этого приходится подолгу дожидаться, чтобы SQL сервер откатил все изменения, и пытаться запустить установку заново. Иногда она завершается благополучно :ya_hoo_oo:
Нельзя ли мне как-то изменять таймаут, чтобы установщик обновления подольше не прерывал задумчивый SQL?

Посмотрите тут Ошибка обновления базы данных при обновлении с версии R23.06 до R25.09 и выше . Вроде та же проблема, обещали исправить.

Обещали исправить в R26.01. Вот именно это обновление я сейчас не могу установить.

Приложите журнал работы вашей службы обновления ЛЭРС УЧЕТ. Возможно в вашем случае проблема отличается от описанной в теме Ошибка обновления базы данных при обновлении с версии R23.06 до R25.09 и выше.

Напрасно сомневаетесь:
Lers.UpdateService.log.7z (215 KB)

Приложите журналы SQL Server за тот же день, что и приложенный журнал работы Службы обновления.

Прикладываю журнал SQL Server за тот же день, что и приложенный ранее журнал работы Службы обновления.
ERRORLOG.7z (4.06 KB)

Как видно из присланного вами журнала работы SQL Server, у вас постоянно возникает ошибка:

Login failed for user ‘TELersUpdaterAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]

Устраните данную ошибку и повторите попытку обновления.

Эта ошибка является всего лишь следствием того, что БД блокируется на длительное время для выполнения отката изменений, внесенных программой-установщиком обновления ЛЭРСа. В это время я пытался повторно запустить установку обновления, но постоянно выскакивала эта ошибка. Нужно было просто дольше ждать. Никаких проблем с авторизацией нет, следовательно ваш совет ни к селу, ни к городу.
Пока временно решил проблему таким образом: удалил архивы текущих значений старее 10 дней (текущие значения снимались раз в минуту, срок хранения был 90 дней и база была пухлая и задумчивая). После чистки базы обновление R26.1 поставил без проблем.

Не совсем уверен что это так, потому что данная проблема, опять же исходя из присланного вами журнала, возникает сразу после запуска SQL Server при входе локального системного пользователя:

Login failed for user ‘NT AUTHORITYСИСТЕМА’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: ]

Поэтому возникновение этой ошибки не может быть следствием блокировки БД на длительное время для выполнения отката изменений, т.к. она возникает еще до обновления и с разными пользователями.

данная проблема, опять же исходя из присланного вами журнала, возникает сразу после запуска SQL Server при входе локального системного пользователя

Почему “сразу”? Интересно, куда вы смотрите?

2018-06-20 22:58:00.07 spid51 Starting up database ‘LERS’.
2018-06-20 22:59:12.10 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:12.10 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 22:59:24.14 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:24.14 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 22:59:36.15 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:36.15 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 22:59:48.19 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:48.19 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:00:10.23 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:00:10.23 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:00:52.31 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:00:52.31 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:01:04.34 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:01:04.34 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:01:14.64 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:01:14.64 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]

Я так понимаю, что:
2018-06-20 22:58:00.07 spid51 Starting up database ‘LERS’. - это установщик обновления начал обновление БД

А потом установщик по таймауту выдал ошибку, и предложил повторить процесс. Я тыкаю кнопку “Повторить”, но БД недоступна, так как идёт откат изменений, и появляются сообщения:

2018-06-20 22:59:12.10 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:12.10 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]

я ещё 7 раз тыкаю кнопку “Повторить”, и появляются остальные сообщения:

2018-06-20 22:59:24.14 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:24.14 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 22:59:36.15 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:36.15 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 22:59:48.19 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:48.19 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:00:10.23 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:00:10.23 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:00:52.31 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:00:52.31 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:01:04.34 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:01:04.34 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]
2018-06-20 23:01:14.64 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 23:01:14.64 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]

Видно же - разница во времени больше одной минуты между сообщениями:
2018-06-20 22:58:00.07 spid51 Starting up database ‘LERS’.
и
2018-06-20 22:59:12.10 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-20 22:59:12.10 Вход Login failed for user ‘TELersServerAccount’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: 10.104.0.30]

По Lers.UpdateService.log можно догадаться, что вы таймаут подняли с 15 секунд до 90 в R26.1. Видимо, этот таймаут включает в себя не только обновление БД, но и предшествующее обновление файлов, тогда понятна разница в 72 секунды между сообщениями

Я внимательно смотрю ваш лог и отчетливо вижу описанную мною в предыдущем сообщении ошибку. Чтобы вам нагляднее было видно и вам было легче ее найти, я отметил ее красным цветом, а запуск БД LERS зеленым.

2018-06-19 13:59:46.71 Server Microsoft SQL Server 2008 R2 (RTM) - 10.50.1600.1 (X64)
Apr 2 2010 15:48:46
Copyright (c) Microsoft Corporation
Enterprise Edition (64-bit) on Windows NT 6.2 (Build 9200: ) (Hypervisor)

2018-06-19 13:59:46.77 Server (c) Microsoft Corporation.
2018-06-19 13:59:46.77 Server All rights reserved.
2018-06-19 13:59:46.77 Server Server process ID is 1292.
2018-06-19 13:59:46.77 Server System Manufacturer: ‘VMware, Inc.’, System Model: ‘VMware Virtual Platform’.
2018-06-19 13:59:46.78 Server Authentication mode is MIXED.
2018-06-19 13:59:46.78 Server Logging SQL Server messages in file ‘C:Program FilesMicrosoft SQL ServerMSSQL10_50.SQLLERSMSSQLLogERRORLOG’.
2018-06-19 13:59:46.81 Server This instance of SQL Server last reported using a process ID of 1212 at 19.06.2018 13:58:56 (local) 19.06.2018 8:58:56 (UTC). This is an informational message only; no user action is required.
2018-06-19 13:59:46.81 Server Registry startup parameters:
-d C:Program FilesMicrosoft SQL ServerMSSQL10_50.SQLLERSMSSQLDATAmaster.mdf
-e C:Program FilesMicrosoft SQL ServerMSSQL10_50.SQLLERSMSSQLLogERRORLOG
-l C:Program FilesMicrosoft SQL ServerMSSQL10_50.SQLLERSMSSQLDATAmastlog.ldf
2018-06-19 13:59:46.96 Сервер SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2018-06-19 13:59:46.96 Сервер Detected 4 CPUs. This is an informational message; no user action is required.
2018-06-19 13:59:47.40 Server Large Page Extensions enabled.
2018-06-19 13:59:47.42 Server Large Page Granularity: 2097152
2018-06-19 13:59:47.42 Server Large Page Allocated: 32MB
2018-06-19 13:59:47.63 Сервер Using locked pages for buffer pool.
2018-06-19 13:59:48.38 Сервер 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.
2018-06-19 13:59:49.24 Сервер 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.
2018-06-19 13:59:49.90 spid7s Starting up database ‘master’.
2018-06-19 13:59:50.38 spid7s Recovery is writing a checkpoint in database ‘master’ (1). This is an informational message only. No user action is required.
2018-06-19 13:59:50.86 spid7s Resource governor reconfiguration succeeded.
2018-06-19 13:59:50.86 spid7s SQL Server Audit is starting the audits. This is an informational message. No user action is required.
2018-06-19 13:59:50.94 spid7s SQL Server Audit has started the audits. This is an informational message. No user action is required.
2018-06-19 13:59:51.01 spid7s FILESTREAM: effective level = 0, configured level = 0, file system access share name = ‘MSSQLSERVER’.
2018-06-19 13:59:51.54 spid7s SQL Trace ID 1 was started by login “sa”.
2018-06-19 13:59:51.65 spid7s Starting up database ‘mssqlsystemresource’.
2018-06-19 13:59:51.69 spid7s The resource database build version is 10.50.1600. This is an informational message only. No user action is required.
2018-06-19 13:59:52.47 spid10s Starting up database ‘model’.
2018-06-19 13:59:52.54 spid7s Server name is ‘APP5’. This is an informational message only. No user action is required.
2018-06-19 13:59:53.21 spid10s Clearing tempdb database.
2018-06-19 13:59:53.73 spid10s Starting up database ‘tempdb’.
2018-06-19 13:59:53.90 Сервер A self-generated certificate was successfully loaded for encryption.
2018-06-19 13:59:53.97 spid13s The Service Broker protocol transport is disabled or not configured.
2018-06-19 13:59:53.97 spid13s The Database Mirroring protocol transport is disabled or not configured.
2018-06-19 13:59:54.00 Сервер Server is listening on [ ‘any’ 1433].
2018-06-19 13:59:54.00 Сервер Server is listening on [ ‘any’ 1433].
2018-06-19 13:59:54.00 Сервер Server local connection provider is ready to accept connection on [ .pipeSQLLocalMSSQLSERVER ].
2018-06-19 13:59:54.00 Сервер Server local connection provider is ready to accept connection on [ .pipesqlquery ].
2018-06-19 13:59:54.01 Сервер Server is listening on [ ::1 1434].
2018-06-19 13:59:54.01 Сервер Server is listening on [ 127.0.0.1 1434].
2018-06-19 13:59:54.01 Сервер Dedicated admin connection support was established for listening locally on port 1434.
2018-06-19 13:59:54.03 spid13s Service Broker manager has started.
2018-06-19 13:59:54.04 Сервер The SQL Server Network Interface library successfully registered the Service Principal Name (SPN) [ MSSQLSvc/app5.te.local ] for the SQL Server service.
2018-06-19 13:59:54.04 Сервер The SQL Server Network Interface library successfully registered the Service Principal Name (SPN) [ MSSQLSvc/app5.te.local:1433 ] for the SQL Server service.
2018-06-19 13:59:54.04 Сервер SQL Server is now ready for client connections. This is an informational message; no user action is required.
2018-06-19 14:00:07.43 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-19 14:00:07.43 Вход Login failed for user ‘NT AUTHORITYСИСТЕМА’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: ]
2018-06-19 14:00:09.17 Вход Ошибка: 18456, серьезность: 14, состояние: 38.
2018-06-19 14:00:09.17 Вход Login failed for user ‘NT AUTHORITYСИСТЕМА’. Причина: не удалось открыть явно указанную базу данных. [КЛИЕНТ: ]
2018-06-19 14:00:10.23 spid20s A new instance of the full-text filter daemon host process has been successfully started.
2018-06-19 14:00:10.62 spid21s Starting up database ‘ReportServerTempDB’.
2018-06-19 14:00:10.62 spid22s Starting up database ‘ReportServer’.
2018-06-19 14:00:10.62 spid20s Starting up database ‘msdb’.
2018-06-19 14:00:11.81 spid7s Recovery is complete. This is an informational message only. No user action is required.
2018-06-19 14:00:18.30 spid51 Attempting to load library ‘xpsqlbot.dll’ into memory. This is an informational message only. No user action is required.
2018-06-19 14:00:18.37 spid51 Using ‘xpsqlbot.dll’ version ‘2009.100.1600’ to execute extended stored procedure ‘xp_qv’. This is an informational message only; no user action is required.
2018-06-19 14:00:18.87 spid51 Attempting to load library ‘xpstar.dll’ into memory. This is an informational message only. No user action is required.
2018-06-19 14:00:18.97 spid51 Using ‘xpstar.dll’ version ‘2009.100.1600’ to execute extended stored procedure ‘xp_instance_regread’. This is an informational message only; no user action is required.
2018-06-19 14:00:19.35 spid51 Attempting to load library ‘xplog70.dll’ into memory. This is an informational message only. No user action is required.
2018-06-19 14:00:19.41 spid51 Using ‘xplog70.dll’ version ‘2009.100.1600’ to execute extended stored procedure ‘xp_msver’. This is an informational message only; no user action is required.
2018-06-19 14:01:31.63 spid51 Starting up database ‘LERS’.
2018-06-19 14:08:16.01 spid57 Starting up database ‘LERS’.
2018-06-19 14:58:04.41 spid57 Starting up database ‘LERS’.

Из приведенной выше выдержки вашего журнала явно видно, что ошибка возникает еще до старта БД LERS, а по сему работа с БД LERS еще попросту невозможна.

Почему-то вы стали изучать лог за 19 число, а не за 20, когда я последний раз пытался ставить обновления.
А 19 числа я ещё не пришёл к правильному выводу, о том, что БД при прерывании установки обновления ЛЭРСа блокируется примерно на 15 минут из-за отката изменений. Заметив в SQL менеджере, что к БД LERS нет доступа, и постоянно висит сообщение, что база восстанавливается, я, не дождавшись финала восстановления, решил, что раз база повреждена, её нужно восстановить из бекапа. И то что вы выделили, происходило в процессе многократных перезапусков серверов с БД и с ЛЭРСом (это два разных компьютера), многократных попыток выполнения восстановления БД из бэкапа средствами ЛЭРС и SQL-менеджера. Так что советую не обращать внимания на записи за 19 июня.

Хорошо, мы разбираемся по 20.06.2018.

Мы не видим в журнале за 20.06.2018 никаких ошибок обновления базы данных, более того, мы не нашли подтверждение того, что обновление базы данных запускалось. За 19.06.2018 число тоже. Сообщений о том, что обновление базы данных откатывается также нет.
Более того 20-го числа сообщения начинаются не с начала, почему нам не известно.
Также у нас отсутствует таймаут на выполнение обновления, т.к. обновление может выполняться очень долго.

Приложите пожалуйста журнал, когда служба обновления начала обновлять базу данных и по какой-то причине перестала это делать. Нам интересна эта причина, чтобы мы могли её устранить.
Без этих сведений мы можем только предположить, что вы не дожидаетесь окончания работы службы обновления и запускаете её повторно, тут как раз мы видим ошибку подключения к базе данных, когда база данных уже занята.