9 октября 2020 г.

Добавление EurekaLog в программу вызывает Access Violation?

К нам обратился человек, который пожаловался на то, что его приложение работало нормально, пока он не добавил в него EurekaLog. После включения в проекте EurekaLog стало появляться исключение AccessViolation с текстом Access violation at address 00E15025 in module 'Project.exe'. Read of address 83EC8B69 и таким стеком:
  • Contoso.pas TContosoEventMessage.BasePerform
  • Vcl.Forms.pas TApplication.WndProc
  • System.Classes.pas StdWndProc
  • Vcl.Forms.pas TApplication.HandleMessage
  • Vcl.Forms.pas TApplication.Run
  • Project.dpr Initialization
(все имена заменены; Contoso - это некая известная библиотека для Delphi).

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

Адрес в сообщении об ошибке (83EC8B69 - "случайный") и короткий стек могут указывать на проблему "управление ушло по мусорному указателю и вылетело в случайном месте". К сожалению, в отчёте не были включены секции CPU и ассемблера (отключены в настройках). В этом случае диагностика по исходному коду была бы невозможной. Признаться, я сначала хотел так и ответить, дав рекомендацию по усилению контроля за памятью.

Но вот именно такой стек возможен также в случае, если BasePerform вызывается главным потоком как процедура, поставленная в очередь для Synchronize. И действительно - поиск по исходникам выдал такой код:
function TContosoEventMessage.Perform(AThread: TContosoThread): Boolean;
begin
  FMsgThread := AThread as TContosoEventThread;
  if FMsgThread.Active then begin
    if FMsgThread.Options.Synchronize then
      TContosoThread.Queue(nil, BasePerform)
    else
      BasePerform;
  end;
  Result := True;
end;
Т.е. у класса сообщения есть функция для обработки этого сообщения. И если в опциях чего-то там указан флаг Synchronize, то непосредственно обработка сообщения (BasePerform) будет выполнена не в текущем потоке, а будет отправлена на выполнение в главный поток - через TThread.Queue.

И да, в отчёте также был виден этот фоновый поток от Contoso, который мог бы выполнить такой код.

Сам метод BasePerform является просто обёрткой вокруг InternalHandle:
procedure TContosoEventMessage.BasePerform;
begin
  FMsgThread.InternalHandle(Self);
end;
И отчёт EurekaLog показывает, что вылет произошёл на первой же строчке.

Что мы имеем?
  1. Фоновый поток поставил в очередь метод, заполнив поле FMsgThread.
  2. Главный поток попробовал выполнить этот метод и вылетел при попытке прочитать поле FMsgThread.
Вторая строка является предположением, поскольку, как я уже сказал, ассемблера в отчёте не было. Но гипотеза вполне себе, поскольку если иначе вылет был бы внутри InternalHandle.

Т.е. вроде как налицо проблема с памятью. И, кстати говоря, это самая частая "проблема" проектов, которые включают EurekaLog. В самом деле, посмотрите на такой код:
procedure TForm1.Button1Click(Sender: TObject);
var
  List: TList;
begin
  List := TList.Create;
  List.Free;

  List.Clear; // - использование объекта после удаления
end;
Корректный ли это код? Нет, конечно. Но будет ли он "работать". Да, с большой вероятностью он корректно отработает. Происходит это по той простой причине, что "освобождённая" память (и, следовательно, "освобождённый" объект) в действительности не удаляются, а просто помечаются как свободные. Т.е. их память остаётся доступной в неизменном виде. Конечно, если между особождением памяти/объекта и повторным доступом к нему будет много операций, то есть какой-то шанс, что они испортят бывшую память. Но на коротких пробегах вы не заметите проблемы.

Добавление EurekaLog в программу меняет ситуацию на корню, поскольку EurekaLog по умолчанию включает проверки памяти и активно борется с указанными багами.

Что-ж, посмотрим может ли у нас сейчас быть такая ситуация. Для этого нужно понять где освобождается память для FMsgThread. Поскольку он приходит из параметра метода - посмотрим, кто вызывает метод BasePerform. Поиск по исходникам подсказал такой код (поиск показал несколько мест, но конкретное место было выбрано исходя из состояние фонового потока из отчёта):
procedure TContosoThread.Execute;
// ...
begin
// ...
              for i := 0 to oReceivedMsgs.Count - 1 do 
              begin
                oMsg := TContosoThreadMsgBase(oReceivedMsgs[i]);
                try
                  if not oMsg.Perform(Self) then
                    Break;
                finally
                  oMsg.Destroy;
                end;
// ...
end;
Оп, а вот он и баг. Сценарий происходящего:
  1. Фоновый поток перебирает входящие сообщения.
  2. Каждое сообщение обрабатывается (Perform).
  3. Какое-то сообщение указывает, что его нужно синхронизировать в главный поток.
  4. Фоновый поток ставит сообщение в очередь (Queue).
  5. Фоновый поток удаляет сообщение (Destroy), но указатель на сообщение всё ещё сидит в очереди.
  6. Главный поток приступает к обработке запланированных сообщений (BasePerform).
  7. Обработка сообщения вызывает Access Violation, потому что сообщение уже удалено.
Т.е. баг тут либо в управлении памятью, либо в синхронизации потоков. Как возникла такая ошибка? Очевидно, изначально были написаны базовые классы, которые предполагали линейное выполнение: "взяли сообщение - обработали - освободили". Потом был написан особый класс-наследник, который переопределил поведение "обработать" на "поставить в очередь и выйти". А базовый класс (с циклом) про это не в курсе. Что и привело к багу.

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

Я подозреваю, что исправление проблемы могло бы быть в замене Queue на Synchronize.

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

