От экспертов «1С‑Рарус»: Расследование ошибки пессимистической блокировки и устройство СУБД «1С:Сервер взаимодействия»

Иллюстрации в документе подготовлены с использованием демонстрационной базы с вымышленными сведениями. Совпадения с реальными данными случайны.

Вступление

Мы продолжаем цикл статей посвященный Системе взаимодействия. Сегодня хотим рассказать про интересный экспертный случай возникший на стыке разных механизмов платформы. И по ходу расследования погрузимся в детали механизма объектных блокировок и лучше узнаем внутреннее устройство Сервера взаимодействия, а точнее его систему логирования и таблицы СУБД.

Перед прочтением рекомендуем ознакомиться с первой статьёй цикла , в которой мы разворачивали свой сервер взаимодействия.

Описание случая

Представим себе обычную ситуацию. Мы начали редактировать какой-то документ — изменили одно из полей, не закрывая его форму и не сохранив изменения, запустили в том же сеансе какую-то длительную обработку или, например, сеанс завис. А документ отредактировать надо. Ждать мы не хотим, поэтому открываем другой сеанс той же базы, тот же документ, пытаемся что-то отредактировать в нём и получаем сообщение «Не удалось начать редактирование»:

Со спокойной душой нажимаем «Начать редактировать», получаем доступ к форме и вносим изменения, какие хотели:

Так вот, к нам обратился пользователь, у которого в таком же сценарии при нажатии на кнопку «Начать редактировать» программа стала выдавать странное сообщение «Обсуждение уже существует», без передачи доступа к документу. Помимо этого, на ту же проблему иногда стали жаловаться сотрудники техподдержки, которые получали то же сообщение при попытке «перехватить» редактирование документом у другого пользователя:

На первый взгляд — это какая-то путаница, одно сообщение явно связано с объектной блокировкой, а второе по слову «обсуждение» намекает на систему взаимодействия. В попытке понять связь этих явлений и началось наше расследование.

Тестируем разные объекты и проверяем релиз платформы «1С:Предприятие»

Сначала мы пробовали локализовать проблему. Протестировали некоторые варианты, проблема воспроизводится на разных объектах — элементах справочника, документах и с разными пользователями.

И что интересно, появилась как будто недавно. Первая мысль «значит в базе изменилось что‑то существенное». И действительно, примерно за месяц до указанных событий в базе была обновлена платформа 1С аж на 4 релиза (!), с версии 8.3.17.2306 на версию 8.3.21.1895.

Может ли проблема быть в релизе платформы?

Чтобы проверить эту гипотезу, мы взяли

• Другую продуктивную базу.
• На той же НОВОЙ версии платформы 8.3.21.1895.
• Подключенную к тому же серверу взаимодействия.

И проверили аналогичную ситуацию — открыли документ под двумя разными пользователями. К сожалению или к счастью, ситуация не воспроизвелась — никаких дополнительных сообщений и успешная передача редактирования:

Получается обновление ни при чем? И проблема локализована в конкретной базе? Было понятно, что ничего не понятно.

Само сообщение с заголовком «Не удалось начать редактирование» означает наличие пессимистической блокировки. Для начала вспомним, какие вообще виды объектных блокировок бывают, возможно, в теории найдем ключ к разгадке.

Виды объектных блокировок

Заглянем на ИТС в руководство разработчика «Глава 9. Работа с данными».

Итак, всего видов объектных блокировок два:

1. оптимистическая,
2. пессимистическая.

Обе служат в общем-то одной цели: помочь наиболее безболезненным способом разрешить конфликтную ситуацию одновременного редактирования одного объекта — документа, элемента справочника и т. д.

На всякий случай уточним, не стоит путать объектные блокировки с транзакционными блокировками (управляемыми и СУБД) — это разные механизмы.

Оптимистическая блокировка

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

Платформа 1С для каждого объекта хранит в СУБД специальное поле «ВерсияДанных». При чтении данных эта версия запоминается на время редактирования:

1. В форме при событиях:
   1. ПриСозданииНаСервере.
   2. ПриЧтенииНаСервере.
2. Программно — в момент вызова метода ПолучитьОбъект().

Далее при записи объекта происходит сравнение ранее закэшированной версии с той, что на текущий момент присутствует в базе. В случае, если версии различны, вызывается исключение. Вид сообщения с исключением зависит от источника записи.

• При записи в форме:

  

• При программном вызове метода объекта Записать();

  

Схематично это выглядит так:

Воспроизведем блокировку и посмотрим наглядно, что происходит.

Для этого в демо-базе УНФ в форме документа расходной накладной поставим точку останова в процедуре «ПриЧтенииНаСервере» и откроем какой-нибудь документ:

Выведем в табло поле «ВерсияДанных»:

• От поля «Объект» — та версия, что мы закэшировали «AAAAAAABgJl=».
• От дочернего поля «Ссылка» — та версия, что хранится в базе данных «AAAAAAABgJl=».

На текущий момент они равны:

Также можем посмотреть, как это выглядит в СУБД.

С помощью обработки «Структура хранения метаданных» находим для документа «Расходная накладная» имя таблицы СУБД — «_Document203»:

Наша демо-база развернута на MS SQL 19, поэтому мы можем зайти в Microsoft SQL Server Management Studio и найти запросом строку с тем же документом «АСФР-000024» в таблице _Document203. Версия данных хранится в поле «_Version»:

Видно, что значение отличается от того, что мы получили в отладке. Это связано с особенностью хранения и преобразования типов, об этом подробнее расскажем чуть ниже.

Далее открываем ещё один сеанс под другим пользователем, открываем тот же самый документ и нажимаем кнопку «Записать»:

В СУБД видно, что версия уже изменилась:

• Была 0×0000000000018092.

• Стала 0×00000000000180A3.

  

Теперь вернемся в сеанс первого пользователя, поставим точку останова в процедуре «ПередЗаписью» на клиенте и также пытаемся записать документ:

При этом видим, что:

• Закэшированная «ВерсияДанных» объекта осталась той же «AAAAAAABgJl=».

• Версию данных от ссылки через точку получить нельзя, так как мы находимся в клиентском контексте. Поэтому получаем её через специальную функцию, которая возвращает реквизит «ВерсияДанных» от ссылки, выполняя запрос на сервере. И видим, что версия в БД отличается «AAAAAAABgKM=»:

  

