Упрощаем лог действий пользователя


    В предыдущих статьях мы сделали большое и доброе дело — научились автоматически собирать предысторию падения программы и отправлять её с крэш-репортом. Для WinForms, WPF, ASP, Javascript. Теперь научимся показывать все эти горы информации в удобоваримом виде.

    Казалось бы, чего ещё не хватает, сиди и читай лог внимательно, там всё достаточно подробно написано. Даже слишком подробно, пожалуй. Прямо отладочный лог какой-то. Тоже штука несомненно полезная, но мы-то хотели чуть другого. Мы хотели знать, что пользователь делал перед тем, как программа завалилась. Шаги для воспроизведения. Как человек будет в письме разработчику описывать свои действия человеческим языком? Наверное, что-то типа:

    Я запустил программу
    Нажал кнопку «Edit Something»
    Открылось диалоговое окно «Edit»
    Далее я ткнул мышкой в поле «Name»
    Ввёл своё имя
    Нажал Enter
    И тут-то у меня всё упало


    А у нас что? По сути, вроде то же самое, но изобилует массой «излишних» подробностей: мышку нажал, мышку отпустил, кнопку нажал, символ ввёл, кнопку отпустил и тому подобное.

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

    Начнём с мышки.
    Вот так выглядит в логе двойной клик левой кнопкой мыши для платформы WinForms:



    С виду несложно — ищем в логе последовательность событий down/up/doubleClick/up и заменяем её на одну запись о doubleClick. При этом надо убедиться, что в найденной последовательности у всех событий одна и та же кнопка мыши (левая в нашем примере), и что все события происходят над одним и тем же окном. Также, во избежание недоразумений, лучше проверить, что координаты всех четырёх событий не выходят за пределы квадрата размером SystemInformation.DragSize. Делать это мы будем на сервере, а DragSize по-хорошему надо бы использовать с клиентской машины. В реальности же, даже если и удастся поймать ситуацию, в которой они различаются, то это мало на что повлияет. Поэтому осознанно пренебрегаем этим и используем фиксированные значения.

    Координаты мышки придётся присылать с клиента:

    void AppendMouseCoords(ref Message m, Dictionary<string, string> data) {
        data["x"] = GetMouseX(m.LParam).ToString();
        data["y"] = GetMouseY(m.LParam).ToString();
    }
    int GetMouseX(IntPtr param) {
        int value = param.ToInt32();
        return value & 0xFFFF;
    }
    int GetMouseY(IntPtr param) {
        int value = param.ToInt32();
        return (value >> 16) & 0xFFFF;
    }
    

    Следующая «упрощалка» будет заниматься одиночными кликами:



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

    Перейдём к клавиатурному вводу.

    Одиночное нажатие алфавитно-цифровой клавиши:



    На первый взгляд, всё то же, что и с мышкой, какие тут могут быть проблемы? У нас тут записано 3 события: WM_KEYDOWN, WM_CHAR и WM_KEYUP. Что у них есть общего, чтобы понять, что все 3 записи относятся к одному событию — нажатию кнопки F? А общего у них только сканкод в битах с 16 по 23, поскольку WM_KEYDOWN и WM_KEYUP содержат в себе Virtual Key Code, который не зависит от текущего языка ввода. А вот WM_CHAR содержит уже юникодный символ, который соответствует нажатой клавише (или комбинации клавиш, или вообще последовательности IME ввода). Сканкод надо также прислать с клиента, при этом не забыть спрятать его при вводе паролей:

    void ProcessKeyMessage(ref Message m, bool isUp) {
        // etc
        data["scanCode"] = maskKey ? "0" : GetScanCode(m.LParam).ToString();
        // etc
    }
    int GetScanCode(IntPtr param) {
        int value = param.ToInt32();
        return (value >> 16) & 0xFF;
    }

    Ну вот, выключаем газ, снимаем чайник с плиты, выливаем воду и сводим задачу к уже решённой, теперь можно, как и для мышки, свернуть тройки событий в одно. «Ага, такой большой, а всё ещё в сказки веришь!» — сказала реальность:



    Оказывается, при быстром наборе keyUp может неслабо так отставать от соответствующих keyDown и keyPress. Поэтому искать просто 3 последовательных записи определённого вида не выйдет. Придётся от найденной начальной точки (keyDown) искать соответствующие keyPress и затем keyUp. До конца списка искать? Так это сразу квадратичная сложность получается, здравствуйте, тормоза! Да и события keyPress может не быть вообще, если была нажата не алфавитно-цифровая клавиша. Поэтому будем искать не далее фиксированного количества записей от начальной, число выберем исходя из здравого смысла и исправим при необходимости. Пусть будет 15, по 2-3 записи на одну клавишу, это будет означать 5-8 одновременно нажатых и неотпущенных клавиш. Для нормального «гражданского» ввода более чем достаточно.

    Итак, отдельные нажатия клавиш свернули до ввода отдельных символов (type char). Теперь можно попробовать объединить неразрывные последовательности type char в одну большую type text. Хотя насчёт неразрывности я, пожалуй, погорячился — до, внутри и после последовательности type char вполне себе допустимы нажатия и отпускания клавиш Shift, что также необходимо учесть при сворачивании цепочки событий.

    С алфавитно-цифровым вводом всё, теперь можно свернуть и оставшиеся пары keyDown/keyUp, больших сюрпризов там уже не предвидится.

    Что там у нас ещё осталось? Фокус.

    Смена фокуса мышкой:



    Ищем и заменяем тройку записей на одну, контролируем соответствие координат мыши.

    Смена фокуса с клавиатуры:



    Очень похоже на мышку, но важно не наколоться на том, что keyDown приходит в окно, которое теряет фокус, а keyUp — в окно, которое его получает.

    Теперь попробуем собрать это всё вместе и посмотрим.

    Было:



    Стало:



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

    В первом приближении с WinForms закончили. Переходим к WPF.

    До определённой степени WPF похож на WinForms, и можно использовать почти все вышеописанные правила. Но, как помним из курса школьной математики, чтобы задачу решить типовым способом, для начала к этому способу ее надо привести. Давайте взглянем, что мы имеем на входе:



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

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

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

    
    class PreviousArgs {
        public EventArgs EventArgs { get; set; }
        public string Id { get; set; }
    }
    
    PreviousArgs previousArgs = null;
    short currentId = 0;
    
    Dictionary<string, string> CollectCommonProperties(FrameworkElement source,
                                                       EventArgs e) {
        Dictionary<string, string> properties = new Dictionary<string, string>();
        properties["Name"] = source.Name;
        properties["ClassName"] = source.GetType().ToString();
    
        if(previousArgs == null) {
            previousArgs = new PreviousArgs() {
                               EventArgs = e,
                               Id = (currentId++).ToString("X")
                           };
        } else {
            if(e == null || !Object.ReferenceEquals(previousArgs.EventArgs, e)) {
                previousArgs = new PreviousArgs() {
                               EventArgs = e,
                               Id = (currentId++).ToString("X")
                           };
            }
        }
        properties["#e"] = previousArgs.Id;
    }
    

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



    Хорошо, размер лога сильно сократили, и теперь уже почти похоже на WinForms, а значит можно пробовать применить правила, описанные выше.

    Чтобы заработали правила сворачивания кликов мышки, нам не хватает сбора координат. Координаты относительно рутового элемента мы получим при помощи метода MouseEventArgs.GetPosition, а координаты относительно окна — при помощи Visual.PointToScreen:

    
    void CollectMousePosition(IDictionary<string, string> properties, 
                              FrameworkElement source, 
                              MouseButtonEventArgs e) {
        IInputElement inputElement = GetRootInputElement(source);
        if(inputElement != null) {
            Point relativePosition = e.GetPosition(inputElement);
            properties["x"] = relativePosition.X.ToString();
            properties["y"] = relativePosition.Y.ToString();
            if(inputElement is Visual) {
                Point screenPosition = 
                        (inputElement as Visual).PointToScreen(relativePosition);
                properties["sx"] = screenPosition.X.ToString();
                properties["sy"] = screenPosition.Y.ToString();
            }
        }
    }
    
    IInputElement GetRootInputElement(FrameworkElement source) {
        return GetRootInputElementCore(source, null);
    }
    
    IInputElement GetRootInputElementCore(FrameworkElement source,
                                          IInputElement lastInputElement) {
        if(source is IInputElement)
            lastInputElement = source as IInputElement;
    
        if(source != null) {
            return GetRootInputElementCore(source.Parent as FrameworkElement,
                                           lastInputElement);
        }
        return lastInputElement;
    }
    

    Теперь у нас вполне успешно сворачиваются клик и двойной клик.

    Теперь взглянем на перемещение фокуса. В отличие от WinForms в WPF мы используем два эвента: GotFocus и LostFocus, соответственно, и записей лога у нас две. Ну да и ничего страшного, просто поправим логику, чтобы при сворачивании искался либо FocusChanged, либо пара из Got и Lost focus эвентов.

    В принципе, с WPF на этом и закончили. К сожалению, свернуть ввод текста мы не можем, так как TextInput эвент полностью оторван от клавиатуры, и никаких аналогов scan code там нет. В результате нам удалось добиться вот такого внешнего вида:



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

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

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

    Developer Soft

    73,79

    Компания

    Поделиться публикацией
    Комментарии 12
      0
      Особенно доставляют эти up и down в отношении клавиш и их состояния — не сразу поймешь, что
      F up
      Type 'f'
      F down

      (тут еще бы понять, почему где-то 'F', а где-то 'f', хотя клавиша та же)
      Да, именно так
      image

      — так вот это читается не как «отжатие клавиши, ввод буквы, и нажатие клавиши», а как раз наоборот, «нажатие — ввод буквы — отжатие» (притом что ввод буквы — это уже реакция на нажатие).
        +2
        Да, всё именно так. Как и в любом логгере, более новые записи отображаются выше (видно по timestamp на картинке)

        'F' — значение из enum, а 'f' — тот символ, который был реально напечатан с учётом клавиатуры и текущей раскладки
          0
          Поясню чуть подробнее. На события keyUp и keyDown у нас не приходит введённый символ. Приходит только информация о нажатой клавише. А реальный текст мы можем узнать только на событии keyPress
          0

          Что-то смутно мне подсказывает что все это Windows и так за вас делает — и вам надо просто логировать и более высокоуровневые сообщения (а низкоуровневые прятать/сворачивать).
          И вообще в общем случае ввод может прийти и не с традиционных девайсов (с речевого ввода например) и там вообще может не быть keyDown/keyUp...

            +1
            При работе с нетрадиционными девайсами можно заполнить бердкрамбсы вручную. Автоматический режим написан для наиболее часто используемых сценариев.
              0

              Ну например, в MSDN написано:


              Double-clicking the left mouse button actually generates a sequence of four messages: WM_LBUTTONDOWN, WM_LBUTTONUP, WM_LBUTTONDBLCLK, and WM_LBUTTONUP.

              То есть из Windows приходят не только "сырые" сообщения о нажатии/отжатии кнопки, но и уже обработанные — двойной клик произошел. И это истинные сообщения (учитывающие, например, скорость двойного клика в настройках мыши).


              Так какой смысл игнорировать эти сообщения, и пытаться потом их восстановить задним числом?

                0
                Так мы и не игнорируем.

                Если посмотреть на скриншот — https://hsto.org/webt/u4/wh/2l/u4wh2l7n7baleb9kkdtxnwotnpk.png, в сырых данных мы и собираем нативный doubleClick.
                Но он прилетает не один, а в последовательности — down/up/doubleClick/up.
                Вот из этой последовательности в финальном отображении мы и оставляем только doubleClick по результатам коллапса.
                  0
                  Спасибо кэп, см. первую картинку в статье. В случае двойного клика восстанавливать ничего и не надо, напротив, стОит убрать/свернуть «лишние» сообщения, предшествующие (и следующие за) WM_LBUTTONDBLCLK. Выкинуть их «превентивно» нельзя, ибо в таком случае не отловишь одиночный клик. А еще, сюрприз, сообщения WM_LBUTTONSINGLECLICK в винде не существует, и таки придётся анализировать соответствующие пары Down/Up. Аналогичная ситуация и с KeyDown, KeyPress, KeyUp.

                  Может возникнуть соблазн сделать обработку не на сервере, а на клиентах, типа ближе к телу, сразу учесть особенности платформы и т.п. Но есть один ньюанс) Выпущенную версию клиента обратно не воротишь, улучшить что-то или поправить косяк получится только в следующей версии клиента. Пока будешь делать новую версию, «плохой» клиент успеет распространиться в природе, и попробуй теперь замени его на более новый, стильный, модный и молодёжный. А логика обработки и показа на сервере может быть быстро/легко исправлена и расширена, полностью независимо от клиентов и их версий.
                    0
                    Объем передаваемых данных?
                      0
                      Кольцевой буфер, по дефолту на 1000 элементов, размер настраивается в коде/конфиге. Размер элемента переменный (json), в ориентировочно десятки-сотни байт. Если всё это вместе превышает ~3Mb, отправляются самые свежие по времени данные, поместившиеся в 3Mb.
                        0
                        Я имел в виду, что объем передаваемых данных можно существенно уменьшить, если делать оптимизацию на клиенте.
                          0
                          Можно. Но, потеряем тогда оригинал, а он бывает важен. Может оно и специфика, но во всех больших контролах, что лично мне пришлось разрабатывать (RichEdit, Spreadsheet, Scheduler), обработка клавиатуры и мышки полностью кастомная. И при любых подозрениях на эту часть кода, я бы обязательно взглянул на неоптимизированный оригинал. Плюс, см. аргументы выше.

            Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

            Самое читаемое