2012-08-30

Attenuating Linux dmesg USB Spam

For some reason, my usb mouse and keyboard, hooked up to a kvm, freeze intermittently when switching back and forth to the system. After wasting way too much time trying to figure out why, my workaround is to switch to a console before switching off system.

However, the console becomes flooded with the USB modules noisy spam, as does dmesg, of course.

Here are my naive, uninformed, lazy kludges to deal with this, and other noise.

First, an example of the usb printk noise:

[87934.587528] usb 2-2.2: USB disconnect, device number 20
[87944.107520] usb 2-2.2: new low-speed USB device number 21 using uhci_hcd
[87944.248817] input: Logitech Trackball as /devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2/2-2.2:1.0/input/input27
[87944.248917] hid-generic 0003:046D:C404.0014: input,hidraw0: USB HID v1.10 Mouse [Logitech Trackball] on usb-0000:00:1d.0-2.2/input0
[91382.140601] usb 2-2.2: USB disconnect, device number 21
[91390.507608] usb 2-2.2: new low-speed USB device number 22 using uhci_hcd
[91390.650062] input: Logitech Trackball as /devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2/2-2.2:1.0/input/input28
[91390.650176] hid-generic 0003:046D:C404.0015: input,hidraw0: USB HID v1.10 Mouse [Logitech Trackball] on usb-0000:00:1d.0-2.2/input0
A glance at /usr/src/linux/.config shows:
# CONFIG_USB_DEBUG is not set
# CONFIG_USB_ANNOUNCE_NEW_DEVICES is not set
(this is for kernel 3.5.3)
And in /usr/src/linux/drivers/usb/core/hub.c:

#ifdef CONFIG_USB_ANNOUNCE_NEW_DEVICES
static void show_string(struct usb_device *udev, char *id, char *string)
{
        if (!string)
                return;
        dev_printk(KERN_INFO, &udev->dev, "%s: %s\n", id, string);
}

So, why the spam? Because these aren't wrapped:
        dev_info(&udev->dev, "USB disconnect, device number %d\n",
                        udev->devnum);

                dev_info(&udev->dev,
                                "%s %s USB device number %d using %s\n",
                                (udev->config) ? "reset" : "new", speed,
                                devnum, udev->bus->controller->driver->name);
Solution: Wrap:
#ifdef CONFIG_USB_ANNOUNCE_NEW_DEVICES
        dev_info(&udev->dev, "USB disconnect, device number %d\n",
                        udev->devnum);
#endif

For Xorg.0.log, every switch back and forth results in this:

[ 51354.054] (II) config/udev: Adding input device Logitech Trackball (/dev/input/mouse0)
[ 51354.054] (II) No input driver specified, ignoring this device.
[ 51354.054] (II) This device may have been added with another device file.
[ 51354.054] (II) config/udev: Adding input device Logitech Trackball (/dev/input/event6)
[ 51354.054] (**) Logitech Trackball: Applying InputClass "evdev pointer catchall"
[ 51354.054] (II) Using input driver 'evdev' for 'Logitech Trackball'
[ 51354.054] (**) Logitech Trackball: always reports core events
[ 51354.054] (**) evdev: Logitech Trackball: Device: "/dev/input/event6"
[ 51354.054] (--) evdev: Logitech Trackball: Vendor 0x46d Product 0xc404
[ 51354.054] (--) evdev: Logitech Trackball: Found 3 mouse buttons
[ 51354.054] (--) evdev: Logitech Trackball: Found scroll wheel(s)
[ 51354.054] (--) evdev: Logitech Trackball: Found relative axes
[ 51354.054] (--) evdev: Logitech Trackball: Found x and y relative axes
[ 51354.054] (II) evdev: Logitech Trackball: Configuring as mouse
[ 51354.054] (II) evdev: Logitech Trackball: Adding scrollwheel support
[ 51354.054] (**) evdev: Logitech Trackball: YAxisMapping: buttons 4 and 5
[ 51354.054] (**) evdev: Logitech Trackball: EmulateWheelButton: 4, EmulateWheelInertia: 10, EmulateWheelTimeout: 200
[ 51354.054] (**) Option "config_info" "udev:/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2/2-2.2:1.0/input/input24/event6"
[ 51354.054] (II) XINPUT: Adding extended input device "Logitech Trackball" (type: MOUSE, id 8)
[ 51354.054] (II) evdev: Logitech Trackball: initialized for relative axes.
[ 51354.054] (**) Logitech Trackball: (accel) keeping acceleration scheme 1
[ 51354.054] (**) Logitech Trackball: (accel) acceleration profile 0
[ 51354.054] (**) Logitech Trackball: (accel) acceleration factor: 2.000
[ 51354.054] (**) Logitech Trackball: (accel) acceleration threshold: 4