Как закономерный итог — получаем ошибку:

Похожим образом блокировка работает и при программном взаимодействии, меняется только вид сообщения.

Тема хранения версии данных в СУБД не относится к текущей статье, но если интересны подробности, предлагаем ознакомиться с небольшой заметкой. Если не интересны — переходите к следующему разделу «Пессимистическая блокировка».

Заметка про хранение версии в СУБД MSSQL и PostgreSQL

В отладке мы видели строку вида «AAAAAAABgYo=», для начала ответим на нижеследующий вопрос.

Какой тип у версии данных?

Мы нашли следующую информацию. Если в конфигруторе в синтакс-помощнике пройти в описание процедуры ЗаблокироватьДанныеДляРедактирования, можно найти упоминание, что ВерсияДанных это строка в формате Base64:

Однако, на стороне MSSQL мы видели значение другого вида «0×000000000001818A».

MSSQL

На первый взгляд можно сказать, что префикс «0x» указывает на то, что это шестнадцатеричное значение. Если заглянем в свойствах колонки _Version — там мы видим тип timestamp:

Получается, что версия данных — это некое число, которое хранится в бинарном виде. При этом в случае MSSQL платформа 1С использует механизм изменения версии при записи строки, который заложен в саму СУБД, то есть дополнительно делать этого не требуется.

Попробуем это проверить.

Зайдем в Management Studio и выполним запрос, получив текущую версию нашего документа «0×000000000001818A»:

Далее обновим строку прямым запросом в СУБД, в обход 1С:Предприятия. Например, повторно установим тот же самый номер (изменять значение не обязательно, главное — выполнение оператора UPDATE):

После чего снова получаем версию и видим, что она изменилась на «0×0000000000018274»:

Как получить из значения «0×0000000000018274» строку версии «как в 1С»?

Для нашей версии MSSQL Server 2022 мы нашли только способ, используя функции XML, через метод «xs:base64Binary()», который преобразует бинарные данные в строку типа base64:

SELECT  TOP (1000) [_IDRRef]

	,[_Version] 

		,CAST('' AS  XML).value('xs:base64Binary(sql:column("[_Version]"))',  'VARCHAR(MAX)') AS Base64String

		,[_Date_Time]

	,[_Number]      

  FROM  [base_name].[dbo].[_Document203]

  where _Number = 'АСФР-000024';

Как именно это преобразование делает платформа 1С не известно, по крайней мере, судя по тексту запроса в событии DBMSSQL из технологического журнала, колонка _Version выбирается, как есть:

PostgreSQL

Ради интереса мы развернули ту же самую демо-базу на PostgreSQL, чтобы узнать как обстоят дела с версией данных на этой СУБД.

Заглянули в pgadmin и выполнили запрос к тому же самому документу. Видим, что здесь также есть колонка _version, но в отличии от MSSQL она имеет обычный числовой тип «integer»:

На всякий случай проверим со стороны кода 1С — при открытии формы документа версия получается в том же формате base64:

Запишем документ, после этого видим, что версия в таблице СУБД увеличилась на единицу:

И судя по всему в случае PostgreSQL инкрементирование версии данных лежит полностью на плечах платформы. Проведем аналогичный эксперимент с прямым запросом на обновление.

Как в MSSQL перезапишем номер, тем самым обновив строку:

Снова выберем версию, как видно она не поменялась:

Так что вероятно за этим следит платформа 1С.

По поводу преобразования типов.

Если заглянуть в событие DBPOSTGRS технологического журнала, в тексте запроса можно увидеть, что версия выбирается через некий метод BINROWVER():

В документации PostgreSQL такого метода мы, увы, не нашли. Тогда решили поискать в разделе Functions нашей базы. И действительно — там есть такая функция:

Судя по всему функция нужна, как некая «прослойка», чтобы получить из типа integer бинарный тип, аналогично тому, как это было в MSSQL. И похоже, что эта функция добавлена самой платформой 1С.

При желании мы можем её использовать в своих запросах и получить строку в формате base64 с помощью метода encode:

SELECT _idrref, _version, _date_time,  _number,

	BINROWVER(_version),  encode(BINROWVER(_version),'base64')

FROM public._document203

where _number = 'АСФР-000024';

Пессимистическая блокировка

Проявление пессимистической блокировки можно увидеть в ситуации, когда в двух сеансах открывают форму одного и того же объекта и пытаются одновременно его редактировать.

Например, один пользователь открыл расходную накладную и изменил реквизит «Склад», далее другой пользователь (или тот же пользователь, но в другом сеансе) открыл тот же самый документ и при попытке что-либо изменить получает предупреждение системы:

Вид сообщения и его функционал зависят от вида базы (файловая или клиент-серверная) и наличия подключения к системе взаимодействия:

• В случае, если база не подключена к системе взаимодействия:
  • В файловом варианте — это будет чисто информационное сообщение о том, кто и когда заблокировал объект.
  • В клиент-серверном варианте — у нас появляется возможность начать редактировать объект несмотря на пессимистическую блокировку первого пользователя. При этом, увы, его изменения будут утеряны.

• Если же база подключена к системе взаимодействия, то и в файловом, и в клиент-серверном вариантах в сообщении также есть возможность начать редактирование.

  Но помимо этого появляется возможность отправить сообщение пользователю через личное обсуждение, например, с просьбой его закрыть объект. При этом в такое сообщение будет добавлена ссылка на объект:

  

Судя по всему именно этот вариант блокировки и срабатывал у пользователя в нашем расследовании, но что-то пошло не по плану.

Занимательный факт — пессимистические блокировки можно увидеть в консоли кластера. К теме статьи это не относится, но если интересно предлагаем ознакомиться с заметкой. Если не интересно — переходите к следующему разделу «Гипотезы».

Заметка про блокировки в консоли кластера

Если открыть консоль кластера, там перейдя в строку конкретной базы данных можно увидеть раздел «Блокировки».

У нас открыт только один сеанс тонкого клиента, поэтому сейчас здесь видим только некие блокировки ИБ и БД. Подробнее про них можно почитать на ИТС в разделе «Клиент-серверный вариант. Руководство администратора» (its.1c.ru/db/v8325doc#bookmark:cs:TI000000179):

Далее откроем документ расходной накладной и изменим реквизит «склад»:

В этот момент в консоли кластера видим, что появилась ещё одна строка с типом блокировки «Объект БД»:

Увы, в данном списке мы видим только факт блокировки, но какой конкретно объект заблокирован не понятно. Однако, для каждого такого заблокированного объекта в этом списке будет отдельная строка.

Также возможно упредим вопрос — управляемые блокировки и тем паче блокировки СУБД в этом списке похоже увидеть нельзя. Мы провели небольшой эксперимент, запустили проведение расходной накладной, установив точку останова сразу после метода «Заблокировать()» одной из управляемых блокировок. В списке блокировок в консоли в разрезе нашего сеанса тонкого клиента ничего нового не появилось:

Гипотезы

Теперь, когда мы подкрепились теоретическим основанием, вернемся к нашему случаю. Ясно, что у нас срабатывает пессимистическая блокировка, которая, как видим по описанию на ИТС, может быть тесно связана с системой взаимодействия.

На это также недвусмысленно намекает текст сообщения «Обсуждение уже существует»:

К тому моменту база, в которой произошла эта ситуация, была подключена к развернутому на собственных мощностях Серверу взаимодействия. Связь с системой взаимодействия стала более явной и мы решили изучить логи сервера.

Логирование сервера взаимодействия

В первой части цикла статей мы описывали порядок запуска сервера взаимодействия и вскользь упоминали его логи. Для начала расскажем про них чуть поподробнее.

Где лежат логи?

Напомним, что основу сервера составляют три компоненты — cs, elasticsearch и hazelcast, для каждой из них мы создавали инстанс и службу:

1. cs — головная служба сервера взаимодействия.
2. hazelcast — распределенное хранилище в памяти, в котором обслуживаются сессии/очереди/события.
3. elasticsearch — служба поиска, обеспечивает полнотекстовый поиск и подбор пользователей.

Инстансы мы инициализировали специальной командой утилиты ring, в этой команде в параметре dir обязательно задается путь к рабочей папке:

Пример для нашего демо-стенда из прошлой статьи:

Каждый инстанс ведет свой лог внутри рабочей папки в подпапке «logs»:

Чтобы узнать какие инстансы развернуты на сервере и найти путь к рабочей папке, можно воспользоваться командой:

где Компонент принимает значение cs / hazelcast / elasticsearch.

Например:

В ответном сообщении будет приведен список экземпляров и в поле «Расположение» указана рабочая папка:

Логи инстанса cs

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

Для начала оценим содержимое папки logs. Для пущего интереса зайдем не в наш демо-стенд, который был развернут в прошлый раз (там скорее всего мало логов), а окинем взглядом логи нашего продуктивного сервера:

Что ж, количество и разнообразие файлов здесь весомое. Попробуем разобраться что они из себя представляют.

launcher.log

Посмотрим на структуру файла:

Каждое событие лога начинается с даты/времени вплоть до миллисекунд, также можно обратить внимание на поля:

• level — по нему можно определить критичность события, например есть значения INFO и ERROR.
• message — собственно текст события.

Т. к. логи имеют текстовый формат, как и логи ТЖ, следовательно можно применить аналогичные методы анализа. Выполним bash-команду, которая отсеет все поля, кроме поля message:

Судя по содержимому в этот файл записывается последовательность действий, которая совершается при запуске и завершении службы инстанса:

По опыту наших расследований — из полезного здесь в событиях уровня ERROR можно найти причину, по которой служба может не запускаться. Например, в прошлой статье мы упоминали ошибку запуска с переменной JAVA_HOME:

server.log

По формату похож на launcher.log, здесь также есть дата/время и поля level и message:

Также по наблюдениям здесь могут попадаться многострочные события, это нужно учитывать при анализе bash-командами:

По наполнению — похоже это основной лог функционирования сервера, соответственно при каких-либо вопросах, связанных с работой уже запущенного сервера, имеет смысл в первую очередь заглядывать в него.

К примеру, в одном из прошлых расследований при попытке подключения к серверу взаимодействия базы с несовместимой версией платформы именно в этом файле может попадаться сообщение вида:

Другие файлы

Также в папке логов есть ещё три файла:

1. websocket,
2. syserr,
3. sysout.

Однако, и на продуктивном сервере взаимодействия, и на демо-стенде полезных предупреждений или ошибок мы в них не видели. Файл websocket всегда был пуст, syserr наполнен некими предупреждениями о внутренних операциях, а в sysout единственное мы ловили сообщение о переменной среды JAVA_HOME, но кроме самого сообщения ни даты ни источника ошибки в нём нет:

Конфигурационный файл

Для управления сбором логов можно использовать файл logging.yml в директории config внутри рабочей папки службы сервера:

Файл разбит на две секции — handlers и loggers. Предположительно, в секции loggers указываются утилиты/механизмы, которые собирают логи событий, а в секции handlers — обработчики потока этих логов, которые должны будут записать их на диск. Причем сборщики логов привязываются к обработчикам по имени:

В обработчиках handlers указывается ещё ряд настроек, например, имя сохраняемого файла и некие ограничения файлов:

• limit — задает максимальный размер в байтах, при превышении которого будет создаваться новый файл.
• count — задает максимальное количество сохраняемых файлов, судя по всему более старые будут удаляться.

На примере файлов server видно, что эти условия соблюдаются — файлов действительно 10 шт., и их размеры 9766КБ, что чуть больше 10 000 000 Байт:

Правда, для файлов websocket логика с условием по размеру не прослеживается, так что, вероятно, правила чуть сложнее.

По опыту работы с технологическим журналом можно было бы подумать, что процесс сбора логов полностью зависит от настроек файла logging.yml, аналогично тому, как это работает с logcfg.xml. Но, как мы упоминали, в папке логов кроме server и websocket были ещё файлы launcher, sysout, syserr, однако в конфигурационном файле секций с ними нет.

Ради эксперимента, на нашем демо-стенде мы удалили файл logging.yml, удалили все текущие файлы логов и перезапустили сервер. Заглянем в папку логов:

• Файл websocket не восстановился.
• Файл server восстановился, но предполагаем, что теперь часть событий в нём не будет логироваться и, вероятно, теперь не будет соблюдаться ограничение на количество и размер.

Судя по всему даже без файла logging.yml некий минимальный уровень логирования предусмотрен в сервере по умолчанию.

Уровни событий

Помимо прочего в файле logging.yml можно заметить настройки уровня событий — level. Мы попробовали разобраться что это и как его использовать.

Сначала предположили, что варианты уровней схожи с аналогичным параметром в технологическом журнале.

Похоже, но не совсем то.

Далее мы проанализировали некоторые конфигурационные файлы сервера взаимодействия и в итоге вышли на файл launcher.yml, который ранее видели в логах. В нём мы подробно не разбирались, но в строке с подключаемыми модулями можно найти строку log4j:

Этот список уже больше похож на правду.

Попробуем поменять уровни в файле logging.yml и посмотрим, какие события мы сможем поймать. Возможно, это пригодится в будущем.

Повышение уровней логирования server.log

Сначала в секции loggers для элемента с именем ROOT повысим уровень логирования с WARN до DEBUG:

Чтобы настройки вступили в силу перезапустили службу сервера командой:

С уровнем DEBUG в логе начали появляться события с текстом SQL-запросов. Например, вот обращение к таблице context_conversation (связи идентификаторов обсуждений и идентификаторов объектов контекста):

Однако, значений параметров этого запроса поблизости мы не нашли, так что кажется такой вариант лога малополезен.

Поэтому переключимся в самый подробный режим логирования TRACE:

Перезапускаем службу и создадим обсуждение с темой «Тестовое 3!»:

Теперь в режиме TRACE в логе можно увидеть запросы со всеми параметрами в соседних событиях:

Это можно использовать в расследованиях, как некий аналог событий DBMSSQL/DBPOSTGRS из лога ТЖ, что нам ещё пригодится в будущем.

В режиме подробного логирования файлы заполняются очень быстро даже в тестовом стенде, в котором никто толком не работает. Конечно, исходя из настроек лимитов файлов переполнение диска нам не грозит, но нужно иметь ввиду, что важное событие может быть достаточно скоро затерто новыми логами:

Повышение уровней логирования websocket.log

Выше мы писали, что при стандартных настройках в файлах websocket.log обычно ничего нет. А что если в секции loggers для элементов с обработчиком websocket-file установить уровень TRACE:

Также перезапускаем сервер. Пробуем создать обсуждение, сообщение, переподключиться к серверу. Увы, в логах по прежнему пусто:

А вот похоже и причина — у настройки handler обработчика есть своя настройка уровня события = WARN, видимо, она отсекала подробные логи. Поменяем её тоже:

Пробуем создать обсуждение и сообщение:

И находим в логах websocket.log записи с информацией о методах, по которым в принципе можно понять, что происходит. А также о передаваемых свойствах объектов.

Создание обсуждения:

Создание сообщения:

Полагаем, эту информацию уже можно использовать в каких-либо расследованиях.

Логи инстансов elasticsearch/hazelcast

У обеих служб elasticsearch и hazelcast в логах есть файлы launcher.log, в которых мы ранее уже находили полезную информацию в случае если по какой-то причине служба не запускается:

Однако, подробно разбираться в логах этих служб нам пока не представилось случая. Уже на первый взгляд их конфигурационные файлы настраиваются совсем по иной логике, нежели у службы cs. Полагаем, что их разбор выходит за рамки статьи.

Продолжение расследования — изучение логов сервера взаимодействия

Вернемся к нашему расследованию.

Что именно искать в логах сервера взаимодействия мы на тот момент не знали, поэтому идея была простой — воспроизвести ошибку (благо в этом проблемы не было) и посмотреть последние события в самом свежем измененном файле лога.

Повторяем ситуацию с пессимистической блокировкой, ловим заветное сообщение:

Для верности повторяем ситуацию несколько раз.

Далее идем в папку логов службы cs и сортируем файлы по дате изменения, самым свежим оказался файл server.log:

Следуем в самый конец файла и находим сообщения следующего содержания «Conversation with key 9A5D8A84-35F4-4319-B45B-284089201110 already exists»:

К слову, в нашем случае парсинг не понадобился, но на всякий случай приведем bash-скрипт, которым при необходимости можно проанализировать события уровня ERROR:

Данный скрипт считывает все файлы server.log, приводит события к однострочному виду, отсеивает по строке «level=ERROR» и берет первые 3 события. Результат будет выглядеть подобным образом:

Conversation with key already exists

Итак, мы нашли сообщение «Conversation with key 9A5D8A84-35F4-4319-B45B-284089201110 already exists». Строго по тексту оно соответствует нашей ошибке «Обсуждение уже существует», но что за ключ?

Насколько нам было известно, в исследуемой базе на тот момент механизм системы взаимодействия не был задействован в доработках «для коммуникации между сервером и клиентом», следовательно, никаких специальных обсуждений с заданным ключом не должно было быть. Создается впечатление, что это некое служебное обсуждение, которое платформа использует в связке с сообщением о том, что объект уже редактируется.

Странное обсуждение

Далее, чтобы подтвердить или опровергнуть догадку о платформенном обсуждении мы хотели взглянуть на его сообщения.

Для этого воспользовались методами менеджера СистемаВзаимодействия:

• ПолучитьОбсуждение,
• ПолучитьСообщения.

Обсуждение = СистемаВзаимодействия.ПолучитьОбсуждение("9A5D8A84-35F4-4319-B45B-284089201110");

Сообщить(Обсуждение = Неопределено);

Отбор = Новый ОтборСообщенийСистемыВзаимодействия;

Отбор.Обсуждение = Обсуждение.Идентификатор;

МассивСообщений = СистемаВзаимодействия.ПолучитьСообщения(Отбор);

МассивТекстСообщений = Новый Массив;

Для Каждого Элемент Из МассивСообщений Цикл

            МассивТекстСообщений.Добавить(Строка(Элемент.Текст) + " - " + Элемент.Дата);

КонецЦикла;

Сообщить(СтрСоединить(МассивТекстСообщений, ";")); 

Ответ выглядел так:

Содержимое сообщений явно говорило в пользу нашей гипотезы, что это служебное обсуждение.

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

Устройство сервера взаимодействия на стороне СУБД

Прежде, чем продолжить расследование, расскажем немного про внутреннее устройство СУБД сервера взаимодействия. Нижеследующая информация касается версии сервера 26.0.54.

Какой-либо методической информации по структуре СУБД мы не нашли, так что содержимое данного раздела основано целиком на наших наблюдениях.

Общее описание

В первой части цикла статей в разделе «настройка JDBC-драйвера» мы упоминали, что хранение информации сервера взаимодействия разделено условно на две части, назовем их «Основная база» и «База хранения данных абонентов». Это могут быть разные базы данных, а может быть и одна база для простых случаев. В любом варианте таблицы этих двух частей будут разведены по разным схемам:

Также важно упомянуть, что эти части в сервере взаимодействия настраиваются по-разному.

Основная база

Что хранит:

• Административные настройки — соответствия абонентов, приложений, пользователей.
• Конфигурации дополнительных систем — информацию о подключенных медиасерверах, файловых серверах, а также адресацию хранения данных абонентов.

Основная база настраивается через команду утилиты ring, в ней указывается инстанс PostgreSQL, имя базы, схема и другие параметры. Подробности см. в предыдущей статье. Пример такой команды:

Список таблиц основной базы такой:

База хранения данных абонентов

Что хранит: списки обсуждений и участников обсуждений, данные сообщений, связи идентификаторов контекстных обсуждений и другую сопутствующую информацию.

Настройка отличается от основной базы, она выполняется не через утилиту ring, а с помощью специального http-запроса к интерфейсу обслуживания, подробнее также читайте в прошлой статье в разделе «Инициализация базы данных». Пример такой команды:

Причем схему этой базы мы при настройке сервера нигде не указываем, она имеет наименование вида «vb_subscriber_№», где № определяется по некой внутренней логике сервера и начинается с «13». По наблюдениям для каждой настроенной базы в момент подключения приложения с новым абонентом создается своя схема. В нашем случае было подключено две базы, в одной создалась схема vb_subscriber_13_13, во второй vb_subscriber_14_14.

Список таблиц Базы хранения данных абонентов, следующий:

Таблиц в сервере множество, цели исследовать их все в данной статье у нас не было. Но мы выделили несколько важных на наш взгляд «контуров» — то есть наборов связанных таблиц. Расскажем о них поподробнее.

Основная база — контур абоненты-приложения-пользователи

Контур представлен тремя таблицами:

• subscriber — список абонентов, когда-либо подключавшихся к серверу.
• application — здесь находится список подключений к базам. В рамках одного абонента может быть подключено несколько баз, в том числе с синхронизацией пользователей между ними.
• user — в этой таблице хранятся записи о пользователях системы взаимодействия. Как правило, запись создается автоматически при первом входе пользователя в 1С, но при желании можно сделать это либо в обработке «Управление системой взаимодействия», либо программно, через объектную модель системы взаимодействия.

Таблица subscriber

Пояснения по некоторым полям:

• id — внутренний идентификатор, его можно использовать для связи с другими таблицами СУБД с полем subscriber_id.
• credential — идентификатор абонента, тот самый, что был указан в форме обработки регистрации базы на сервере взаимодействия.
  Со стороны 1С приложения его можно изменить из встроенной обработки «Управление системой взаимодействия».
• bucket_id — некий индекс «virtual bucket» — используется для адресации базы хранения данных абонента, сама адресация хранится в таблице vb_mapping.
• created_at/updated_at — даты создания и изменения свойств абонента.
• adminisration_key_hash — предположительно хранит хэш ключа администратора.
  Подробнее о том, что это такое можно почитать на ИТС в Руководстве разработчика — Работа со списком администраторов абонента (its.1c.ru/db/v8325doc#bookmark:dev:TI000002769).
• enabled, is_deleted, on_maintenance — некие управляющие флаги, на что конкретно они должны влиять не понятно.
  • Для теста мы выставили для одного абонента все три флага в иное положение, в подключенном приложении базовый функционал (создание обсуждений, сообщений, звонки) остался доступен.
  • Но как бы то ни было, какого-либо управления ими со стороны 1С:Предприятия — нет. Ни из обработки «Управление системой взаимодействия», ни объектными методами.
• video_enabled — по логике флаг коррелирует с объектным методом ПоддерживаютсяВидеоконференции(), однако, в наших тестах изменение флага ни на этот метод, ни на возможность звонков не повлияло. Истинное назначение пока от нас ускользает, возможно поймем в будущих разборах.

Таблица application

Пояснения по некоторым полям:

• id — внутренний идентификатор, его можно использовать для связи с другими таблицами СУБД с полем application_id.
• Следующие поля согласно инструкции на ИТС (its.1c.ru/db/v8325doc#bookmark:dev:TI000001902) называются «данными регистрации приложения»:
  • client_id — идентификатор приложения, генерируется автоматически при регистрации базы на сервере взаимодействия. Можно получить объектным методом ИдентификаторТекущегоПриложения() менеджера системы взаимодействия.
  • title — наименование приложения, что было указано в форме обработки регистрации базы на сервере взаимодействия.
  • ecs_private_key, ecs_public_key, app_public_key — предположительно криптографические ключи, о которых упоминается на ИТС.
• subscriber_id — внутренний идентификатор абонента, по нему можно связать с таблицей subscriber по полю id.
• subscriber_bucket_id — индекс «virtual backet», по-видимому дублирует значения поля bucket_id таблицы subscriber.
• is_deleted — поле используется для некой установки пометки удаления текущей строки приложения:
  • Причем судя по экспериментам оно не взводится в «истина» при отмене регистрации, а только после повторной регистрации того же приложения. В этом случае в таблицу добавится новая строка с теми же полями id/client_id.

  • Если же после отмены регистрации в базе 1С удалить текущие данные регистрации с помощью метода
    УстановитьДанныеРегистрацииИнформационнойБазы(Неопределено) и заново зарегистрировать приложение, то в таблице будет создана строка уже с новыми идентификаторами:

    

Таблица user

Пояснения по некоторым полям:

• id — идентификатор пользователя системы взаимодействия, его можно получить объектным методом ПолучитьИдентификаторПользователя() менеджера системы взаимодействия, а также использовать для связи с другими таблицами.
• application_id — идентификатор приложения, можно использовать для отбора по текущей базе, или для связи с таблицей application по полю id.

• Следующие поля являются свойствами пользователей, которые соответствуют колонкам в разделе «Пользователи» обработки «Управление системой взаимодействия», многие из них можно тут изменить:

  

  • name/full_name — Имя и полное имя пользователя. Похоже эти поля синхронизируются с соответствующими полями пользователя ИБ. Изменить их в обработке нельзя.

  • nickname — псевдоним пользователя, который можно задать в обработке.
    Согласно справке синтакс-помощника:

    Содержит псевдоним пользователя, с которым пользователь отображается во внешних системах (например, в интеграции типа «WebChat»). В интерфейсе клиентских приложений «1С:Предприятия» данное имя не отображается.

  • phone, email, picture — номер телефона, адрес электронной почты и картинка, которые отображаются в свойствах пользователя в интерфейсе системы взаимодействия:

    

  • blocked — флаг блокировки пользователя. Заблокировать и разблокировать пользователя можно в обработке. У заблокированного пользователя отключится возможность отправлять сообщения, а при повторном входе в 1С список обсуждений будет пуст, при некоторых интерактивных действиях в окне системы взаимодействия будет выдано предупреждение:

    

Связь таблиц

Для примера представим прикладную задачку. Хотим получить список пользователей с информацией по абоненту по текущему приложению.

Для этого сначала получим идентификатор приложения: вызовем в выбранной базе метод ИдентификаторТекущегоПриложения() объекта СистемаВзаимодействия.

Он возвращает значение типа «ИдентификаторПриложенияСистемыВзаимодействия», если привести его к строке, получим идентификатор «665eb34e-1756-4b2a-bb2c-161874c6de25», который соответствует колонке client_id в таблице applications.

Далее, например, в pgadmin можем выполнить запрос, который свяжет данные абонентов, приложений и пользователей и выведет информацию по текущему идентификатору приложения:

SELECT 

subs.credential,

app.title,

users.name,

users.full_name

FROM public.user as users

	inner join public.application  as app

		inner  join public.subscriber as subs

		on  app.subscriber_id = subs.id

		and app.client_id  = '665eb34e-1756-4b2a-bb2c-161874c6de25'

		and  not subs.is_deleted and subs.enabled

	on  users.application_id = app.id

	and  not app.is_deleted

where not users.is_deleted and not users.blocked

order by users.name

Limit 100; 

Основная база — контур адресации «Виртуальные корзины»

Как мы уже писали выше, сервер взаимодействия позволяет указать несколько баз для хранения данных абонентов — обсуждений, сообщений и т. д. Параметры доступа к этим базам хранятся в таблице bucket_server основной схемы:

Эти настройки можно добавить, получить или изменить извне через http запрос, например из консоли с помощью утилиты curl. Подробнее об этом можно почитать в прошлой статье .

Схема адресации по нашим наблюдениям выглядит примерно так:

1. При регистрации нового приложения с новым абонентом ему присваивается индекс «virtual bucket» — bucket_id.
2. По некоторой логике происходит выбор базы из доступных в таблице bucket_server и в ней создается схема с именем vb_subscriber_# (если она ещё не существует).
3. В итоге в таблицу vb_mapping прописывается соответствие:
   1. key — индекс корзины bucket_id.
   2. db_schema — имя схемы «vb_subscriber_#».
   3. db_connection — параметры подключения к базе.

Схема связей с учетом таблиц адресации хранения:

База хранения данных абонентов — контур обсуждения-сообщения-контексты

Контур представлен следующими таблицами:

• conversation — в этой таблице размещена информация обо всех обсуждениях — личных, контекстных и остальных.
• conversation_message — данные по всем сообщениям.
• context_in_application — отдельная таблица только для контекстных обсуждений, в которой есть навигационная ссылка на объект базы — тот самый «контекст».
• context_conversation — таблица, позволяющая связать таблицы conversation и context_in_application.

Таблица conversation

Пояснения по некоторым полям:

• id — внутренний идентификатор обсуждения, его можно использовать для связи с другими таблицами СУБД с полем conversation_id. Также его можно получить объектным методом, из свойства «Идентификатор» объекта «ОбсуждениеСистемыВзаимодействия».
• application_id/subscriber_id — идентификаторы приложения и абонента соответственно.
• Ряд полей, соответствующие свойствам объекта обсуждения:
  • title — «Заголовок»;
  • key — «Ключ»;
  • visible — «Отображаемое»;
  • face_to_face — по сути определяет является ли обсуждение «Личным», но такого флага в свойствах нет, так что видимо это инвертированное свойство «Групповое».
• contextual — флаг, означающий является ли обсуждение контекстным.
• created_at/updated_at — даты создания и изменения свойств обсуждения.
• last_message_id/last_message_at — идентификатор и дата последнего сообщения.

Таблица conversation_message

Пояснения по некоторым полям:

• id — внутренний идентификатор сообщения. Соответствует свойству «Идентификатор» объекта «СообщениеСистемыВзаимодействия».
• application_id/subscriber_id — идентификаторы приложения и абонента соответственно.
• author_id/recipients — идентификаторы автора и получателей соответственно.
• created_at/updated_at — даты создания и изменения свойств обсуждения.
• text — текст сообщения.

Связь таблиц

Также обсуждения можно связать через промежуточную таблицу context_conversation с таблицей context_in_application, в которой в поле object_key находится навигационная ссылка на объект 1С:

Для примера покажем запрос, которым можно выбрать для конкретного приложения — данные обсуждений, его сообщений и связь с объектом прикладной базы. В условии отбираем по полю application_id таблицы conversation, используем идентификатор приложения из предыдущего примера ‘665eb34e-1756-4b2a-bb2c-161874c6de25’:

SELECT 

	cnv.title "Тема обсуждения",

	cnv.face_to_face "Личное",

	cnv.contextual "Контекстное",

	cntx_app.object_key "Навигационная ссылка",

	msg.text "Текст сообщения"

	FROM vb_subscriber_13_13.conversation cnv

		inner join vb_subscriber_13_13.conversation_message msg

			on cnv.id = msg.conversation_id

			and cnv.application_id = '665eb34e-1756-4b2a-bb2c-161874c6de25'

		left join vb_subscriber_13_13.context_conversation cntx_cnv

			inner join vb_subscriber_13_13.context_in_application cntx_app

				on cntx_cnv.context_id = cntx_app.context_id

			on cnv.id = cntx_cnv.conversation_id

order by

	cnv.face_to_face,

	cnv.contextual,

	msg.created_at

Limit 100; 

Расследование — изучаем таблицы сервера

Итак, теперь «мы знаем кунг-фу», как сказал бы Нео. Но нет, мы лишь немного начали ориентироваться в базе данных сервера взаимодействия.

Мы при расследовании пришли к базе данных за ответами. А чтобы задать вопросы мы зашли в pgadmin. На момент расследования мы ещё кунг-фу не владели, поэтому для начала просто хотели найти это злосчастное обсуждение по ключу. Для этого выполнили запрос по всем полям к таблице обсуждений conversation с отбором по полю key равному найденному ключу из лога сервера:

SELECT *

	FROM vb_subscriber_13_13.conversation

	where key = '9A5D8A84-35F4-4319-B45B-284089201110'

limit 100

Как ни странно — мы нашли и даже не одно:

Тут мы обратили внимание, что таких обсуждений ровно 4, столько же, сколько продуктивных баз подключено к серверу взаимодействия, причем у одного из обсуждений некоторые свойства выделяются среди остальных. Тогда мы чуть усложнили запрос, выбрав ещё и имена приложений, и отобрав только интересующие нас поля из таблицы обсуждений. Получился такой запрос:

SELECT 

	t2.title, 

	t1.key, 

	t1.title, 

	t1.is_deleted, 

	t1.visible, 

	t1.face_to_face, 

	t1.contextual, 

	t1.accessible_to_everyone

FROM vb_subscriber_13_13.conversation as t1

	left join  public.application as t2

		on  t1.application_id = t2.id     

		and not  t2.is_deleted

	where key =  '9A5D8A84-35F4-4319-B45B-284089201110'
	limit 100

В результате увидели, что именно в базе, в которой случилась проблема, поля title и accessible_to_everyone у обсуждения отличаются от обсуждений остальных баз, в которых подобной ошибки не было:

И в тот самый момент мы вспомнили, что только эта база из четырех примерно за год до нашего случая, была переведена с подключения к сервису «1С:Диалог» на собственный сервер взаимодействия, остальные базы изначально были подключены к нему.

Про переход с 1С:Диалог на собственный сервер взаимодействия

Текущая база несколько лет жила в сервисе «1С:Диалог». В определенный момент было принято решение по переезду на свой сервер взаимодействия. Можно было просто переключить базу между серверами — это заняло бы пару минут. Но терять накопленные за время эксплуатации обсуждения не хотелось, да и в любом случае пришлось бы заново регистрировать всех пользователей в системе взаимодействия. Поэтому возникла задача по перегрузке данных — информации о пользователях, обсуждениях и сообщений.

Процесс перехода можно описать следующими этапами:

1. Получение информации по пользователям, обсуждениям, сообщениям и выгрузка в файл.
2. Переподключение на свой сервер взаимодействия.
3. Загрузка информации из файла выгрузки и создание пользователей, обсуждений и сообщений.

Все операции по получению данных и созданию объектов производились с использованием методов менеджера системы взаимодействия «СистемаВзаимодействия».

С помощью метода ПолучитьПользователей() получен массив пользователей Системы взаимодействия и выгружен в файл:

Используя метод ПолучитьОбсуждения() мы получили массив обсуждений Системы взаимодействия:

Затем внутри цикла перебора обсуждений для каждого обсуждения получили массив сообщений Системы взаимодействия, используя метод ПолучитьСообщения() и инициализированный ранее объект ОтборСообщенийСистемыВзаимодействия. Полученные сообщения выгрузили в файл:

В результате работы процедуры выгрузки получаем файл в формате json c данными обсуждений Системы взаимодействия:

Далее база была отключена от сервиса 1С:Диалог и подключена к собственному серверу взаимодействия:

После этого приступили к загрузке информации из json.

В первую очередь при помощи метода СоздатьПользователя() были добавлены пользователи СистемыВзаимодействия.

Далее с помощью метода СоздатьОбсуждение() были загружены обсуждения из файла выгрузки. Для поиска существующих обсуждений использовался метод ПолучитьОбсуждения(), в отборе которого передавался контекст обсуждения или ключ, исключающий дублирование обсуждений при повторной загрузке:

Для каждого обработанного обсуждения создаем сообщения системы взаимодействия с помощью метода СоздатьСообщение(). При создании передаем в метод в качестве параметра идентификатор обсуждения, созданный на предыдущем шаге:

На этом переход на свой сервер взаимодействия был завершен.

Конечно, процесс перехода не был простым, предполагал многоитерационное тестирование, в процессе которого пришлось решить ряд задач, например, по привязке прежних идентификаторов пользователей, корректной загрузке свойств личных/групповых обсуждений и других. Но об этом может быть расскажем в другой раз.

Главное, что после переезда на свой сервер взаимодействия в течение года не наблюдалось каких-то проблем.

Исправление ключа

На момент расследования мы предположили, что в процессе «переезда» скорее всего не разделяли обсуждения на служебные и обычные. Тем более какого-либо признака, который однозначно говорил бы о том, что это обсуждение служебное, кажется, не существует. И судя по всему, создание нашего проблемного обсуждения через объектные методы по какой-то причине заполнило нужные поля title/accessible_to_everyone не так, как это заложено в платформе.

Получается для устранения коллизии можно было бы привести отличающиеся поля к общему виду или удалить обсуждение, чтобы система сама пересоздала его.

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

Для этого зашли в pgadmin и выполнили команду UPDATE замены ключа:

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

После проделанных манипуляций мы повторили ситуацию с пессимистической блокировкой:

И (ура-ура!) в результате ошибки не оказалось!

Было показано обычное сообщение о попытке начала редактирования, кнопка «Начать редактировать» сработала как надо и без проблем. Никакого сообщения про обсуждение не появилось и мы смогли внести изменения в документ.

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

Истинные причины возникновения ситуации

В тот раз до истинной причины мы в расследовании не дошли. Лишь предположили, что при переезде на свой сервер взаимодействия при загрузке информации была допущена ошибка, но так как наше исправление сработало и проблема более не проявлялась, мы на этом остановились.

Однако, спустя некоторое время, уже имея на руках рабочий демо-стенд с сервером взаимодействия, а также получив знания о наполнении логов, при написании текущей статьи у нас появилась идея прояснить ситуацию.

Для этого мы хотели «поймать» запрос, который выполняет платформа в момент нажатия на кнопку «Начать редактировать» при пессимистической блокировке.

Чтобы это сделать для начала выставляем самый подробный уровень детализации лога = TRACE в файле logging.yml:

Чтобы настройки конфигурационного файла «подхватились» перезапускаем основную службу сервера с помощью команды:

Воспроизводим ту же ситуацию с пессимистической блокировкой и нажимаем кнопку «Начать редактировать»:

Пользователю уходит оповещение:

Теперь идем смотреть логи.

Для начала поисследуем файл websocket.log.

Увы, никаких запросов с SELECT или INSERT мы не нашли, хотя в нём можно увидеть информацию о выполняемых операциях. Например, следующим bash-скриптом мы выбрали события, в тексте которых содержался ключ служебного обсуждения ‘9A5D8A84-35F4-4319-B45B-284089201110′, а также события рядом с ним, содержащие текст «conversation»:

В результате в файле можно увидеть последовательность операций, которая происходила в тот момент. Видно, что выполняется попытка получения обсуждения, далее создание обсуждения и сообщения:

Но это не совсем то что мы искали, поэтому перешли к файлу server.log

Для его анализа применили похожий подход поиска событий со служебным ключом, а также событий рядом с текстом SELECT/INSERT:

В результирующем файле, как раз на момент времени нажатия на кнопку, мы нашли два идущих подряд события, в одном из которых содержался текст запроса, а в следующем за ним — все значения параметров этого запроса:

Если убрать всё «лишнее» и упростить этот запрос, то он сводится к следующему:

Происходит объединение двух выборок из таблицы conversation, условия в них одинаковы кроме последнего:

1. В первой выборке в условии выполняется коррелированный запрос к таблице conversation_member с отбором по идентификатору пользователя.
2. Во второй выборке ставится отбор по полю accessible_to_everyone.

Говоря простым языком — происходит попытка найти обсуждения, либо в которых текущий пользователь является участником, либо обсуждения «доступные для всех». Попробуем ответить на вопрос, что это значит.

Если выбрать участников корректных служебных обсуждений, например подобным запросом в pgadmin:

SELECT members.*

	FROM vb_subscriber_13_13.conversation as conversations

	INNER JOIN vb_subscriber_13_13.conversation_member as members

		ON conversations.id = members.conversation_id

		AND conversations.key = '9A5D8A84-35F4-4319-B45B-284089201110';

То во всех них увидим ровно одного пользователя с идентификатором «5c9f6038-0026-4439-98d4-1a1a1eb403df»:

Но пользователя с таким идентификатором в таблице user вы не найдете, потому что это это не обычный пользователь, а некий зарезервированный uuid для обозначения «широковещательного» пользователя «ВсеПользователиПриложения». В этом можно убедиться, выполнив команду на стороне 1С:

И похоже, что этот идентификатор всегда один и тот же для разных баз, как и ключ служебного обсуждения.

Более того, именно наличие этого пользователя в участниках приводит к установке флага accessible_to_everyone, который никакими свойствами объекта обсуждения со стороны 1С не управляется. Чтобы проверить это утверждение, на демо-стенде создаем обсуждение с одним участником «ВсеПользователиПриложения» и спецключом «Доступное всем обсуждение», чтобы его потом найти:

НовоеОбсуждение = СистемаВзаимодействия.СоздатьОбсуждение();

  НовоеОбсуждение.Групповое = Истина;

  НовоеОбсуждение.Ключ = "Доступное всем обсуждение";

  НовоеОбсуждение.Участники.Добавить(СистемаВзаимодействия.СтандартныеПользователи.ВсеПользователиПриложения);

  НовоеОбсуждение.Записать();

Далее делаем выборку по ключу «Доступное всем обсуждение» и, как результат, видим у обсуждения выставился флаг:

Если же выбрать участников в том самом проблемном обсуждении с изменённым ключом, то в нём увидим совсем иной идентификатор, который соответствует одному из пользователей базы:

По-видимому, в этом и крылась основная причина.

Но тут вы можете поймать нас на слове «Ведь вы говорили после переноса из 1С:Диалога целый год пользователи работали, неужели никто не жаловался?!».

И ведь правда, проблема как будто возникла только после перехода с версии 8.3.17.2306 на 8.3.21.1895.

В этом месте мы можем только предположить, что на более старых версиях платформа не использовала поле accessible_to_everyone при поиске служебного обсуждения и благополучно его находила. А после обновления появился отбор, из-за которого найти обсуждение не получается, но и создать не удается, т. к. уже существует обсуждение с таким ключом.

Данные сообщения UnblockObjectMsg

А помните те странные сообщения с текстом «UnblockObjectMsg»? Напоследок предлагаем взглянуть на них. При наших изысканиях мы обратили внимание, что у всех сообщений служебного обсуждения заполнено поле «data»:

Анализировать его в «сыром» виде можно, но это дело неблагодарное. Можно пойти другим путём — выловить это сообщение в отладке. В инструменте «Вычислить выражение» конфигуратора видим поле «Данные» с типом «Структура»:

И если раскрыть его детально, становится понятно, что эти сообщения как раз используются для оповещения пользователя, у которого «перехватили» редактирование объектом:

Послесловие

Так часто случается в профессиональной жизни эксперта, что внешнее проявление не связано напрямую с истинными причинами происшедшего. В нашем случае дивным образом вылезали пессимистические объектные блокировки, а на самом деле вышло так, что во всем виновен неверный подход к переносу данных из 1С:Диалог на собственный Сервер взаимодействия. И как круги по воде мы начали расширять свои знания, попутно вспоминая сущность объектных блокировок, погружаясь в устройство БД Системы взаимодействия, ее логирование, наполнения данными таблиц СУБД.

Таков путь эксперта: ему неизбежно приходится заглядывать в потаенные комнаты, освещать фонариком темные уголочки. И поскольку нам было это и сложно, и интересно сделать, то мы решили поделиться с вами, уважаемые коллеги!