8 комментариев :

  1. а что за библиотека то? а то вдруг начну использовать, а там мина тикает

    ОтветитьУдалить
    Ответы
    1. Вы серьёзно полагаете, что я убрал все имена, чтобы сообщить об этом в комментарии?

      Смысл поста не в том, чтобы тыкать пальцем в кого-то, а чтобы продемонстрировать, что простое добавление кода в проект может привести к раскрытию ранее скрытых багов.

      Удалить
  2. Давненько не было ваших постов

    ОтветитьУдалить
  3. А по поводу Access violation at address 0000000000000000 in module 'some.exe'. Execution of address 0000000000000000.
    В стеке _UnhandledException, ExceptProcHook, ExceptProcHandler и TExceptionManager.Handle
    Можете подсказать идею почему такое происходит? Падает на одной машине. Причем только 64битная версия.

    ОтветитьУдалить
    Ответы
    1. Пока бюрократическая машина раскрутится...
      Для справки. Причина оказалась в не инициализированной функции

      Пример
      var
      ucasemap_utf8ToUpper: function(const csm: Pointer; dest: PAnsiChar; destCapacity: Integer; const src: PAnsiChar; srcLength: Integer; var pErrorCode: Integer): Integer; cdecl;

      function UTF8UpperCase(const S: UTF8String): UTF8String;
      var
      Err,Len: Integer;
      begin
      Err := 0;
      Len := Length(S);
      SetLength(Result, Len);
      Len := ucasemap_utf8ToUpper(nil, Pointer(Result), Len, Pointer(S), Len, Err);
      end;

      procedure TForm5.FormCreate(Sender: TObject);
      begin
      UTF8UpperCase(caption);
      end;

      И при этом на 64битной сборке эврика показывает "левый" стек. На 32битной нормально показывает место ошибки, 64битная просто HandleException.

      Удалить
    2. Весьма странно. В случае перехода на nil первая строка в стеке всегда указывает на вызвавший переход call, т.е. строку с ucasemap_utf8ToUpper внутри UTF8UpperCase. И только со второй строки начинается стек.

      Может, старую версию используете, которая не делает такую проверку?

      Удалить
    3. На билд-сервере не старше предпоследней версии. Регулярно обновляют. Но там сам exe фемидой защищен. И в стеке багрепорта вообще нет ничего кроме.
      ----------|
      |00000060|04 |000000000012FBF8|00000000009D0B69|.exe|00000000005D0B69|EExceptionManager.pas|EExceptionManager|TExceptionManager|Handle |2032[34] |
      |00000060|04 |000000000012FCA8|00000000009E0DAE|.exe|00000000005E0DAE|EExceptionHook.pas |EExceptionHook | |ExceptProcHandler |780[60] |
      |00000060|04 |000000000012FE18|00000000009C2176|.exe|00000000005C2176|EInject.pas |EInject | |ExceptProcHook |365[8] |
      |00000060|04 |000000000012FEB8|0000000000413CD1|.exe|0000000000013CD1|System.pas |System | |_UnhandledException|24300[5] |
      |00000060|03 |000000000012FF58|00000000771259EB|kernel32.dll |00000000000159EB|kernel32.dll |kernel32 | |BaseThreadInitThunk| |
      --------------
      Я проверял на 7.7.3.1 Update 3. Тривиальная демка значимый код выше весь привел.
      И 64 стабильно
      |00000060|04 |000000000012FCC8|0000000000895C73|Project5.exe|0000000000495C73|Vcl.Forms.pas|Vcl.Forms|TApplication|HandleException |10832[16] |
      |00000060|04 |000000000012FD08|000000000088F151|Project5.exe|000000000048F151|Vcl.Forms.pas|Vcl.Forms|TCustomForm |HandleCreateException|7625[1] |
      |00000060|04 |000000000012FD38|000000000088572A|Project5.exe|000000000048572A|Vcl.Forms.pas|Vcl.Forms|TCustomForm |DoCreate |3790[5] |
      |00000060|04 |000000000012FD88|0000000000885128|Project5.exe|0000000000485128|Vcl.Forms.pas|Vcl.Forms|TCustomForm |AfterConstruction |3671[1] |
      |00000060|04 |000000000012FDC8|000000000040DE7D|Project5.exe|000000000000DE7D|System.pas |System | |_AfterConstruction |18301[2] |
      |00000060|04 |000000000012FE28|0000000000884FC6|Project5.exe|0000000000484FC6|Vcl.Forms.pas|Vcl.Forms|TCustomForm |Create |3661[37] |
      |00000060|04 |000000000012FEB8|0000000000895866|Project5.exe|0000000000495866|Vcl.Forms.pas|Vcl.Forms|TApplication|CreateForm |10732[13] |
      |00000060|04 |000000000012FF28|00000000008F40FD|Project5.exe|00000000004F40FD|Project5.dpr |Project5 | |Initialization |25[3] |
      |00000060|03 |000000000012FF58|000000007739556B|kernel32.dll|000000000001556B|kernel32.dll |kernel32 | |BaseThreadInitThunk | |
      А вот на 32 битак как Вы говорите
      |00000060|04 |0018FE54|00766E7E|Project5.exe|00366E7E|Unit5.pas |Unit5 | |UTF8UpperCase |35[4]

      Удалить

Можно использовать некоторые HTML-теги, например:

<b>Жирный</b>
<i>Курсив</i>
<a href="http://www.example.com/">Ссылка</a>

Вам необязательно регистрироваться для комментирования - для этого просто выберите из списка "Анонимный" (для анонимного комментария) или "Имя/URL" (для указания вашего имени и (опционально) ссылки на сайт). Все прочие варианты потребуют от вас входа в вашу учётку.

Пожалуйста, по возможности используйте "Имя/URL" вместо "Анонимный". URL можно просто не указывать.

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

Примечание. Отправлять комментарии могут только участники этого блога.