Citrix: Opening Skype Causes Mouse Freeze

Every once in a while I encounter a bug which is annoying, but not annoying enough for me to put effort into solving it. But when \( frequency \times annoyance \times time \) reaches a critical threshold, I always feel tempted to at least have a shot at solving the underlying issue.

This time, the issue occurred every time I logged into my Citrix machine by using Citrix Workspace and opened Skype. Right after Skype popped open, my mouse stopped working. In order to make my mouse work again, I had crawl under my desk, locate the mouse’s USB cable and re-plug it. As you can see, this bug has a high annoyance and frequency value.

Disclaimer: This post does not touch on all the things that were attempted in order to find the cause. It merely describes an alternate reality without dead ends.

The Culprit?

The first indicator that the Citrix Workstation Application itself had no part in my daily desk-crawling exercise was that everything was working as expected when Skype was not running. After some investigating in the process tree, I noticed that Citrix spawned a new process called RTMediaEngineSRV on my host computer once opening Skype remotely. About 2 seconds after the process spawned, my mouse became unresponsive. A first hint!

Looking for Debugging Information

The first thing I always look for (after search-engining) when encountering a problem is logs. While some applications actively try to hide their logging output, RTMediaEngineSRV luckily provided logging information by default. The logs are stored in the /var/log/RTMediaEngineSRV/MediaEngineSRVDebugLogs directory and are grouped by sessions.

Not exactly knowing what to look for, I focused on the two only facts I had:

It affects my USB mouse and other USB devices
It’s an error

Looking through the log, I found some possibly relevant information:

HIDFinder debug: EnumerateDevices
HIDFinder debug: EnumerateDevices: Telephony HID supported devices: 
HIDFinder debug: EnumerateDevices: Number of existing HID devices: 0
HIDFinder debug: Attempting to open device at path: /dev/usb/hiddev0
HIDFinder debug: Failed to get string at index 33, error code=-1
HIDFinder debug: Attempting to open device at path: /dev/usb/hiddev1
HIDFinder debug: Failed to get string at index 33, error code=-1
HIDFinder debug: Attempting to open device at path: /dev/usb/hiddev2
HIDFinder debug: Failed to get string at index 33, error code=-1
HIDFinder debug: Attempting to open device at path: /dev/usb/hiddev3
HIDFinder debug: Failed to get string at index 33, error code=-1
HIDFinder debug: EnumerateDevices: Number of devices removed: 0

This itself did not seem too suspicious, as it could be a simple permission error on the /dev/usb/hiddev devices. HID (Human Interface Devices) are generally all devices which enables a human to interact with a machine (duh). To confirm my doubt about the permissions, I had a look at them:

➜ ~ l /dev/usb
total 0
drwxr-xr-x  2 root root    120  7. Jul 18:38 .
drwxr-xr-x 23 root root   3.8K  7. Jul 18:38 ..
crw-rw-rw-  1 root root 180, 0  7. Jul 18:38 hiddev0
crw-rw-rw-  1 root root 180, 1  7. Jul 18:38 hiddev1
crw-rw-rw-  1 root root 180, 2  7. Jul 18:38 hiddev2
crw-rw-rw-  1 root root 180, 3  7. Jul 18:38 hiddev3

All users have rw permissions on all HID devices, so permissions should not be a problem.

Tracing Systemcalls

I wanted to investigate further for what purpose Citrix needs to enumerate and open those devices. A handy tool for black-box investigating program behavior is strace, which traces all systemcalls including their parameters and return values.

For my first trace, I had no idea what to look for besides the open("/dev/usb/hiddev") calls. Therefore I did not activate any filters.

Now, to trace the RTMediaEngineSRV process, I either had to attach to an already running process or I had to start it via strace directly. Attaching would prove cumbersome, as the process was started by the Citrix Workspace, but not as a child process. Also the relevant behavior happens right after starting. Writing a script that waits for the process to spawn, then start a trace was no option.

Looking at the output of ps -ef | grep -i rtmedia gave me the parameters the process was started with:

RTMediaEngineSRV --port:7102 --requested_version:2.8

Killing the original process and executing the binary with the given parameters manually seemed to work, as the process was not immediately killed. Immediately after starting the process, the oh so familiar mouse freeze set in, which this time produced the opposite reaction of what I’m used to.

I started a strace that follows all child processes and stores the results in separate files (-ff), and a enlarged buffer size for arguments (-s 65536):

➜ ~ sudo strace -s 65536 -ff RTMediaEngineSRV --port:7102 --requested_version:2.8

After the trace was done (and replugging my mouse of course), I was looking for the syscall that opens the HIDs:

➜ grep -R /dev/usb .
./rtm.120231:openat(AT_FDCWD, "/dev/usb/hiddev0", O_RDWR) = 20
./rtm.120231:openat(AT_FDCWD, "/dev/usb/hiddev1", O_RDWR) = 20
./rtm.120231:openat(AT_FDCWD, "/dev/usb/hiddev2", O_RDWR) = 20
./rtm.120231:openat(AT_FDCWD, "/dev/usb/hiddev3", O_RDWR) = 20

We gathered a few new insights:

The HIDs are opened
They are opened with RW permission
The open syscall is successful, returning the file descriptor 20 each time
The bug probably happened in the process with PID 120231

Let’s look at the syscalls after the open call in the PID 120231:

...
openat(AT_FDCWD, "/dev/usb/hiddev0", O_RDWR) = 20
ioctl(20, HIDIOCGRAWNAME(260) or HIDIOCGSTRING, 0x7f4778a889d0) = -1 EINVAL (Invalid argument)
write(2, "ioctl (HIDIOCGSTRING): Invalid a"..., 40) = 40
...
openat(AT_FDCWD, "/dev/usb/hiddev1", O_RDWR) = 20
ioctl(20, HIDIOCGRAWNAME(260) or HIDIOCGSTRING, 0x7f4778a889d0) = -1 EINVAL (Invalid argument)
write(2, "ioctl (HIDIOCGSTRING): Invalid a"..., 40) = 40
...
openat(AT_FDCWD, "/dev/usb/hiddev2", O_RDWR) = 20
ioctl(20, HIDIOCGRAWNAME(260) or HIDIOCGSTRING, 0x7f4778a889d0) = -1 EINVAL (Invalid argument)
write(2, "ioctl (HIDIOCGSTRING): Invalid a"..., 40) = 40
...
openat(AT_FDCWD, "/dev/usb/hiddev3", O_RDWR) = 20
ioctl(20, HIDIOCGRAWNAME(260) or HIDIOCGSTRING <unfinished ...>) = ?
+++ killed by SIGINT +++

Just by looking at it from far away, one can recognize a pattern, which is broken in the last lines:

Open the HID FD
Use ioctl to interact with it
(Print an error)

For some reason the ioctl syscall for hiddev3 never finishes. After confirming that hiddev3 indeed was my mouse, I felt sure enough to continue going down this route.

`ioctl` — What does it do?

That’s the question I had when I saw it. Luckily the man-Pages are always just one terminal away:

int ioctl(int fd, unsigned long request, ...);

The ioctl() system call manipulates the underlying device parameters of special files. […] The argument fd must be an open file descriptor. The second argument is a device-dependent request code. The third argument is an untyped pointer to memory.
—Linux Man Pages

This description helps us to make sense of the ioctl syscall we saw earlier. The application wants to make a request (HIDIOCGSTRING) to my mouse with the data located at memory position 0x7f4778a889d0. As it turns out, reading memory from a dead process is hard. I could have tried creating coredumps or debugging with gdb, but I opted for static analysis later.

We Need to Go Deeper: Kernel Tracing

Wanting to avoid debugging and static analysis for now, I decided to have a shot at tracing the relevant functions in the kernel. Using trace-cmd, kernel functions and their execution durations can be traced. After reading some kernel source and listing the functions i can attach to with trace-cmd list -f ioctl | grep hid, I came up with the command:

➜ sudo trace-cmd record -p function_graph -l hiddev_ioctl -l hiddev_ioctl_string.constprop.0.isra.0 ./RTMediaEngineSRV ...

The log produced way too much output for me to make sense of it. As we know that our systemcall shows up as unfinished, we can look for long-running systemcalls. Another possibility is that the traced process simply was killed before the syscall could finish. But for now let’s look at systemcalls with long durations.

As trace-cmd is a front end for ftrace, the actual kernel code is injected with tracing operations. To read more about it, I recommend the post about ftrace by Julia Evans. This enables us to view the time deltas between function entry and exit. By specifying the --ts-diff in our command, those deltas will be calculated and displayed. In order to filter the systemcalls with long durations, I opted for a regex in grep:

➜ trace-cmd report --ts-diff | grep -P '\+\d\d\d\d\d' -C3

<...>-45049 [000] 36602.593473: (+1)     funcgraph_entry:      ! 258.002 us |    hiddev_ioctl_string.constprop.0.isra.0();
<...>-45049 [003] 36602.593733: (+260)   funcgraph_exit:       ! 260.879 us |  }
<...>-45049 [000] 36612.895448: (+10301715) funcgraph_entry:                   |  hiddev_ioctl() {
<...>-45049 [000] 36612.895450: (+2)     funcgraph_entry:      # 2318.666 us |    hiddev_ioctl_string.constprop.0.isra.0();
<...>-45049 [000] 36612.897770: (+2320)  funcgraph_exit:       # 2323.450 us |  }

This confirms our assumptions. The ioctl syscall really takes \( 10301715 \mathrm{\mu s} \approx 10.3 \mathrm{s} \), which we can agree on, is too long for a systemcall. This evidence exonerates the RTMediaEngineSRV as the principal culprit, now I view it as merely an accessory to the act.

Recreating the `ioctl` Call

Now that we confirmed that our HID does not respond well to a certain ioctl call, we can further drill down on the specifics. As a sanity check, let’s try to create a Minimum Working Example (MWE) in plain old C, based on the arguments we saw earlier. The last argument is unknown to us, so let’s consult the documentation of HIDIOCGSTRING.

The linux kernel documentation has a description for it:

HIDIOCGSTRING - struct hiddev_string_descriptor (read/write)

Gets a string descriptor from the device. The caller must fill in the “index” field to indicate which descriptor should be returned.
—Linux Kernel Documentation

In short, we use the mentioned structure to pass a request with a specified index to the kernel. The struct contains a value field, which will be filled with the response from the USB device. Great, let’s try it out!

#include <stdio.h>         // for printf
#include <fcntl.h>         // for open
#include <sys/ioctl.h>     // for ioctl
#include <linux/hiddev.h>  // for HIDIOCGSTRING

int main() {
  int fd = open("/dev/usb/hiddev3", O_RDWR);
  printf("open(...,%d) = %d\n", O_RDWR, fd);
  
  struct hiddev_string_descriptor desc;
  desc.index = 1;
  int ret = ioctl(fd, HIDIOCGSTRING, &desc);
  printf("ioctl(HIDIOCGSTRING, %d) = %d -> %s\n", desc.index, ret, desc.value);
}

➜ gcc string-test.c -o string-test && ./string-test
open(...,2) = 3
ioctl(HIDIOCGSTRING, 1) = 6 -> ROCCAT

Well this seems to work better than expected! Mouse is still working and we successfully read what seems to be the manufacturer string from the mouse.

Finding the `HIDIOCGSTRING` Request Index

I have been looking for an excuse to try out Ghidra for statically analyzing executables. One yay ghidra later, I started the automatic analysis of the RTMediaEngineSRV binary, with all modules enabled. The whole analysis took about 90 minutes to finish.

The simplest way to find meaningful place to start in a non-obfuscated binary is to search for known strings. Luckily we already know such a string, we saw it in the log earlier! A search for the “EnumerateDevices” constant string reveals one reference to it. Thanks to Ghidra’s decompilation view as first class citizen, getting an overview of the functionality is comparatively easy.

Looks like we have found a good place to start looking for the ioctl call. Further down there is a call to a function hid_get_indexed_string, which sounds very promising. With some variable renaming and filling in the definitions for the request struct data type, our memory layout looks more correct.

In summary, the function reads a string at a given index from an USB device with the given file descriptor. That’s exactly what we build in our C program earlier. Let’s figure out who is calling this function and which parameter is used. A reference search only reveals one caller, perfect!

hid_get_indexed_string(fileDescriptor,0x21,stringOut);

0x21 is the magical number we have been looking for. Let’s use 0x21 as request index for our USB string request instead of 1.

struct hiddev_string_descriptor desc;
desc.index = 0x21;
int ret = ioctl(fd, HIDIOCGSTRING, &desc);

➜ gcc string-test.c -o string-test && ./string-test
open(...,2) = 3
# 10 seconds freeze
ioctl(HIDIOCGSTRING, 33) = -1 ->

Not only does my mouse become unresponsive, the LED animation also stops. This is starting to look like a hardware issue now.

Further testing reveals that my mouse freezes on every request with an index > 3.

But why 0x21?

What is so special about this index and why does my Citrix client want to know about its contents? USB String Descriptors are a way for USB devices to provide optionally available information for reading.[^3]

After some more digging, I came across a debugging output in the application’s source code:

if (stringOut[0] == L'U'
 && stringOut[1] == L'C'
 && stringOut[2] == L'Q') {
  Debug(*(char **)(this + 0x18),"UCQ Descriptor: %ls",stringOut);
  // ...
}

It was checking if the USB Descriptor at index 0x21 == 33 is starting with the characters “UCQ”. Some minutes of research later, I found a Skype/Lync Specification for compatible USB devices. Document H100689 states on page 13 in the section “UC Qualification (UCQ) Descriptor for HID”:

The UCQ descriptor is used by Lync to determine the basic capabilities of the audio device. The string is requested by Lync through a standard USB string descriptor request at index 0x33. —Document H100689

Wait, something does not match here. 0x33 != 33, 33 == 0x21. Someone must have forgotten the hexadecimal prefix! I wonder whether it’s a mistake in the specification, as the test instructions later on ask for checking the value of 33. Version 1.0 and 4.0 of the spec contain those discrepancies. I doubt I will find out.

The Workaround

As I settled on this being a hardware issue, I disabled the write permissions for my hiddev via a udev rule. The rule changes the permissions to read-only for everyone except root.

➜ cat /etc/udev/rules.d/50-roccat.rules
KERNEL=="hiddev*", ATTRS{idVendor}=="1e7d", ATTRS{idProduct}=="2d51", MODE="0644"

Conclusion

This voyage through multiple layers of the operating system taught me many new techniques for analysis and debugging. Especially Ghidra impressed me with the ease of use (compared to IDA that is) and the lightning fast decompilation. The time was well spent and I even was rewarded a decimal-hexadecimal bug.

As I don’t have to crawl under the desk each day now, I’ll have to find a new form of exercise.

Maybe I’ll take a look at the mouse’s firmware one day.

Basti’s Buggy Blog

Citrix: Opening Skype Causes Mouse Freeze

Table of Contents

The Culprit?

Looking for Debugging Information

Tracing Systemcalls

`ioctl` — What does it do?

We Need to Go Deeper: Kernel Tracing

Recreating the `ioctl` Call

Finding the `HIDIOCGSTRING` Request Index

But why 0x21?

The Workaround

Conclusion

Citrix: Opening Skype Causes Mouse Freeze

Table of Contents

The Culprit?

Looking for Debugging Information

Tracing Systemcalls

ioctl — What does it do?

We Need to Go Deeper: Kernel Tracing

Recreating the ioctl Call

Finding the HIDIOCGSTRING Request Index

But why 0x21?

The Workaround

Conclusion

`ioctl` — What does it do?

Recreating the `ioctl` Call

Finding the `HIDIOCGSTRING` Request Index