[ 58510.586] (II) config/udev: removing device Logitech Trackball
[ 58510.587] (II) evdev: Logitech Trackball: Close
[ 58510.587] (II) UnloadModule: "evdev"

The solution for this spam didn't require a recompile --- only digging through the usual delightful lack of anything resembling documentation for X.
$ X -help
yields:

-verbose [n]           verbose startup messages
-logverbose [n]        verbose log messages

Great! So, what should [n] be to do less log messages? Oh, right, who'd want to know that? 

It turns out it's somewhat similar to kernel logging, so higher numbers are noisier.  Based on the source:
/* Flags for log messages. */
typedef enum {
    X_PROBED,                   /* Value was probed */
    X_CONFIG,                   /* Value was given in the config file */
    X_DEFAULT,                  /* Value is a default */
    X_CMDLINE,                  /* Value was given on the command line */
    X_NOTICE,                   /* Notice */
    X_ERROR,                    /* Error message */
    X_WARNING,                  /* Warning message */
    X_INFO,                     /* Informational message */
    X_NONE,                     /* No prefix */
    X_NOT_IMPLEMENTED,          /* Not implemented */
    X_UNKNOWN = -1              /* unknown -- this must always be last */
} MessageType;
/* Returns the Message Type string to prepend to a logging message, or NULL
 * if the message will be dropped due to insufficient verbosity. */
static const char *
LogMessageTypeVerbString(MessageType type, int verb)
{
    if (type == X_ERROR)
        verb = 0;

    if (logVerbosity < verb && logFileVerbosity < verb)
        return NULL;

    switch (type) {
    case X_PROBED:
        return X_PROBE_STRING;
    case X_CONFIG:
        return X_CONFIG_STRING;
    case X_DEFAULT:
        return X_DEFAULT_STRING;
    case X_CMDLINE:
        return X_CMDLINE_STRING;
    case X_NOTICE:
        return X_NOTICE_STRING;
    case X_ERROR:
        return X_ERROR_STRING;
    case X_WARNING:
        return X_WARNING_STRING;
    case X_INFO:
        return X_INFO_STRING;
    case X_NOT_IMPLEMENTED:
        return X_NOT_IMPLEMENTED_STRING;
    case X_UNKNOWN:
        return X_UNKNOWN_STRING;
    case X_NONE:
        return X_NONE_STRING;
    default:
        return X_UNKNOWN_STRING;
    }
}

So, the easy solution to kill the spam:
$ vi /etc/X11/xinit/xserverrc
change
exec /usr/bin/X -nolisten tcp "$@"
to
exec /usr/bin/X -logverbose 1 -nolisten tcp "$@"

(YMMV. This is with Debian (#!) )
This allows the usual startup messages for debugging, but gets rid of the constant 'Look at me!" kvm switch messages.

And a bit of bonus irritation, on boot, I was getting these friendly messages:

udevd[25342]: failed to execute '/lib/udev/mtp-probe' 'mtp-probe /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2 2 20': No such file or directory
udevd[25656]: failed to execute '/lib/udev/mtp-probe' 'mtp-probe /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2 2 21': No such file or directory
udevd[26105]: failed to execute '/lib/udev/mtp-probe' 'mtp-probe /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2 2 22': No such file or directory
udevd[10556]: failed to execute '/lib/udev/mtp-probe' 'mtp-probe /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2/2-2.2 2 23': No such file or directory

My first thought was to remove mtp, since it's a worthless Microsoft abortion... but, since vlc, which is occasionally useful, depends on it, the more proper fix seems to be this:
$ vi /lib/udev/rules.d/69-libmtp.rules
and comment out this line:

# Autoprobe vendor-specific, communication and PTP devices
ENV{ID_MTP_DEVICE}!="1", ENV{MTP_NO_PROBE}!="1", ENV{COLOR_MEASUREMENT_DEVICE}!="1", ENV{libsane_matched}!="yes", ATTR{bDeviceClass}=="00|02|06|ef|ff", PROGRAM="mtp-probe /sys$env{DEVPATH} $attr{busnum} $attr{devnum}", RESULT=="1", SYMLINK+="libmtp-%k", MODE="660", GROUP="audio", ENV{ID_MTP_DEVICE}="1", ENV{ID_MEDIA_PLAYER}="1"

And done! Needles are easier to find when the haystack isn't augmented by rotten weeds...



No comments: