System crash (Kernel Oops) during USB Bulk Transfer (Read) with Transfer Buffers >16k

localuser2 commented 4 years ago

Description

A USB bulk read transfer with a transfer buffer size >16 KiB (16384 Bytes) results in frequent system crashes (Kernel Oops). The problem could to be connected to a strange behaviour of the Linux Kernel for ARM regarding USB read transfers: If the transfer buffer exceeds a length of 16KiB the USB read request seems to result always in multiple USB Request Blocks (URB). This is observable via Wireshark on all (for me accessible) ARM platforms. An amd64-Kernel of roughly the same version does not show this behaviour.

Steps to reproduce

The crashes seem to be independent from the kind of the USB device or the driver back-end. I was able to reproduce the problem with libusb0 as well as with libusb1 and at least two different USB controllers. However the generation of the RaspberryPi hardware seems to be relevant. We found the problem with a RasperryPi 3 (B+) the most current model RaspberryPi 4 seems to be not affected. To reproduce the crash, you will need some kind of USB hardware to read from. For the example I used a setup of two DIGITUS USB-to-Serial converters and a Null-Modem-Cable:

connect one side of the Null-Modem-Cable to a Linux-PC
become root (or set up a udev-rule) to be able to write to the serial interface
write data to the serial interface (e.g. while true;do echo BLABLUBB > /dev/ttyUSB0;done)
connect the other side of the Null-Modem-Cable to a RaspberryPi 3 (B+?)
install gcc C compiler and package libusb-1.0-0-dev
compile the attached code example: gcc -lusb-1.0 -o usb-crash usb-crash.c
unload the FTDI kernel driver (e.g. sudo rmmod ftdi-sio) to be able to open the USB device
become root (or set up a udev-rule) to be able to read from the serial interface
execute example program ./usb-crash

#include <stdio.h>
#include <stdlib.h>

#include <libusb-1.0/libusb.h>

// if this define is changed to 16384 or a lesser value, the crashes disappear
#define BUFLEN 16384+1

static unsigned char buf[BUFLEN];

int main(void)
{
  int result = libusb_init(NULL);
  if (result < 0)
  {
    fprintf(stderr, "failed to initialize libusb\n");
    exit(1);
  }

  // this is the Product and Vendor ID of the DIGITUS USB-to-Serial converter (FTDI-based)
  // however, the problem seems to be reproducible with similar hardware -> edit if necessary
  libusb_device_handle *devh = libusb_open_device_with_vid_pid(NULL, 0x0403, 0x6001);

  if (!devh)
  {
    fprintf(stderr, "failed to open device\n");
    exit(1);
  }

  int actual_length;

  // this loop will crash the raspi with high probability
  for (int ix = 0; ix < 10000; ++ix)
  {
    result = libusb_claim_interface(devh, 0);
    if (result < 0)
    {
      fprintf(stderr, "libusb_usb_claim_interface error %d\n", result);
      exit(1);
    }

    // 129 is the read endpoint for bulk transfers of this device -> edit if necessary
    result = libusb_bulk_transfer(devh, 129, (unsigned char*)&buf, BUFLEN, &actual_length, 1000);
    if (result < 0)
    {
      fprintf(stderr, "libusb_bulk_transfer error %d\n", result);
      libusb_release_interface(devh, 0);
      exit(1);
    }

    printf("Iteration %d: Actually read %d bytes\n", ix, actual_length);

    libusb_release_interface(devh, 0);
  }

  return 0;
}

Expected behaviour

The USB read transfers should be executed without errors. This is what happens on a PC (current Debian 10/Buster on AMD64 hardware) or a RaspberryPi 4.

Actual behaviour

The System crashes. The Oops is usually not reported in the Syslog. However sometimes an crash output is visible in the terminal before the system freezes completely (output of attached demo application):

Iteration 52: Actually read 4 bytes
Iteration 53: Actually read 22 bytes
Iteration 54: Actually read 3 bytes
Iteration 55: Actually read 3 bytes

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.029156] Internal error: Oops: 5 [#14] SMP ARM

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.087069] Process usb-crash (pid: 962, stack limit = 0x60771838)

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.089863] Stack: (0xb761bc48 to 0xb761c000)

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.092587] bc40:                   b96c1470 00000008 b761bc6c 0000d3d2 8014e0e0 8014dc40

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.097921] bc60: b761bc94 b8cfa028 00000007 80d6beb4 80aa9b40 8093c950 00000000 b9ce2b00

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.103201] bc80: b761bcdc b761bc90 8081f804 80295088 b8cfa020 00000007 00000034 801444e0

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.108460] bca0: b761bcd4 b761bcb0 801444e0 80ab3dbc 00000000 b8cfa020 b8cfa054 80d6beb4

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.113804] bcc0: 00000000 00000034 b96c1470 00000008 b761bcec b761bce0 8081fde0 8081f73c

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.119415] bce0: b761bd14 b761bcf0 805ab638 8081fdd8 00000003 00000001 b8cfa020 b8cfa000

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.125416] bd00: b96b34ac 00000000 b761bd24 b761bd18 805ab66c 805ab430 b761bd4c b761bd28

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.131631] bd20: 80624104 805ab658 80d04d48 80831d24 00000005 00000000 b8c50300 b8cfa000

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.138177] bd40: b761bd6c b761bd50 80629198 8062407c 00000001 00000000 b8c50300 b96b3400

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.144861] bd60: b761bd8c b761bd70 8062945c 80629140 b05d9cc0 b96c1470 b9d95510 b9bdbcc0

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.151705] bd80: b761bdcc b761bd90 802ac8cc 806293e0 00000000 00000000 801405b4 b05d9cc8

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.156168] bda0: b2b50538 b05d9c00 b2b5051c b2b50000 b2b50538 80d9e35c b05d9cc0 000000a8

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.159184] bdc0: b761bddc b761bdd0 802aca80 802ac834 b761be04 b761bde0 801405d0 802aca74

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.162210] bde0: b2b50000 00000534 00000538 b761be0c 00000001 b2b9083c b761be44 b761be08

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.165237] be00: 80124f74 80140520 80d04d48 fffffdfc b761bec4 9dff151b 400004d8 00000002

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.168263] be20: b2b4c2c0 fffffdfc b761bec4 76e33cd0 400004d8 000000a8 b761be64 b761be48

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.171288] be40: 80125844 80124ba0 b761bec4 b761bfb0 00418004 fffffdfc b761bebc b761be68

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.174300] be60: 8013172c 80125804 00000003 418004fc 80d8f2f0 00000000 80d04d70 b761bed8

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.177324] be80: b2b58540 b2b58a44 b2b4c2c0 b761bec4 00000000 b761bfb0 80d04d48 fffffdfc

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.180353] bea0: b761bec4 76e33cd0 76e33cd4 000000a8 b761bf8c b761bec0 8010c948 80131594

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.183378] bec0: 00027b40 802c1dc4 0000003c 00000000 000000da 00000000 00000009 b761bf70

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.186403] bee0: b761bf20 00000000 00000000 b761a000 b761bf64 b761bf08 802c1dc4 801959d4

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.189424] bf00: 000000da 00000000 00ec7261 00000001 0000003c 00000000 00000000 9dff151b

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.192438] bf20: 00000116 00000000 00ec7261 802cbd6c 0000003c 9dff151b 00000000 80d04d48

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.195459] bf40: 00000003 80c92ad8 8010cbec 801011c4 b761bfb0 801011c4 b761a000 9dff151b

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.198479] bf60: b761bf8c 00000001 b761a010 801011c4 b761bfb0 801011c4 b761a000 000000a8

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.201497] bf80: b761bfac b761bf90 8010cc64 8010c5f0 0000ea60 00000003 0003ace0 000000a8

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.204519] bfa0: 00000000 b761bfb0 80101034 8010cb94 0003ace0 00000003 0000ea60 00000000

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.207532] bfc0: 0000ea60 00000003 0003ace0 000000a8 00000003 0003ace0 76ec66ac 7ef155ec

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.210548] bfe0: 00000002 7ef15578 00000000 76e33cd0 80000010 0003ace0 00000000 00000000

Message from syslogd@smartnir at Jan  2 14:27:03 ...
 kernel:[  218.262888] Code: e7904001 e3540000 0a000056 e5973014 (e7943003)

System

------------------

Raspberry Pi 3 Model B Plus Rev 1.3
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"

Raspberry Pi reference 2018-11-13
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 7e0c786c641ba15990b5662f092c106beed40c9f, stage2

Linux smartnir 4.19.75-v7+ #1270 SMP Tue Sep 24 18:45:11 BST 2019 armv7l GNU/Linux
Revision    : a020d3
Serial      : 00000000d0bbd74b
Model       : Raspberry Pi 3 Model B Plus Rev 1.3
Throttled flag  : throttled=0x0
Camera          : supported=0 detected=0

Videocore information
---------------------

Sep 24 2019 17:37:19 
Copyright (c) 2012 Broadcom
version 6820edeee4ef3891b95fc01cf02a7abd7ca52f17 (clean) (release) (start)

alloc failures:     0
compactions:        0
legacy block fails: 0

Filesystem information
----------------------
Filesystem     1K-blocks    Used Available Use% Mounted on
/dev/root       30611780 3491672  25843768  12% /
devtmpfs          469544       0    469544   0% /dev
tmpfs             474152       0    474152   0% /dev/shm
tmpfs             474152    6332    467820   2% /run
tmpfs               5120       4      5116   1% /run/lock
tmpfs             474152       0    474152   0% /sys/fs/cgroup
/dev/mmcblk0p1     44220   22927     21294  52% /boot
tmpfs              94828       0     94828   0% /run/user/1000

Filename                Type        Size    Used    Priority
/var/swap                               file        102396  0   -2

Package version information
---------------------------
raspberrypi-ui-mods:
  Installed: (none)
raspberrypi-sys-mods:
  Installed: 20191105
openbox:
  Installed: (none)
lxpanel:
  Installed: (none)
pcmanfm:
  Installed: (none)
rpd-plym-splash:
  Installed: (none)

Networking Information
----------------------

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet x.x.x.x  netmask x.x.x.x  broadcast x.x.x.x
        inet6 y::y.y.y.y  prefixlen 64  scopeid 0x20<link>
        ether m.m.m.m  txqueuelen 1000  (Ethernet)
        RX packets 3779  bytes 372548 (363.8 KiB)
        RX errors 0  dropped 1  overruns 0  frame 0
        TX packets 537  bytes 65890 (64.3 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet x.x.x.x  netmask x.x.x.x
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 198  bytes 17851 (17.4 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 198  bytes 17851 (17.4 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

wlan0: flags=4099<UP,BROADCAST,MULTICAST>  mtu 1500
        ether m.m.m.m  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

USB Information
---------------

/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 1: Dev 3, If 0, Class=Hub, Driver=hub/3p, 480M
            |__ Port 1: Dev 5, If 0, Class=Vendor Specific Class, Driver=lan78xx, 480M
        |__ Port 3: Dev 4, If 0, Class=Vendor Specific Class, Driver=ftdi_sio, 12M

config.txt
----------

aphy_params_current=819
arm_freq=1400
audio_pwm_mode=514
config_hdmi_boost=5
core_freq=400
desired_osc_freq=0x331df0
desired_osc_freq_boost=0x3c45b0
disable_commandline_tags=2
disable_l2cache=1
display_hdmi_rotate=-1
display_lcd_rotate=-1
dphy_params_current=547
force_eeprom_read=1
force_pwm_open=1
framebuffer_ignore_alpha=1
framebuffer_swap=1
gpu_freq=300
init_uart_clock=0x2dc6c00
lcd_framerate=60
over_voltage_avs=31250
over_voltage_avs_boost=0x2191c
pause_burst_frames=1
program_serial_random=1
sdram_freq=450
hdmi_force_cec_address:0=65535
hdmi_force_cec_address:1=65535
hdmi_pixel_freq_limit:0=0x9a7ec80
hdmi_pixel_freq_limit:1=0x9a7ec80
device_tree=-
hdmi_cvt:0=
hdmi_cvt:1=
hdmi_edid_filename:0=
hdmi_edid_filename:1=
hdmi_timings:0=
hdmi_timings:1=

cmdline.txt
-----------
coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=106135ba-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait

raspi-gpio settings
-------------------

BANK0 (GPIO 0 to 27):
GPIO 0: level=1 fsel=0 func=INPUT
GPIO 1: level=1 fsel=0 func=INPUT
GPIO 2: level=1 fsel=0 func=INPUT
GPIO 3: level=1 fsel=0 func=INPUT
GPIO 4: level=1 fsel=0 func=INPUT
GPIO 5: level=1 fsel=0 func=INPUT
GPIO 6: level=1 fsel=0 func=INPUT
GPIO 7: level=1 fsel=0 func=INPUT
GPIO 8: level=1 fsel=0 func=INPUT
GPIO 9: level=0 fsel=0 func=INPUT
GPIO 10: level=0 fsel=0 func=INPUT
GPIO 11: level=0 fsel=0 func=INPUT
GPIO 12: level=0 fsel=0 func=INPUT
GPIO 13: level=0 fsel=0 func=INPUT
GPIO 14: level=0 fsel=0 func=INPUT
GPIO 15: level=1 fsel=0 func=INPUT
GPIO 16: level=0 fsel=0 func=INPUT
GPIO 17: level=0 fsel=0 func=INPUT
GPIO 18: level=0 fsel=0 func=INPUT
GPIO 19: level=0 fsel=0 func=INPUT
GPIO 20: level=0 fsel=0 func=INPUT
GPIO 21: level=0 fsel=0 func=INPUT
GPIO 22: level=0 fsel=0 func=INPUT
GPIO 23: level=0 fsel=0 func=INPUT
GPIO 24: level=0 fsel=0 func=INPUT
GPIO 25: level=0 fsel=0 func=INPUT
GPIO 26: level=0 fsel=0 func=INPUT
GPIO 27: level=0 fsel=0 func=INPUT
BANK1 (GPIO 28 to 45):
GPIO 28: level=1 fsel=0 func=INPUT
GPIO 29: level=0 fsel=1 func=OUTPUT
GPIO 30: level=0 fsel=7 alt=3 func=CTS0
GPIO 31: level=0 fsel=7 alt=3 func=RTS0
GPIO 32: level=1 fsel=7 alt=3 func=TXD0
GPIO 33: level=1 fsel=7 alt=3 func=RXD0
GPIO 34: level=0 fsel=7 alt=3 func=SD1_CLK
GPIO 35: level=1 fsel=7 alt=3 func=SD1_CMD
GPIO 36: level=1 fsel=7 alt=3 func=SD1_DAT0
GPIO 37: level=1 fsel=7 alt=3 func=SD1_DAT1
GPIO 38: level=1 fsel=7 alt=3 func=SD1_DAT2
GPIO 39: level=1 fsel=7 alt=3 func=SD1_DAT3
GPIO 40: level=0 fsel=4 alt=0 func=PWM0
GPIO 41: level=0 fsel=4 alt=0 func=PWM1
GPIO 42: level=0 fsel=4 alt=0 func=GPCLK1
GPIO 43: level=0 fsel=4 alt=0 func=GPCLK2
GPIO 44: level=1 fsel=0 func=INPUT
GPIO 45: level=1 fsel=0 func=INPUT
BANK2 (GPIO 46 to 53):
GPIO 46: level=1 fsel=0 func=INPUT
GPIO 47: level=1 fsel=1 func=OUTPUT
GPIO 48: level=0 fsel=4 alt=0 func=SD0_CLK
GPIO 49: level=1 fsel=4 alt=0 func=SD0_CMD
GPIO 50: level=1 fsel=4 alt=0 func=SD0_DAT0
GPIO 51: level=1 fsel=4 alt=0 func=SD0_DAT1
GPIO 52: level=1 fsel=4 alt=0 func=SD0_DAT2
GPIO 53: level=1 fsel=4 alt=0 func=SD0_DAT3

vcdbg log messages
------------------

001312.064: brfs: File read: /mfs/sd/config.txt
001312.935: brfs: File read: 1590 bytes
001323.532: HDMI:EDID error reading EDID block 0 attempt 0
001324.834: HDMI:EDID error reading EDID block 0 attempt 1
001326.127: HDMI:EDID error reading EDID block 0 attempt 2
001327.422: HDMI:EDID error reading EDID block 0 attempt 3
001328.715: HDMI:EDID error reading EDID block 0 attempt 4
001330.010: HDMI:EDID error reading EDID block 0 attempt 5
001331.304: HDMI:EDID error reading EDID block 0 attempt 6
001332.599: HDMI:EDID error reading EDID block 0 attempt 7
001333.891: HDMI:EDID error reading EDID block 0 attempt 8
001335.186: HDMI:EDID error reading EDID block 0 attempt 9
001336.243: HDMI:EDID giving up on reading EDID block 0
001336.601: HDMI:EDID error reading EDID block 0 attempt 0
001337.899: HDMI:EDID error reading EDID block 0 attempt 1
001339.197: HDMI:EDID error reading EDID block 0 attempt 2
001340.495: HDMI:EDID error reading EDID block 0 attempt 3
001341.793: HDMI:EDID error reading EDID block 0 attempt 4
001343.091: HDMI:EDID error reading EDID block 0 attempt 5
001344.389: HDMI:EDID error reading EDID block 0 attempt 6
001345.699: HDMI:EDID error reading EDID block 0 attempt 7
001346.997: HDMI:EDID error reading EDID block 0 attempt 8
001348.296: HDMI:EDID error reading EDID block 0 attempt 9
001349.359: HDMI:EDID giving up on reading EDID block 0
001366.528: brfs: File read: /mfs/sd/config.txt
001587.431: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
001589.526: *** Restart logging
001589.592: brfs: File read: 1590 bytes
001590.345: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
001591.655: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
001592.958: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
001594.261: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
001595.564: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
001596.867: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
001598.170: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
001599.473: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
001600.776: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
001602.079: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
001603.146: hdmi: HDMI:EDID giving up on reading EDID block 0
001603.509: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
001604.807: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
001606.104: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
001607.400: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
001608.696: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
001609.993: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
001611.289: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
001612.585: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
001613.882: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
001615.178: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
001616.238: hdmi: HDMI:EDID giving up on reading EDID block 0
001616.318: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001616.390: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001620.083: brfs: File read: /mfs/sd/cmdline.txt
001620.181: Read command line from file 'cmdline.txt':
001620.244: 'dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=106135ba-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait'
001624.904: brfs: File read: 142 bytes
001628.824: brfs: File read: /mfs/sd/bcm2710-rpi-3-b-plus.dtb
001628.889: Loading 'bcm2710-rpi-3-b-plus.dtb' to 0x100 size 0x69ca
001782.762: brfs: File read: 27082 bytes
001786.616: brfs: File read: /mfs/sd/config.txt
001787.240: dtparam: audio=on
004158.457: gpioman: gpioman_get_pin_num: pin EMMC_ENABLE not defined
004259.887: brfs: File read: 1590 bytes
004627.418: brfs: File read: /mfs/sd/kernel7.img
004627.481: Loading 'kernel7.img' to 0x8000 size 0x5108a0
004627.551: Device tree loaded to 0x2eff9200 (size 0x6df5)
004630.102: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
006021.374: vchiq_core: vchiq_init_state: slot_zero = 0xfad80000, is_master = 1
010456.847: brfs: File read: 5310624 bytes

dmesg log
---------

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.75-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1270 SMP Tue Sep 24 18:45:11 BST 2019
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x3ac00000
[    0.000000] On node 0 totalpages: 242688
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:63
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
[    0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632
[    0.000000] pcpu-alloc: s39488 r8192 d21952 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=106135ba-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 939088K/970752K available (8192K kernel code, 629K rwdata, 2176K rodata, 1024K init, 821K bss, 23472K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
                   lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)
                   modules : 0x7f000000 - 0x80000000   (  16 MB)
                     .text : 0x(ptrval) - 0x(ptrval)   (9184 kB)
                     .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
                     .data : 0x(ptrval) - 0x(ptrval)   ( 630 kB)
                      .bss : 0x(ptrval) - 0x(ptrval)   ( 822 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 26399 entries in 78 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000023] Switching to timer-based delay loop, resolution 52ns
[    0.000291] Console: colour dummy device 80x30
[    0.000911] console [tty1] enabled
[    0.000969] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.001014] pid_max: default: 32768 minimum: 301
[    0.001371] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001408] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.002345] CPU: Testing write buffer coherency: ok
[    0.002824] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003496] Setting up static identity map for 0x100000 - 0x10003c
[    0.003665] rcu: Hierarchical SRCU implementation.
[    0.004480] smp: Bringing up secondary CPUs ...
[    0.005338] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.006262] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.007128] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007249] smp: Brought up 1 node, 4 CPUs
[    0.007330] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.007354] CPU: All CPU(s) started in HYP mode.
[    0.007374] CPU: Virtualization extensions available.
[    0.008363] devtmpfs: initialized
[    0.021487] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.021758] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.021806] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.022425] pinctrl core: initialized pinctrl subsystem
[    0.023296] NET: Registered protocol family 16
[    0.026282] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.031934] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.031970] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.032194] Serial: AMBA PL011 UART driver
[    0.034506] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.069076] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.071008] SCSI subsystem initialized
[    0.071252] usbcore: registered new interface driver usbfs
[    0.071333] usbcore: registered new interface driver hub
[    0.071447] usbcore: registered new device driver usb
[    0.090300] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-09-24 17:37, variant start
[    0.100130] raspberrypi-firmware soc:firmware: Firmware hash is 6820edeee4ef3891b95fc01cf02a7abd7ca52f17
[    0.111752] clocksource: Switched to clocksource arch_sys_counter
[    0.201223] VFS: Disk quotas dquot_6.6.0
[    0.201334] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.201512] FS-Cache: Loaded
[    0.201761] CacheFiles: Loaded
[    0.211696] NET: Registered protocol family 2
[    0.212522] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[    0.212587] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.212731] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.212936] TCP: Hash tables configured (established 8192 bind 8192)
[    0.213098] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.213164] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.213495] NET: Registered protocol family 1
[    0.214079] RPC: Registered named UNIX socket transport module.
[    0.214106] RPC: Registered udp transport module.
[    0.214127] RPC: Registered tcp transport module.
[    0.214149] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.215846] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.218863] Initialise system trusted keyrings
[    0.219081] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.228918] FS-Cache: Netfs 'nfs' registered for caching
[    0.229504] NFS: Registering the id_resolver key type
[    0.229547] Key type id_resolver registered
[    0.229569] Key type id_legacy registered
[    0.229601] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.231940] Key type asymmetric registered
[    0.231969] Asymmetric key parser 'x509' registered
[    0.232037] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.232219] io scheduler noop registered
[    0.232243] io scheduler deadline registered (default)
[    0.232437] io scheduler cfq registered
[    0.232461] io scheduler mq-deadline registered (default)
[    0.232485] io scheduler kyber registered
[    0.234683] bcm2708_fb soc:fb: FB found 1 display(s)
[    0.244016] Console: switching to colour frame buffer device 82x26
[    0.250852] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[    0.257568] bcm2835-rng 3f104000.rng: hwrng registered
[    0.260252] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.265590] vc-sm: Videocore shared memory driver
[    0.268342] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.284204] brd: module loaded
[    0.296852] loop: module loaded
[    0.299905] Loading iSCSI transport class v2.0-870.
[    0.303097] libphy: Fixed MDIO Bus: probed
[    0.305607] usbcore: registered new interface driver lan78xx
[    0.308067] usbcore: registered new interface driver smsc95xx
[    0.310419] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.340685] dwc_otg 3f980000.usb: base=(ptrval)
[    0.543339] Core Release: 2.80a
[    0.545719] Setting default values for core params
[    0.548162] Finished setting default values for core params
[    0.750910] Using Buffer DMA mode
[    0.753317] Periodic Transfer Interrupt Enhancement - disabled
[    0.755741] Multiprocessor Interrupt Enhancement - disabled
[    0.758112] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.760455] Dedicated Tx FIFOs mode
[    0.763166] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = bad14000 dma = 0xfad14000 len=9024
[    0.767743] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.778650] dwc_otg: Microframe scheduler enabled
[    0.778710] WARN::hcd_init_fiq:457: FIQ on core 1
[    0.780938] WARN::hcd_init_fiq:458: FIQ ASM at 80655664 length 36
[    0.783153] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
[    0.785414] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.787677] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.789999] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    0.792323] Init: Port Power? op_state=1
[    0.794567] Init: Power Port (0)
[    0.796991] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.801504] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.803939] usb usb1: Product: DWC OTG Controller
[    0.806310] usb usb1: Manufacturer: Linux 4.19.75-v7+ dwc_otg_hcd
[    0.808733] usb usb1: SerialNumber: 3f980000.usb
[    0.811681] hub 1-0:1.0: USB hub found
[    0.813990] hub 1-0:1.0: 1 port detected
[    0.816743] dwc_otg: FIQ enabled
[    0.816749] dwc_otg: NAK holdoff enabled
[    0.816754] dwc_otg: FIQ split-transaction FSM enabled
[    0.816765] Module dwc_common_port init
[    0.817036] usbcore: registered new interface driver usb-storage
[    0.819490] mousedev: PS/2 mouse device common for all mice
[    0.822663] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    0.825294] bcm2835-cpufreq: min=600000 max=1400000
[    0.828120] sdhci: Secure Digital Host Controller Interface driver
[    0.830535] sdhci: Copyright(c) Pierre Ossman
[    0.833334] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[    0.836243] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    0.838920] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.843039] ledtrig-cpu: registered to indicate activity on CPUs
[    0.845776] hidraw: raw HID events driver (C) Jiri Kosina
[    0.848550] usbcore: registered new interface driver usbhid
[    0.851184] usbhid: USB HID core driver
[    0.854525] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    0.858616] [vc_sm_connected_init]: start
[    0.867408] [vc_sm_connected_init]: end - returning 0
[    0.870950] Initializing XFRM netlink socket
[    0.873415] NET: Registered protocol family 17
[    0.875930] Key type dns_resolver registered
[    0.878777] Registering SWP/SWPB emulation handler
[    0.881890] registered taskstats version 1
[    0.884305] Loading compiled-in X.509 certificates
[    0.894043] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    0.896579] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    0.903395] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    0.905937] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    0.934568] sdhost: log_buf @ (ptrval) (fad13000)
[    0.972005] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    0.975982] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.979845] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.984872] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    0.987006] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    0.990383] of_cfs_init
[    0.992550] of_cfs_init: OK
[    0.995053] Waiting for root device PARTUUID=106135ba-02...
[    1.031879] Indeed it is in host mode hprt0 = 00021501
[    1.102319] random: fast init done
[    1.130452] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.138705] mmc0: new high speed SDHC card at address aaaa
[    1.143719] mmc1: new high speed SDIO card at address 0001
[    1.146413] mmcblk0: mmc0:aaaa SC32G 29.7 GiB
[    1.153576]  mmcblk0: p1 p2
[    1.176202] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
[    1.178350] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
[    1.241811] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.244121] Indeed it is in host mode hprt0 = 00001101
[    1.482058] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    1.486460] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.489594] hub 1-1:1.0: USB hub found
[    1.492238] hub 1-1:1.0: 4 ports detected
[    1.559415] EXT4-fs (mmcblk0p2): orphan cleanup on readonly fs
[    1.562179] EXT4-fs (mmcblk0p2): 1 orphan inode deleted
[    1.564778] EXT4-fs (mmcblk0p2): recovery complete
[    1.612988] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.618102] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.629878] devtmpfs: mounted
[    1.637737] Freeing unused kernel memory: 1024K
[    1.640673] Run /sbin/init as init process
[    1.811801] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.942095] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    1.947401] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.950872] hub 1-1.1:1.0: USB hub found
[    1.953735] hub 1-1.1:1.0: 3 ports detected
[    2.051799] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
[    2.209374] usb 1-1.3: New USB device found, idVendor=0403, idProduct=6001, bcdDevice= 6.00
[    2.214515] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.217182] usb 1-1.3: Product: FT232R USB UART
[    2.219850] usb 1-1.3: Manufacturer: FTDI
[    2.222507] usb 1-1.3: SerialNumber: AK06RXXK
[    2.361533] systemd[1]: System time before build time, advancing clock.
[    2.495945] NET: Registered protocol family 10
[    2.500002] Segment Routing with IPv6
[    2.547225] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    2.556433] systemd[1]: Detected architecture arm.
[    2.594864] systemd[1]: Set hostname to <smartnir>.
[    2.599728] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument
[    2.731877] usb 1-1.1.1: new high-speed USB device number 5 using dwc_otg
[    2.872385] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
[    2.877898] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.005318] systemd[1]: File /lib/systemd/system/systemd-journald.service:12 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
[    3.014263] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.)
[    3.147828] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
[    3.155239] libphy: lan78xx-mdiobus: probed
[    3.186826] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
[    3.557061] random: systemd: uninitialized urandom read (16 bytes read)
[    3.571736] random: systemd: uninitialized urandom read (16 bytes read)
[    3.580493] systemd[1]: Created slice system-getty.slice.
[    3.587629] random: systemd: uninitialized urandom read (16 bytes read)
[    3.592460] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    3.600105] systemd[1]: Listening on udev Control Socket.
[    3.607240] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    4.334062] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    4.444749] systemd-journald[105]: Received request to flush runtime journal from PID 1
[    5.104105] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    5.106736] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    5.106752] [vc_sm_connected_init]: start
[    5.108509] [vc_sm_connected_init]: installed successfully
[    5.136671] media: Linux media interface: v0.10
[    5.173849] videodev: Linux video capture interface: v2.00
[    5.254908] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.285932] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    5.288990] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    5.301522] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    5.301579] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    5.308635] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    5.309316] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    5.309351] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    5.318373] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    5.318410] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    5.323242] bcm2835_audio soc:audio: card created with 8 channels
[    5.467056] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    5.530356] usbcore: registered new interface driver usbserial_generic
[    5.530427] usbserial: USB Serial support registered for generic
[    5.548037] usbcore: registered new interface driver ftdi_sio
[    5.548115] usbserial: USB Serial support registered for FTDI USB Serial Device
[    5.548408] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
[    5.548562] usb 1-1.3: Detected FT232RL
[    5.571955] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
[    5.606093] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    5.688640] brcmfmac: F1 signature read @0x18000000=0x15264345
[    5.702060] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    5.702488] usbcore: registered new interface driver brcmfmac
[    5.946000] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    5.964923] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
[    6.002760] random: crng init done
[    6.002775] random: 7 urandom warning(s) missed due to ratelimiting
[    7.386880] uart-pl011 3f201000.serial: no DMA platform data
[    7.461254] 8021q: 802.1Q VLAN Support v1.8
[    7.701852] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[    7.729112] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    7.729147] brcmfmac: power management disabled
[    7.966567] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    7.966585] 8021q: adding VLAN 0 to HW filter on device eth0
[    7.975401] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   14.276568] Bluetooth: Core ver 2.22
[   14.276665] NET: Registered protocol family 31
[   14.276673] Bluetooth: HCI device and connection manager initialized
[   14.276696] Bluetooth: HCI socket layer initialized
[   14.276709] Bluetooth: L2CAP socket layer initialized
[   14.276750] Bluetooth: SCO socket layer initialized
[   14.297562] Bluetooth: HCI UART driver ver 2.3
[   14.297576] Bluetooth: HCI UART protocol H4 registered
[   14.297661] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   14.297866] Bluetooth: HCI UART protocol Broadcom registered
[   14.544601] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   14.544611] Bluetooth: BNEP filters: protocol multicast
[   14.544631] Bluetooth: BNEP socket layer initialized

JamesH65 commented 4 years ago

@P33M This one's for you I think!!

P33M commented 4 years ago

I can't reproduce. 2000+ iterations and counting. Is the baudrate important?

I strongly recommend getting a full stack trace and dmesg log via the onboard GPIO uart on GPIO 14 and 15 - add the parameters "enable_uart=1" and "dtoverlay=pi3-disable-bt" to /boot/config.txt and reboot. Uart is at 115200 baud by default.

After rebooting, enable kdgb: echo ttyAMA0,115200 | sudo tee /sys/module/kgdboc/parameters/kgdboc

When you get a crash you should drop into a kgdb prompt on the uart. Press spacebar to scroll through the stack trace then do "dmesg" and "btc" to capture the full output.

P33M commented 4 years ago

I do see one odd message in dmesg though:

[   31.351907] dwc_otg: DEVICE:004 : update_urb_state_xfer_comp:751:trimming xfer length

But this happens only once.

Edit; and of course, it's a printk_once in the driver.

P33M commented 4 years ago

Aha, after messing with baudrates on both ends I finally get a crash:

pi@raspberrypi:~$ [  206.983853] Unable to handle kernel paging request at virtual address 0ee06801
[  206.991082] pgd = c03209db
[  206.993782] [0ee06801] *pgd=00000000
[  206.997357] Internal error: Oops: 5 [#1] SMP ARM
[  207.001967] Modules linked in: fuse 8021q garp stp llc brcmfmac brcmutil sha256_generic usbserial cfg80211 rfkill raspberrypi_hwmon hwmon snd_bcm2835(C) snd_pcm snd_timer snd bcm2835_v4l2(C) bcm2835_codec(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) v4l2_common videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev media vc_sm_cma(C) uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6 [last unloaded: ftdi_sio]
[  207.041921] CPU: 0 PID: 1035 Comm: usb-crash Tainted: G         C        4.19.75-v7+ #1270
[  207.050184] Hardware name: BCM2835
[  207.053597] PC is at __kmalloc+0xac/0x288
[  207.057613] LR is at __kmalloc+0x60/0x288
[  207.061623] pc : [<80294ea0>]    lr : [<80294e54>]    psr: 20000093
[  207.067889] sp : a99d7bb0  ip : a99d7bb0  fp : a99d7bf4
[  207.073113] r10: b9c01e40  r9 : 80657540  r8 : 00488020
[  207.078339] r7 : b9c01e40  r6 : 0000002c  r5 : ad26d240  r4 : 0ee06801
[  207.084866] r3 : 00000000  r2 : 80c97a60  r1 : 396bd000  r0 : a99d7bb0
[  207.091394] Flags: nzCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment user
[  207.098617] Control: 10c5383d  Table: 2984c06a  DAC: 00000055
[  207.104367] Process usb-crash (pid: 1035, stack limit = 0xead25408)
[  207.110637] Stack: (0xa99d7bb0 to 0xa99d8000)
[  207.114999] 7ba0:                                     80d8b568 80d8b588 80d04d70 00020c80
[  207.123182] 7bc0: a99d7c14 a99d7bd0 80294fb4 b96b0000 ad26d240 b97d3020 ad26d240 b9430400
[  207.131365] 7be0: 00000000 00000000 a99d7c04 a99d7bf8 80657540 80294e00 a99d7c1c a99d7c08
[  207.139548] 7c00: 806514e4 80657528 b96b0000 00000001 a99d7c4c a99d7c20 8064a5d4 806514c4
[  207.147731] 7c20: a99d7c78 8061b6ec a99d7c4c b6346480 ad26d240 80d04d48 b96b0000 b9430400
[  207.155913] 7c40: a99d7cac a99d7c50 8064c3c0 8064a588 00004000 00000000 00000000 00000001
[  207.164096] 7c60: 00000000 8083719c 00000000 b97d3000 00000000 b97d3020 60000093 cb577e12
[  207.172281] 7c80: 8061d0d8 b6346480 b9430400 80d04d48 00000000 00480020 b6346488 00000000
[  207.180464] 7ca0: a99d7d5c a99d7cb0 8061d860 8064c1f0 a99d7cd4 80d8bb40 00000000 80d8bb40
[  207.188647] 7cc0: 00000000 00000000 00000000 a99d7cd8 8074f98c 806eefb0 00000000 b936a064
[  207.196829] 7ce0: 00000001 806ed564 00000001 cb577e12 80e6572c a99d7e78 af031f80 00004000
[  207.205012] 7d00: 006000c0 80295024 00000002 00000000 a99d7d2c a99d7d20 8026729c 802420c8
[  207.213195] 7d20: a99d7d5c a99d7d30 80267314 cb577e12 80831d24 b6346480 00480020 00000002
[  207.221376] 7d40: 00000201 b96b3400 00000040 00000000 a99d7da4 a99d7d60 8061f444 8061d794
[  207.229557] 7d60: a99d7d8c a99d7d70 80201fd4 8020304c 00000002 00000000 af031f80 a99d7e78
[  207.237738] 7d80: af031f80 80e3ff68 ad26d940 af031f94 af031f90 00000000 a99d7e1c a99d7da8
[  207.245919] 7da0: 8062bc24 8061f198 a99d7e1c a99d7dc0 802c8998 802c8894 5e0f24c0 00000000
[  207.254100] 7dc0: 20228679 af031f90 00000000 00000000 00000000 00000001 00000000 00000000
[  207.262281] 7de0: 00000000 00000001 006c1108 b97d3000 b96b34ac 80d04d48 b96b3478 b96b34ac
[  207.270462] 7e00: b96b3400 00000009 802c550a af031f80 a99d7ed4 a99d7e20 8062c508 8062add4
[  207.278643] 7e20: ad37f000 00000026 00000000 00000026 a99d6000 a9a91240 a99d7e5c b92ce6f0
[  207.286824] 7e40: 006c1108 80168264 5e0f24c0 00000000 00000000 af384e40 a99d7e8c a99d7e68
[  207.295005] 7e60: 8082ac3c 808234f8 00000007 af384e40 af384e40 00000000 00008103 00000000
[  207.303185] 7e80: 00000001 00021050 00004000 00000000 00000000 00000000 00000000 00000000
[  207.311366] 7ea0: 006bfec8 cb577e12 8019a7d4 80d04d48 006c1108 b92ce6f0 b7e49780 00000009
[  207.319547] 7ec0: a99d6000 00000036 a99d7f6c a99d7ed8 802bfa98 8062bc58 af384e40 802fead4
[  207.327728] 7ee0: 00000001 af384e40 a99d7fa4 a99d7ef8 802fead4 802aca90 00000000 00000000
[  207.335908] 7f00: 00000000 00000026 00000001 00000000 00000000 00000001 00000000 00000000
[  207.344090] 7f20: 00000000 a99d7f30 b7e496c0 802cbd6c 006c1108 006c1108 00000000 cb577e12
[  207.352270] 7f40: a99d7f5c b7e49781 006c1108 b7e49780 802c550a 00000009 a99d6000 00000036
[  207.360452] 7f60: a99d7f94 a99d7f70 802c0224 802bf9e8 006c42f8 006c1108 006bfec8 00000000
[  207.368633] 7f80: 00000036 801011c4 a99d7fa4 a99d7f98 802c0264 802c01ec 00000000 a99d7fa8
[  207.376814] 7fa0: 80101000 802c0258 006c1108 006bfec8 00000009 802c550a 006c1108 006c42f8
[  207.384994] 7fc0: 006c1108 006bfec8 00000000 00000036 00000002 00000001 00000001 00000000
[  207.393175] 7fe0: 76eab0b4 7ea2d5b4 76e92608 76e0851c 60000010 00000009 00000000 00000000
[  207.401374] [<80294ea0>] (__kmalloc) from [<80657540>] (__DWC_ALLOC_ATOMIC+0x24/0x28)
[  207.409217] [<80657540>] (__DWC_ALLOC_ATOMIC) from [<806514e4>] (dwc_otg_hcd_qtd_create+0x2c/0x60)
[  207.418185] [<806514e4>] (dwc_otg_hcd_qtd_create) from [<8064a5d4>] (dwc_otg_hcd_urb_enqueue+0x58/0x204)
[  207.427676] [<8064a5d4>] (dwc_otg_hcd_urb_enqueue) from [<8064c3c0>] (dwc_otg_urb_enqueue+0x1dc/0x384)
[  207.436992] [<8064c3c0>] (dwc_otg_urb_enqueue) from [<8061d860>] (usb_hcd_submit_urb+0xd8/0x988)
[  207.445784] [<8061d860>] (usb_hcd_submit_urb) from [<8061f444>] (usb_submit_urb+0x2b8/0x4f4)
[  207.454228] [<8061f444>] (usb_submit_urb) from [<8062bc24>] (proc_do_submiturb+0xe5c/0xe84)
[  207.462585] [<8062bc24>] (proc_do_submiturb) from [<8062c508>] (usbdev_ioctl+0x8bc/0x1acc)
[  207.470856] [<8062c508>] (usbdev_ioctl) from [<802bfa98>] (do_vfs_ioctl+0xbc/0x804)
[  207.478522] [<802bfa98>] (do_vfs_ioctl) from [<802c0224>] (ksys_ioctl+0x44/0x6c)
[  207.485926] [<802c0224>] (ksys_ioctl) from [<802c0264>] (sys_ioctl+0x18/0x1c)
[  207.493069] [<802c0264>] (sys_ioctl) from [<80101000>] (ret_fast_syscall+0x0/0x28)
[  207.500636] Exception stack(0xa99d7fa8 to 0xa99d7ff0)
[  207.505691] 7fa0:                   006c1108 006bfec8 00000009 802c550a 006c1108 006c42f8
[  207.513872] 7fc0: 006c1108 006bfec8 00000000 00000036 00000002 00000001 00000001 00000000
[  207.522050] 7fe0: 76eab0b4 7ea2d5b4 76e92608 76e0851c
[  207.527107] Code: e7914002 e3540000 0a000067 e5973014 (e7943003)
[  207.533203] ---[ end trace 9f415fbd16d0a534 ]---

Someone's trampling freed memory, I would guess.

localuser2 commented 4 years ago

So it is a kernel bug? Do you have enough information or do I have to provide something else?

P33M commented 4 years ago

Can you provide your GPIO uart crash logs so I can confirm I have hit the same bug?

localuser2 commented 4 years ago

Here it is (crash, dmesg, btc):

[   57.463534] Unable to handle kernel paging request at virtual address fb0070b1
[   57.471709] pgd = 06b30de9
[   57.475317] [fb0070b1] *pgd=00000000
[   57.479785] Internal error: Oops: 5 [#1] SMP ARM
[   58.484380] KGDB: Timed out waiting for secondary CPUs.

Entering kdb (current=0xb1598f00, pid 844) on processor 1 Oops: (null)
due to oops @ 0x80294ea0
CPU: 1 PID: 844 Comm: usb-crash Tainted: G         C        4.19.75-v7+ #1270
Hardware name: BCM2835
PC is at __kmalloc+0xac/0x288
LR is at __kmalloc+0x60/0x288
pc : [<80294ea0>]    lr : [<80294e54>]    psr: a0000093
sp : b165bbb0  ip : b165bbb0  fp : b165bbf4
r10: b9c01e40  r9 : 80657540  r8 : 00488020
r7 : b9c01e40  r6 : 0000002c  r5 : b788d500  r4 : fb0070b1
r3 : 00000000  r2 : 80c97a60  r1 : 396ce000  r0 : b165bbb0
Flags: NzCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 10c5383d  Table: 3165c06a  DAC: 00000055
CPU: 1 PID: 844 Comm: usb-crash Tainted: G         C        4.19.75-v7+ #1270
Hardware name: BCM2835
[<80111fcc>] (unwind_backtrace) from [<8010d544>] (show_stack+0x20/0x24)
[<8010d544>] (show_stack) from [<80819bc0>] (dump_stack+0xd4/0x118)
[<80819bc0>] (dump_stack) from [<80109d34>] (show_regs+0x1c/0x20)
[<80109d34>] (show_regs) from [<801da678>] (kdb_main_loop+0x3ec/0x828)
[<801da678>] (kdb_main_loop) from [<801dd6ec>] (kdb_stub+0x240/0x480)
[<801dd6ec>] (kdb_stub) from [<801d2ab8>] (kgdb_cpu_enter+0x4b4/0x868)
[<801d2ab8>] (kgdb_cpu_enter) from [<801d30f0>] (kgdb_handle_exception+0x12c/0x244)
more> 
[<801d30f0>] (kgdb_handle_exception) from [<801114e4>] (kgdb_notify+0x40/0x90)
[<801114e4>] (kgdb_notify) from [<80144078>] (notifier_call_chain+0x54/0x94)
[<80144078>] (notifier_call_chain) from [<801442a0>] (notify_die+0x58/0x78)
[<801442a0>] (notify_die) from [<8010d660>] (die+0x118/0x35c)
[<8010d660>] (die) from [<801168e4>] (__do_kernel_fault.part.0+0x74/0x84)
[<801168e4>] (__do_kernel_fault.part.0) from [<80116684>] (do_sect_fault+0x0/0x20)
[<80116684>] (do_sect_fault) from [<80837900>] (do_translation_fault+0x7c/0xc0)
[<80837900>] (do_translation_fault) from [<801166fc>] (do_DataAbort+0x58/0xf4)
[<801166fc>] (do_DataAbort) from [<80101934>] (__dabt_svc+0x54/0x80)
Exception stack(0xb165bb60 to 0xb165bba8)
bb60: b165bbb0 396ce000 80c97a60 00000000 fb0070b1 b788d500 0000002c b9c01e40
bb80: 00488020 80657540 b9c01e40 b165bbf4 b165bbb0 b165bbb0 80294e54 80294ea0
bba0: a0000093 ffffffff
[<80101934>] (__dabt_svc) from [<80294ea0>] (__kmalloc+0xac/0x288)
[<80294ea0>] (__kmalloc) from [<80657540>] (__DWC_ALLOC_ATOMIC+0x24/0x28)
[<80657540>] (__DWC_ALLOC_ATOMIC) from [<806514e4>] (dwc_otg_hcd_qtd_create+0x2c/0x60)
[<806514e4>] (dwc_otg_hcd_qtd_create) from [<8064a5d4>] (dwc_otg_hcd_urb_enqueue+0x58/0x204)
[<8064a5d4>] (dwc_otg_hcd_urb_enqueue) from [<8064c3c0>] (dwc_otg_urb_enqueue+0x1dc/0x384)
[<8064c3c0>] (dwc_otg_urb_enqueue) from [<8061d860>] (usb_hcd_submit_urb+0xd8/0x988)
more> 
[<8061d860>] (usb_hcd_submit_urb) from [<8061f444>] (usb_submit_urb+0x2b8/0x4f4)
[<8061f444>] (usb_submit_urb) from [<8062bc24>] (proc_do_submiturb+0xe5c/0xe84)
[<8062bc24>] (proc_do_submiturb) from [<8062c508>] (usbdev_ioctl+0x8bc/0x1acc)
[<8062c508>] (usbdev_ioctl) from [<802bfa98>] (do_vfs_ioctl+0xbc/0x804)
[<802bfa98>] (do_vfs_ioctl) from [<802c0224>] (ksys_ioctl+0x44/0x6c)
[<802c0224>] (ksys_ioctl) from [<802c0264>] (sys_ioctl+0x18/0x1c)
[<802c0264>] (sys_ioctl) from [<80101000>] (ret_fast_syscall+0x0/0x28)
Exception stack(0xb165bfa8 to 0xb165bff0)
bfa0:                   018c44c8 018c4440 00000009 802c550a 018c44c8 018d86a8
bfc0: 018c44c8 018c4440 00000000 00000036 00000002 00000001 00000001 00000000
bfe0: 76f270b4 7eebf5b4 76f0e608 76e8451c

[1]kdb> 

[1]kdb> 
[1]kdb> 
[1]kdb> dmesg
<6>[    0.000000] Booting Linux on physical CPU 0x0
<5>[    0.000000] Linux version 4.19.75-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1270 SMP Tue Sep 24 18:45:11 BST 2019
<6>[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
<6>[    0.000000] CPU: div instructions available: patching division code
<6>[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
<6>[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
<6>[    0.000000] Memory policy: Data cache writealloc
<6>[    0.000000] cma: Reserved 8 MiB at 0x3ac00000
<7>[    0.000000] On node 0 totalpages: 242688
<7>[    0.000000]   Normal zone: 2133 pages used for memmap
<7>[    0.000000]   Normal zone: 0 pages reserved
<7>[    0.000000]   Normal zone: 242688 pages, LIFO batch:63
<5>[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0
<6>[    0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632
<7>[    0.000000] pcpu-alloc: s39488 r8192 d21952 u69632 alloc=17*4096
<7>[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
<6>[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
more> 

<6>[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
<6>[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
<6>[    0.000000] Memory: 939088K/970752K available (8192K kernel code, 629K rwdata, 2176K rodata, 1024K init, 821K bss, 23472K reserved, 8192K cma-reserved)
<5>[    0.000000] Virtual kernel memory layout:
<5>[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
<5>[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
<6>[    0.000000] ftrace: allocating 26399 entries in 78 pages
<6>[    0.000000] rcu: Hierarchical RCU implementation.
<6>[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
<6>[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
<6>[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
<6>[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
<6>[    0.000023] Switching to timer-based delay loop, resolution 52ns
<6>[    0.000292] Console: colour dummy device 80x30
<6>[    0.000912] console [tty1] enabled
<6>[    0.000974] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
more> 
<6>[    0.001020] pid_max: default: 32768 minimum: 301
<6>[    0.001377] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
<6>[    0.001412] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
<6>[    0.002346] CPU: Testing write buffer coherency: ok
<6>[    0.002829] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
<6>[    0.003502] Setting up static identity map for 0x100000 - 0x10003c
<6>[    0.003669] rcu: Hierarchical SRCU implementation.
<6>[    0.004482] smp: Bringing up secondary CPUs ...
<6>[    0.005344] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
<6>[    0.006276] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
<6>[    0.007143] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
<6>[    0.007264] smp: Brought up 1 node, 4 CPUs
<6>[    0.007345] SMP: Total of 4 processors activated (153.60 BogoMIPS).
<6>[    0.007369] CPU: All CPU(s) started in HYP mode.
<6>[    0.007389] CPU: Virtualization extensions available.
<6>[    0.008384] devtmpfs: initialized
<6>[    0.021512] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
<6>[    0.021782] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
<6>[    0.021830] futex hash table entries: 1024 (order: 4, 65536 bytes)
<6>[    0.022450] pinctrl core: initialized pinctrl subsystem
more> 
<6>[    0.023322] NET: Registered protocol family 16
<6>[    0.026264] DMA: preallocated 1024 KiB pool for atomic coherent allocations
<6>[    0.031910] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
<6>[    0.031946] hw-breakpoint: maximum watchpoint size is 8 bytes.
<6>[    0.032170] Serial: AMBA PL011 UART driver
<6>[    0.034490] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
<6>[    0.069059] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
<5>[    0.070992] SCSI subsystem initialized
<6>[    0.071234] usbcore: registered new interface driver usbfs
<6>[    0.071315] usbcore: registered new interface driver hub
<6>[    0.071429] usbcore: registered new device driver usb
<6>[    0.090302] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-09-24 17:37, variant start
<6>[    0.100130] raspberrypi-firmware soc:firmware: Firmware hash is 6820edeee4ef3891b95fc01cf02a7abd7ca52f17
<6>[    0.111779] clocksource: Switched to clocksource arch_sys_counter
<5>[    0.201346] VFS: Disk quotas dquot_6.6.0
<6>[    0.201457] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
<5>[    0.201635] FS-Cache: Loaded
more> 
<6>[    0.201893] CacheFiles: Loaded
<6>[    0.211923] NET: Registered protocol family 2
<6>[    0.212710] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
<6>[    0.212775] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
<6>[    0.212907] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
<6>[    0.213112] TCP: Hash tables configured (established 8192 bind 8192)
<6>[    0.213272] UDP hash table entries: 512 (order: 2, 16384 bytes)
<6>[    0.213339] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
<6>[    0.213670] NET: Registered protocol family 1
<6>[    0.214248] RPC: Registered named UNIX socket transport module.
<6>[    0.214275] RPC: Registered udp transport module.
<6>[    0.214298] RPC: Registered tcp transport module.
<6>[    0.214319] RPC: Registered tcp NFSv4.1 backchannel transport module.
<6>[    0.216008] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
<5>[    0.219032] Initialise system trusted keyrings
<6>[    0.219240] workingset: timestamp_bits=14 max_order=18 bucket_order=4
<5>[    0.229070] FS-Cache: Netfs 'nfs' registered for caching
<5>[    0.229667] NFS: Registering the id_resolver key type
<5>[    0.229716] Key type id_resolver registered
<5>[    0.229738] Key type id_legacy registered
more> 
<6>[    0.229770] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
<5>[    0.232107] Key type asymmetric registered
<5>[    0.232137] Asymmetric key parser 'x509' registered
<6>[    0.232205] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
<6>[    0.232388] io scheduler noop registered
<6>[    0.232413] io scheduler deadline registered (default)
<6>[    0.232603] io scheduler cfq registered
<6>[    0.232627] io scheduler mq-deadline registered (default)
<6>[    0.232651] io scheduler kyber registered
<6>[    0.234852] bcm2708_fb soc:fb: FB found 1 display(s)
<6>[    0.244301] Console: switching to colour frame buffer device 82x26
<6>[    0.251120] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
<6>[    0.256847] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
<6>[    0.260678] bcm2835-rng 3f104000.rng: hwrng registered
<6>[    0.263405] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
<6>[    0.268753] vc-sm: Videocore shared memory driver
<6>[    0.271558] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
<6>[    0.287529] brd: module loaded
<6>[    0.300187] loop: module loaded
more> 
<6>[    0.303354] Loading iSCSI transport class v2.0-870.
<6>[    0.306491] libphy: Fixed MDIO Bus: probed
<6>[    0.308996] usbcore: registered new interface driver lan78xx
<6>[    0.311515] usbcore: registered new interface driver smsc95xx
<6>[    0.313998] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
<6>[    0.344307] dwc_otg 3f980000.usb: base=(ptrval)
<4>[    0.547031] Core Release: 2.80a
<4>[    0.549489] Setting default values for core params
<4>[    0.552019] Finished setting default values for core params
<4>[    0.754795] Using Buffer DMA mode
<4>[    0.757200] Periodic Transfer Interrupt Enhancement - disabled
<4>[    0.759615] Multiprocessor Interrupt Enhancement - disabled
<4>[    0.762022] OTG VER PARAM: 0, OTG VER FLAG: 0
<4>[    0.764376] Dedicated Tx FIFOs mode
<4>[    0.767083] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = bad14000 dma = 0xfad14000 len=9024
<4>[    0.771668] FIQ FSM acceleration enabled for :
<4>[    0.771668] Non-periodic Split Transactions
<4>[    0.771668] Periodic Split Transactions
<4>[    0.771668] High-Speed Isochronous Endpoints
<7>[    0.782592] dwc_otg: Microframe scheduler enabled
<4>[    0.782653] WARN::hcd_init_fiq:457: FIQ on core 1
<4>[    0.784886] WARN::hcd_init_fiq:458: FIQ ASM at 80655664 length 36
more> 
<4>[    0.787101] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
<6>[    0.789362] dwc_otg 3f980000.usb: DWC OTG Controller
<6>[    0.791626] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
<6>[    0.793971] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
<4>[    0.796278] Init: Port Power? op_state=1
<4>[    0.798518] Init: Power Port (0)
<6>[    0.800933] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
<6>[    0.805476] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
<6>[    0.807894] usb usb1: Product: DWC OTG Controller
<6>[    0.810262] usb usb1: Manufacturer: Linux 4.19.75-v7+ dwc_otg_hcd
<6>[    0.812710] usb usb1: SerialNumber: 3f980000.usb
<6>[    0.815659] hub 1-0:1.0: USB hub found
<6>[    0.817934] hub 1-0:1.0: 1 port detected
<7>[    0.820699] dwc_otg: FIQ enabled
<7>[    0.820705] dwc_otg: NAK holdoff enabled
<7>[    0.820711] dwc_otg: FIQ split-transaction FSM enabled
<7>[    0.820722] Module dwc_common_port init
<6>[    0.821018] usbcore: registered new interface driver usb-storage
<6>[    0.823508] mousedev: PS/2 mouse device common for all mice
<6>[    0.826675] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
more> 
<6>[    0.829303] bcm2835-cpufreq: min=600000 max=1400000
<6>[    0.832153] sdhci: Secure Digital Host Controller Interface driver
<6>[    0.834566] sdhci: Copyright(c) Pierre Ossman
<6>[    0.837335] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
<6>[    0.840244] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
<6>[    0.842949] sdhci-pltfm: SDHCI platform and OF driver helper
<6>[    0.847058] ledtrig-cpu: registered to indicate activity on CPUs
<6>[    0.849791] hidraw: raw HID events driver (C) Jiri Kosina
<6>[    0.852591] usbcore: registered new interface driver usbhid
<6>[    0.855223] usbhid: USB HID core driver
<6>[    0.858522] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
<6>[    0.862677] [vc_sm_connected_init]: start
<6>[    0.871484] [vc_sm_connected_init]: end - returning 0
<6>[    0.875048] Initializing XFRM netlink socket
<6>[    0.877472] NET: Registered protocol family 17
<5>[    0.879967] Key type dns_resolver registered
<5>[    0.882832] Registering SWP/SWPB emulation handler
<6>[    0.885917] registered taskstats version 1
<5>[    0.888322] Loading compiled-in X.509 certificates
<6>[    0.897852] uart-pl011 3f201000.serial: cts_event_workaround enabled
<6>[    0.900386] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
more> 
<6>[    1.902965] console [ttyAMA0] enabled
<6>[    1.911064] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
<6>[    1.919552] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
<6>[    1.954007] sdhost: log_buf @ (ptrval) (fad13000)
<4>[    1.996043] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
<4>[    2.005465] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
<4>[    2.014771] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
<6>[    2.022452] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
<6>[    2.031376] of_cfs_init
<6>[    2.036027] of_cfs_init: OK
<6>[    2.041369] Waiting for root device PARTUUID=106135ba-02...
<4>[    2.050479] Indeed it is in host mode hprt0 = 00021501
<4>[    2.119645] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
<5>[    2.135510] random: fast init done
<4>[    2.188016] mmc0: host does not support reading read-only switch, assuming write-enable
<6>[    2.206885] mmc0: new high speed SDHC card at address aaaa
<6>[    2.217550] mmc1: new high speed SDIO card at address 0001
<6>[    2.225925] mmcblk0: mmc0:aaaa SC32G 29.7 GiB
<6>[    2.237509]  mmcblk0: p1 p2
<6>[    2.261819] usb 1-1: new high-speed USB device number 2 using dwc_otg
<4>[    2.270539] Indeed it is in host mode hprt0 = 00001101
<6>[    2.276354] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
more> 
<6>[    2.287387] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
<6>[    2.395977] EXT4-fs (mmcblk0p2): orphan cleanup on readonly fs
<6>[    2.404250] EXT4-fs (mmcblk0p2): 1 orphan inode deleted
<6>[    2.411734] EXT4-fs (mmcblk0p2): recovery complete
<6>[    2.429703] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
<6>[    2.442513] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
<6>[    2.461985] devtmpfs: mounted
<6>[    2.472771] Freeing unused kernel memory: 1024K
<6>[    2.480182] Run /sbin/init as init process
<6>[    2.522101] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
<6>[    2.535291] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
<6>[    2.545686] hub 1-1:1.0: USB hub found
<6>[    2.552069] hub 1-1:1.0: 4 ports detected
<6>[    2.871851] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
<6>[    3.002166] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
<6>[    3.015797] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
<6>[    3.026579] hub 1-1.1:1.0: USB hub found
more> 
<6>[    3.033287] hub 1-1.1:1.0: 3 ports detected
<6>[    3.131831] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
<30>[    3.198613] systemd[1]: System time before build time, advancing clock.
<6>[    3.290553] usb 1-1.3: New USB device found, idVendor=0403, idProduct=6001, bcdDevice= 6.00
<6>[    3.304548] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
<6>[    3.314784] usb 1-1.3: Product: FT232R USB UART
<6>[    3.322127] usb 1-1.3: Manufacturer: FTDI
<6>[    3.328938] usb 1-1.3: SerialNumber: AK069117
<6>[    3.340640] NET: Registered protocol family 10
<6>[    3.349151] Segment Routing with IPv6

<30>[    3.430142] systemd[1]: Detected architecture arm.
<30>[    3.473395] systemd[1]: Set hostname to <smartnir>.
<28>[    3.485163] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument
<6>[    3.656475] uart-pl011 3f201000.serial: no DMA platform data
<6>[    3.781833] usb 1-1.1.1: new high-speed USB device number 5 using dwc_otg
<28>[    3.909923] systemd[1]: File /lib/systemd/system/systemd-journald.service:12 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
<6>[    3.913662] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
more> 
<28>[    3.935356] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.)
<6>[    3.949319] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
<6>[    4.246952] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
<6>[    4.264135] libphy: lan78xx-mdiobus: probed
<5>[    4.299973] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
<5>[    4.567073] random: systemd: uninitialized urandom read (16 bytes read)
<5>[    4.588576] random: systemd: uninitialized urandom read (16 bytes read)
<30>[    4.599204] systemd[1]: Listening on fsck to fsckd communication Socket.
<5>[    4.613542] random: systemd: uninitialized urandom read (16 bytes read)
<30>[    4.623761] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
<30>[    4.642282] systemd[1]: Listening on Syslog Socket.
<30>[    4.659311] systemd[1]: Created slice system-serial\x2dgetty.slice.
<6>[    5.409949] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
<46>[    5.511955] systemd-journald[112]: Received request to flush runtime journal from PID 1
<4>[    6.179118] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
<6>[    6.182868] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
more> 
<6>[    6.182885] [vc_sm_connected_init]: start
<6>[    6.184916] [vc_sm_connected_init]: installed successfully
<6>[    6.191665] media: Linux media interface: v0.10
<6>[    6.235529] videodev: Linux video capture interface: v2.00
<4>[    6.344138] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    6.344997] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    6.388443] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    6.394996] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    6.400282] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
<6>[    6.425264] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
<6>[    6.425303] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
<6>[    6.428908] bcm2835_audio soc:audio: card created with 8 channels
<6>[    6.431592] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
<6>[    6.431628] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
<6>[    6.445055] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
<6>[    6.445107] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
<5>[    6.512673] cfg80211: Loading compiled-in X.509 certificates for regulatory database
more> 
<6>[    6.585432] usbcore: registered new interface driver usbserial_generic
<6>[    6.585510] usbserial: USB Serial support registered for generic
<6>[    6.608563] usbcore: registered new interface driver ftdi_sio
<6>[    6.608642] usbserial: USB Serial support registered for FTDI USB Serial Device
<6>[    6.608934] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
<6>[    6.609088] usb 1-1.3: Detected FT232RL
<5>[    6.617604] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
<6>[    6.622515] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
<7>[    6.702264] brcmfmac: F1 signature read @0x18000000=0x15264345
<3>[    6.715390] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
<6>[    6.716286] usbcore: registered new interface driver brcmfmac
<3>[    6.980523] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
<3>[    6.993679] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
<5>[    7.027156] random: crng init done
<5>[    7.027174] random: 7 urandom warning(s) missed due to ratelimiting
<6>[    8.518699] 8021q: 802.1Q VLAN Support v1.8
<6>[    8.883852] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
more> 
<6>[    8.899718] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
<6>[    8.899727] brcmfmac: power management disabled
<6>[    9.197763] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
<6>[    9.197781] 8021q: adding VLAN 0 to HW filter on device eth0
<6>[    9.212745] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
<6>[   41.777138] KGDB: Registered I/O driver kgdboc
<6>[   52.070027] usbserial: USB Serial deregistering driver FTDI USB Serial Device
<6>[   52.070447] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
<6>[   52.070535] usbcore: deregistering interface driver ftdi_sio
<6>[   52.070690] ftdi_sio 1-1.3:1.0: device disconnected
<1>[   57.463534] Unable to handle kernel paging request at virtual address fb0070b1
<1>[   57.471709] pgd = 06b30de9
<1>[   57.475317] [fb0070b1] *pgd=00000000
<0>[   57.479785] Internal error: Oops: 5 [#1] SMP ARM
<2>[   58.484380] KGDB: Timed out waiting for secondary CPUs.
[1]kdb> 
[1]kdb> 
[1]kdb> 
[1]kdb> btc
btc: cpu status: Currently on cpu 1
Available cpus: 0(D), 1, 2(I), 3
WARNING: no task for cpu 0
Stack traceback for pid 844
0xb1598f00      844      839  1    1   R  0xb1599d58 *usb-crash
[<80111fcc>] (unwind_backtrace) from [<8010d544>] (show_stack+0x20/0x24)
[<8010d544>] (show_stack) from [<801dc510>] (kdb_show_stack+0x54/0x68)
[<801dc510>] (kdb_show_stack) from [<801dc5e0>] (kdb_bt1.constprop.0+0xbc/0x104)
[<801dc5e0>] (kdb_bt1.constprop.0) from [<801dc7f0>] (kdb_bt+0x1c8/0x444)
[<801dc7f0>] (kdb_bt) from [<801d9cb8>] (kdb_parse+0x3f0/0x6e4)
[<801d9cb8>] (kdb_parse) from [<801dc890>] (kdb_bt+0x268/0x444)
[<801dc890>] (kdb_bt) from [<801d9cb8>] (kdb_parse+0x3f0/0x6e4)
[<801d9cb8>] (kdb_parse) from [<801da834>] (kdb_main_loop+0x5a8/0x828)
[<801da834>] (kdb_main_loop) from [<801dd6ec>] (kdb_stub+0x240/0x480)
[<801dd6ec>] (kdb_stub) from [<801d2ab8>] (kgdb_cpu_enter+0x4b4/0x868)
[<801d2ab8>] (kgdb_cpu_enter) from [<801d30f0>] (kgdb_handle_exception+0x12c/0x244)
[<801d30f0>] (kgdb_handle_exception) from [<801114e4>] (kgdb_notify+0x40/0x90)
[<801114e4>] (kgdb_notify) from [<80144078>] (notifier_call_chain+0x54/0x94)
[<80144078>] (notifier_call_chain) from [<801442a0>] (notify_die+0x58/0x78)
[<801442a0>] (notify_die) from [<8010d660>] (die+0x118/0x35c)
[<8010d660>] (die) from [<801168e4>] (__do_kernel_fault.part.0+0x74/0x84)
more> 
[<801168e4>] (__do_kernel_fault.part.0) from [<80116684>] (do_sect_fault+0x0/0x20)
[<80116684>] (do_sect_fault) from [<80837900>] (do_translation_fault+0x7c/0xc0)
[<80837900>] (do_translation_fault) from [<801166fc>] (do_DataAbort+0x58/0xf4)
[<801166fc>] (do_DataAbort) from [<80101934>] (__dabt_svc+0x54/0x80)
Exception stack(0xb165bb60 to 0xb165bba8)
bb60: b165bbb0 396ce000 80c97a60 00000000 fb0070b1 b788d500 0000002c b9c01e40
bb80: 00488020 80657540 b9c01e40 b165bbf4 b165bbb0 b165bbb0 80294e54 80294ea0
bba0: a0000093 ffffffff
[<80101934>] (__dabt_svc) from [<80294ea0>] (__kmalloc+0xac/0x288)
[<80294ea0>] (__kmalloc) from [<80657540>] (__DWC_ALLOC_ATOMIC+0x24/0x28)
[<80657540>] (__DWC_ALLOC_ATOMIC) from [<806514e4>] (dwc_otg_hcd_qtd_create+0x2c/0x60)
[<806514e4>] (dwc_otg_hcd_qtd_create) from [<8064a5d4>] (dwc_otg_hcd_urb_enqueue+0x58/0x204)
[<8064a5d4>] (dwc_otg_hcd_urb_enqueue) from [<8064c3c0>] (dwc_otg_urb_enqueue+0x1dc/0x384)
[<8064c3c0>] (dwc_otg_urb_enqueue) from [<8061d860>] (usb_hcd_submit_urb+0xd8/0x988)
[<8061d860>] (usb_hcd_submit_urb) from [<8061f444>] (usb_submit_urb+0x2b8/0x4f4)
[<8061f444>] (usb_submit_urb) from [<8062bc24>] (proc_do_submiturb+0xe5c/0xe84)
[<8062bc24>] (proc_do_submiturb) from [<8062c508>] (usbdev_ioctl+0x8bc/0x1acc)
[<8062c508>] (usbdev_ioctl) from [<802bfa98>] (do_vfs_ioctl+0xbc/0x804)
more> 
[<802bfa98>] (do_vfs_ioctl) from [<802c0224>] (ksys_ioctl+0x44/0x6c)
[<802c0224>] (ksys_ioctl) from [<802c0264>] (sys_ioctl+0x18/0x1c)
[<802c0264>] (sys_ioctl) from [<80101000>] (ret_fast_syscall+0x0/0x28)
Exception stack(0xb165bfa8 to 0xb165bff0)
bfa0:                   018c44c8 018c4440 00000009 802c550a 018c44c8 018d86a8
bfc0: 018c44c8 018c4440 00000000 00000036 00000002 00000001 00000001 00000000
bfe0: 76f270b4 7eebf5b4 76f0e608 76e8451c
Stack traceback for pid 0
0xb9d44b00        0        0  1    2   I  0xb9d45958  swapper/2
Stack traceback for pid 112
0xb8dc6900      112        1  1    3   R  0xb8dc7758  systemd-journal
[<80831314>] (__schedule) from [<801de6a4>] (seccomp_run_filters+0x70/0x16c)
[1]kdb>

P33M commented 4 years ago

In your wireshark traces, what are the URB buffer sizes? I've added debug to dwc_otg and I only ever see 16kib transfer buffer sizes in the URBs that are given to the HCD.

P33M commented 4 years ago

Findings so far:

Slub debugging (redzone+poison) doesn't turn up anything, but since we're usually crashing in kmalloc that doesn't tell us much
The dereferenced faulting "address" is always present in a captured USB bitstream, so read data from the device is getting written either off the end of a buffer or to a bogus buffer address
I've not yet narrowed down why we're getting the trim warning, all the crashes I've had since I moved printks around haven't had a trim warning.
For the crash to occur, "some number of" full-size packets (64 bytes) need to be transferred in a single URB. If I tune the data rate such that you always get short packets, the crash doesn't occur.

What's weird about ftdi devices is that they have a variable data aggregation window, set by the driver, and is dependent on baud rate. This means that the device will rate-limit its returned bulk updates (presumably to reduce IO processing load) so this is why only certain baud rates trigger the crash. What remains to be explained is why only certain sets of returned buffer lengths cause issues - I can transfer thousands of URBs without a crash if we are always returning filled URBs.

localuser2 commented 4 years ago

This is how a transfer of two bytes (reading) looks like with my Raspi 3B+ (stopping after one iteration):

Bildschirmfoto von 2020-01-03 16-49-00

which is odd, because there are two transfers host->device and two more device->host. So to transfer 2 bytes almost 20kbytes go over the line.

While I was debugging the crashes with our USB devices I found this strange behavior. Here are two more examples to clarify. Please note that this is another USB controller than in the DIGITUS converters.

Here four bytes are transferred on a Linux PC (amd64, Debian 10) with a transfer buffer size of 20kbyte:

Bildschirmfoto von 2020-01-03 16-45-55

Here is the same transfer with the same buffer size device on my Raspi 3B+:

Bildschirmfoto von 2020-01-03 16-55-47

On AMD64 only slightly more than 100 bytes go over the line. On Raspi 3B+ its 20k. It is the same on Raspi 4 but without the crashes.

It looks like the 20k buffer is transferred in two fragments whether there are enough data available or not. However, even with an 16kib+1 buffer two fragments go over the line (this is also true for smaller buffers)...

P33M commented 4 years ago

usbmon traces capture both the submit() action and the complete() action. So each wire transfer has two points in the trace - the point at which the device driver requests a transfer, and one where the results of the transfer are returned to the driver.

Requesting a transfer with a buffer of 1 byte from an endpoint that returns 64 byte packets is clearly nonsense - in the first instance we should work out why libusb does this on ARM platforms.

In the majority of cases it looks like dwc_otg is completing the urb with the 1-byte allocation with a zero-byte return length, which I suspect is why I didn't get crashes.

localuser2 commented 4 years ago

But the Raspi traces show four points instead of two.

I do not think libusb is the problem here. As far as I know it is completely platform independent. All abstractions should be done behind the device paths /dev/bus/usb or /proc/bus/usb, right? At least I found no #ifdef ...arm... or something like this. Besides, a userland library should never be able to crash the operating system.

P33M commented 4 years ago

On Pi, something is deciding to split the 16385 byte libusb transfer (as requested by the application) into a 16k transfer buffer and a 1-byte transfer buffer. Similarly for the 20k transfer, you get a 16k transfer and a 4k transfer buffer.

Whoever's splitting this transfer is not aware of the endpoint maxpacket size, which is a bug - you're giving an inadequately sized buffer to a DMA-capable device. I need to check to see if xhci-hcd outright rejects transfers like these, or if you're just "always lucky" with the Pi 4 controller.

localuser2 commented 4 years ago

On the Raspi it seems to be always two transfers in every direction. Even if the buffer is distinctively smaller than 16k. I tried with 4k. No crashes but four points in the Wireshark trace.

If I understand your last post right, is it possible that the problem also occurs with AMD64 platform if the buffer and the actual data length is greater than 16k? In contrast to the Pi, the URB size seems to be correlated with the actually transmitted data length here.

By the way: I also tried the USB-C interface (OTG) on the Raspi 4. It should be USB 2.0 (EHCI), right? No crashes.

P33M commented 4 years ago

If I run the same test on a Pi 4 (xhci controller) and use a 16385 byte transfer, the transfer always completes with an error:

[216983.911031] usb 1-1.3: userurb ba804927, ep1 bulk-in, length 16385
[216984.114002] usb 1-1.3: urb complete
[216984.114013] usb 1-1.3: userurb ba804927, ep1 bulk-in, actual_length 16384 status -75

But, the submission was with a buffer size of 16385 bytes instead of 16k/1.

If I use a transfer size that's not a multiple of 64 and if an "overrun" condition occurs, the driver always returns -75 (EOVERFLOW -> device babble error). The URB is never split, even if I request a ridiculous buffer size like 1MiB+1.

I would say from a controller driver standpoint that a babble error is the correct response in this situation - USB bulk transfers don't require max packet sized transfers, and some upper protocol could want to transfer e.g. 16385 bytes exactly.

So, what's splitting the dwc_otg transfer into two URBs, and in the case where we could write off the end of a buffer (transfer space remaining < wMaxPacketSize) we should guard this by detecting a babble error if the device returns more data than we have buffer space.

Edit: the default driver used on the usb-c interface is dwc2, not dwc-otg. Can you confirm that this was the case when you ran the test?

localuser2 commented 4 years ago

I can confirm that dwc2 is loaded on my Raspi 4. A module with name dwc-otg seems not to be existent. If dwc2 is unloaded, the USB hardware on USB-C port is not accessible anymore (lsusb).

P33M commented 4 years ago

In the dwc2 case I see the same behaviour as dwc_otg - 16384 + 1 byte split URBs, plus multiple occurences of the message

[  455.395114] dwc2 3f980000.usb: dwc2_update_urb_state(): trimming xfer length

Which does an equivalent length munging operation to the one seen in dwc_otg.

P33M commented 4 years ago

There's a bug in both dwc_otg and dwc2. In an IN split transaction, the host channel is set up for the max packet size of the endpoint because multiple individual host channel operations are required to do a split transaction. This unconditional overwrite has the side-effect of ignoring the remaining space in the URB's buffer for bulk, interrupt and control transfers (isoc is treated as an array of maxpacket-sized transfers).

https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/usb/dwc2/hcd.c#L1466 https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/usb/host/dwc_otg/dwc_otg_hcd.c#L1861

For dwc2 and dwc_otg, the transfer length is correctly calculated (or at least constrained) at host channel init time. https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/usb/dwc2/hcd.c#L2842 https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/usb/host/dwc_otg/dwc_otg_hcd.c#L1254

P33M commented 4 years ago

For the other half of the unexplained behaviour - neither version of the dwc driver supports scatter-gather (sg_tablesize = 0). This means the flag USBDEVFS_CAP_BULK_SCATTER_GATHER isn't set when querying ioctl(..., USBDEVFS_GET_CAPABILITIES, ...), so libusb is submitting URBs split on a 16k boundary. 16k is a historical "limit" for the maximum size of a single user-initiated USB bulk transfer.

The reason that I saw the second 1-byte URB being returned with 0 bytes transferred is because it's marked as a "continuation" URB by usbfs, so when a short transfer is received on the first URB, the second URB is automatically unlinked before returning the results to userspace.

I have a tentative fix (which results in dwc_otg having the same error behaviour as xhci if the buffer gets overrun) but it's a bit hacky. The OTG core requires the transfer length register to be an integer multiple of the maximum packet size for the endpoint or you end up with a bogus length register on transfer completion, so I have to mangle both the transfer length and endpoint maxpacket fields in order to generate a device babble error.

localuser2 commented 4 years ago

So a buffer size of 32KiB would have been (accidentally) okay?

P33M commented 4 years ago

Any buffer that did not have a length modulo 64 bytes could potentially corrupt memory, but I suspect you only stomped on something important if more than 32 bytes was received from the device in the last transfer of a sequence of bulk transfers (packet > cacheline width).

I'm now running your test continuously, looping over libusb bulk request sizes from 16385 to 16449 bytes in length. I have the UARTs set to different baud rates so the mismatch of framing and bit position will be interpreted as random numbers of bytes on each read. It's not crashed yet with the fix applied...

localuser2 commented 4 years ago

Sounds good. However, I am pretty sure, the problem was fairly reproducible with the first transfer of 4 bytes (actual length) in our setup. If you have a fix, I can try if the problem is gone. It would be nice if you could provide a deb package containing the fixed kernel though...

pelwell commented 4 years ago

That's a big ask - once the kernel has been tested sufficiently here it will get pushed to the firmware repo and made available via rpi-update. A package release will be weeks or months later.

localuser2 commented 4 years ago

I guess, rpi-update is fine too. I was not aware rpi-update is not using deb packages for updates. I'm just trying to avoid compiling the kernel myself.

JamesH65 commented 4 years ago

@localuser2 Takes less than 2hrs usually to download, change, and rebuild a kernel on Pi4. https://www.raspberrypi.org/documentation/linux/kernel/building.md

localuser2 commented 4 years ago

I can try...

P33M commented 4 years ago

Can you build and test the kernel from this branch?

https://github.com/P33M/linux/tree/dwc-buffer-bounds-check

localuser2 commented 4 years ago

okay.

localuser2 commented 4 years ago

Bad news: I can still crash it.

To be sure, there was no mistake on my side, here is what I did:

$ git clone --depth=1 --branch=dwc-buffer-bounds-check https://github.com/P33M/linux.git
$ cd linux
$ KERNEL=kernel7
$ make bcm2711_defconfig
$ make -j4 zImage modules dtbs
$ sudo make modules_install
$ sudo cp arch/arm/boot/dts/*.dtb /boot/
$ sudo cp arch/arm/boot/dts/overlays/*.dtb* /boot/overlays/
$ sudo cp arch/arm/boot/dts/overlays/README /boot/overlays/
$ sudo cp arch/arm/boot/zImage /boot/$KERNEL.img
$ sudo reboot
$ uname -a
Linux smartnir 4.19.93-v7l+ #1 SMP Tue Jan 7 15:23:07 CET 2020 armv7l GNU/Linux

Then I run usb-crash several times which did not crash the Pi. So there is definitely progress.

However, as mentioned before, there is another scenario where only four bytes of actual data are transmitted which lead to crashes. It is the initiation of communication of our USB devices (NIR spectrometers) with the device driver:

one byte is transmitted to the device
four bytes are read from the device (two status bytes and the the protocol version of the device)

I wrote a minimal example to isolate the issue which just reads the protocol version end exits. With 16KiB buffer no problem. With 20k buffer the system crashes after a couple of iterations.

I will provide a crash log.

localuser2 commented 4 years ago

Here it is (please note that the test program is a Mono assembly, so the process' name is mono, it crashed at second iteration):

[  102.786161] Unable to handle kernel paging request at virtual address f7eb6031
[  102.793889] pgd = f45f1b53
[  102.797062] [f7eb6031] *pgd=80000000007003, *pmd=00000000
[  102.802953] Internal error: Oops: 206 [#1] SMP ARM

Entering kdb (current=0xec63ad00, pid 873) on processor 0 Oops: (null)
due to oops @ 0xc03be950
CPU: 0 PID: 873 Comm: mono Tainted: G         C        4.19.93-v7l+ #1
Hardware name: BCM2835
PC is at __kmalloc+0xa8/0x290
LR is at 0x112b
pc : [<c03be950>]    lr : [<0000112b>]    psr: a0000013
sp : ec469d60  ip : ec469d60  fp : ec469d9c
r10: 00000000  r9 : c0799fb4  r8 : ef001900
r7 : 00000e20  r6 : 006000c0  r5 : ef001900  r4 : f7eb6031
r3 : 00000000  r2 : c0e9e020  r1 : 2e8bd000  r0 : 00000000
Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 30c5383d  Table: 2cdab7c0  DAC: fffffffd
CPU: 0 PID: 873 Comm: mono Tainted: G         C        4.19.93-v7l+ #1
Hardware name: BCM2835
[<c0212d54>] (unwind_backtrace) from [<c020d368>] (show_stack+0x20/0x24)
[<c020d368>] (show_stack) from [<c09ada34>] (dump_stack+0xd8/0x11c)
[<c09ada34>] (dump_stack) from [<c0209d74>] (show_regs+0x1c/0x20)
[<c0209d74>] (show_regs) from [<c02defb4>] (kdb_main_loop+0x3a4/0x7c4)
[<c02defb4>] (kdb_main_loop) from [<c02e1fa8>] (kdb_stub+0x268/0x478)
[<c02e1fa8>] (kdb_stub) from [<c02d7618>] (kgdb_cpu_enter+0x470/0x7d0)
[<c02d7618>] (kgdb_cpu_enter) from [<c02d7bb0>] (kgdb_handle_exception+0xe8/0x22c)
more> 
[<c02d7bb0>] (kgdb_handle_exception) from [<c021229c>] (kgdb_notify+0x40/0x8c)
[<c021229c>] (kgdb_notify) from [<c0246000>] (notifier_call_chain+0x58/0x94)
[<c0246000>] (notifier_call_chain) from [<c02462a8>] (notify_die+0x58/0x78)
[<c02462a8>] (notify_die) from [<c020d4f0>] (die+0x184/0x374)
[<c020d4f0>] (die) from [<c02172dc>] (__do_kernel_fault.part.0+0x74/0x84)
[<c02172dc>] (__do_kernel_fault.part.0) from [<c0217378>] (do_DataAbort+0x0/0xe8)
[<c0217378>] (do_DataAbort) from [<c09ca420>] (do_translation_fault+0xd4/0x10c)
[<c09ca420>] (do_translation_fault) from [<c02173c8>] (do_DataAbort+0x50/0xe8)
[<c02173c8>] (do_DataAbort) from [<c0201934>] (__dabt_svc+0x54/0x80)
Exception stack(0xec469d10 to 0xec469d58)
9d00:                                     00000000 2e8bd000 c0e9e020 00000000
9d20: f7eb6031 ef001900 006000c0 00000e20 ef001900 c0799fb4 00000000 ec469d9c
9d40: ec469d60 ec469d60 0000112b c03be950 a0000013 ffffffff
[<c0201934>] (__dabt_svc) from [<c03be950>] (__kmalloc+0xa8/0x290)
[<c03be950>] (__kmalloc) from [<c0799fb4>] (proc_do_submiturb+0xd7c/0xea4)
[<c0799fb4>] (proc_do_submiturb) from [<c079b2b4>] (usbdev_ioctl+0x11d8/0x1b64)
[<c079b2b4>] (usbdev_ioctl) from [<c03ea298>] (do_vfs_ioctl+0xc0/0x7d4)
[<c03ea298>] (do_vfs_ioctl) from [<c03ea9f0>] (ksys_ioctl+0x44/0x70)
[<c03ea9f0>] (ksys_ioctl) from [<c03eaa34>] (sys_ioctl+0x18/0x1c)
[<c03eaa34>] (sys_ioctl) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
Exception stack(0xec469fa8 to 0xec469ff0)
9fa0:                   024b1214 024c7490 00000009 802c550a 024b1214 024600e0
more> 
9fc0: 024b1214 024c7490 00000001 00000036 00000002 00000001 00000001 00004000
9fe0: b43aa0b4 be83fc3c b4391608 b6c3751c

[0]kdb> 

[0]kdb> 
[0]kdb> 
[0]kdb> dmesg
<6>[    0.000000] Booting Linux on physical CPU 0x0
<5>[    0.000000] Linux version 4.19.93-v7l+ (pi@smartnir) (gcc version 8.3.0 (Raspbian 8.3.0-6+rpi1)) #1 SMP Tue Jan 7 15:23:07 CET 2020
<6>[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=30c5383d
<6>[    0.000000] CPU: div instructions available: patching division code
<6>[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
<6>[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
<6>[    0.000000] Memory policy: Data cache writealloc
<6>[    0.000000] cma: Reserved 8 MiB at 0x000000003ac00000
<7>[    0.000000] On node 0 totalpages: 242688
<7>[    0.000000]   DMA zone: 1728 pages used for memmap
<7>[    0.000000]   DMA zone: 0 pages reserved
<7>[    0.000000]   DMA zone: 196608 pages, LIFO batch:63
<7>[    0.000000]   HighMem zone: 46080 pages, LIFO batch:15
<5>[    0.000000] random: get_random_bytes called from start_kernel+0xc0/0x4e0 with crng_init=0
<6>[    0.000000] percpu: Embedded 16 pages/cpu s36748 r8192 d20596 u65536
<7>[    0.000000] pcpu-alloc: s36748 r8192 d20596 u65536 alloc=16*4096
<7>[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
<6>[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240960
more> 

<6>[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
<6>[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
<6>[    0.000000] Memory: 936976K/970752K available (8192K kernel code, 688K rwdata, 2408K rodata, 2048K init, 848K bss, 25584K reserved, 8192K cma-reserved, 176128K highmem)
<5>[    0.000000] Virtual kernel memory layout:
<5>[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
<5>[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
<6>[    0.000000] ftrace: allocating 28618 entries in 84 pages
<6>[    0.000000] rcu: Hierarchical RCU implementation.
<6>[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
<6>[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
<6>[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
<6>[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
<6>[    0.000022] Switching to timer-based delay loop, resolution 52ns
<6>[    0.000271] Console: colour dummy device 80x30
<6>[    0.000936] console [tty1] enabled
<6>[    0.001004] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
more> 
<6>[    0.001048] pid_max: default: 32768 minimum: 301
<6>[    0.001401] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
<6>[    0.001437] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
<6>[    0.002427] CPU: Testing write buffer coherency: ok
<6>[    0.002906] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
<6>[    0.003574] Setting up static identity map for 0x200000 - 0x20003c
<6>[    0.003746] rcu: Hierarchical SRCU implementation.
<6>[    0.004573] smp: Bringing up secondary CPUs ...
<6>[    0.005447] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
<6>[    0.006397] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
<6>[    0.007269] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
<6>[    0.007395] smp: Brought up 1 node, 4 CPUs
<6>[    0.007480] SMP: Total of 4 processors activated (153.60 BogoMIPS).
<6>[    0.007505] CPU: All CPU(s) started in HYP mode.
<6>[    0.007526] CPU: Virtualization extensions available.
<6>[    0.008525] devtmpfs: initialized
<6>[    0.021480] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
<6>[    0.021750] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
<6>[    0.021800] futex hash table entries: 1024 (order: 4, 65536 bytes)
<6>[    0.022432] pinctrl core: initialized pinctrl subsystem
more> 
<6>[    0.023316] NET: Registered protocol family 16
<6>[    0.026005] DMA: preallocated 1024 KiB pool for atomic coherent allocations
<6>[    0.031674] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
<6>[    0.031711] hw-breakpoint: maximum watchpoint size is 8 bytes.
<6>[    0.031919] Serial: AMBA PL011 UART driver
<6>[    0.034215] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
<6>[    0.068485] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
<6>[    0.069971] vgaarb: loaded
<5>[    0.070472] SCSI subsystem initialized
<6>[    0.070725] usbcore: registered new interface driver usbfs
<6>[    0.070801] usbcore: registered new interface driver hub
<6>[    0.070915] usbcore: registered new device driver usb
<6>[    0.090117] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-09-24 17:37, variant start
<6>[    0.100361] raspberrypi-firmware soc:firmware: Firmware hash is 6820edeee4ef3891b95fc01cf02a7abd7ca52f17
<6>[    0.111773] clocksource: Switched to clocksource arch_sys_counter
<5>[    0.208309] VFS: Disk quotas dquot_6.6.0
<6>[    0.208430] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
more> 
<5>[    0.208603] FS-Cache: Loaded
<6>[    0.208831] CacheFiles: Loaded
<6>[    0.218887] NET: Registered protocol family 2
<6>[    0.219761] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
<6>[    0.219827] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
<6>[    0.219958] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
<6>[    0.220163] TCP: Hash tables configured (established 8192 bind 8192)
<6>[    0.220326] UDP hash table entries: 512 (order: 2, 16384 bytes)
<6>[    0.220393] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
<6>[    0.220663] NET: Registered protocol family 1
<6>[    0.221266] RPC: Registered named UNIX socket transport module.
<6>[    0.221294] RPC: Registered udp transport module.
<6>[    0.221316] RPC: Registered tcp transport module.
<6>[    0.221338] RPC: Registered tcp NFSv4.1 backchannel transport module.
<7>[    0.221369] PCI: CLS 0 bytes, default 64
<6>[    0.223098] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
<5>[    0.226181] Initialise system trusted keyrings
<6>[    0.226382] workingset: timestamp_bits=14 max_order=18 bucket_order=4
<5>[    0.237383] FS-Cache: Netfs 'nfs' registered for caching
<5>[    0.237984] NFS: Registering the id_resolver key type
more> 
<5>[    0.238029] Key type id_resolver registered
<5>[    0.238051] Key type id_legacy registered
<6>[    0.238083] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
<5>[    0.240379] Key type asymmetric registered
<5>[    0.240410] Asymmetric key parser 'x509' registered
<6>[    0.240521] bounce: pool size: 64 pages
<6>[    0.240579] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
<6>[    0.240754] io scheduler noop registered
<6>[    0.240779] io scheduler deadline registered (default)
<6>[    0.240979] io scheduler cfq registered
<6>[    0.241003] io scheduler mq-deadline registered (default)
<6>[    0.241027] io scheduler kyber registered
<6>[    0.243386] bcm2708_fb soc:fb: FB found 1 display(s)
<6>[    0.248779] Console: switching to colour frame buffer device 82x26
<6>[    0.252534] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
<6>[    0.256598] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
<6>[    0.259325] bcm2835-rng 3f104000.rng: hwrng registered
<6>[    0.260878] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
<6>[    0.263909] vc-sm: Videocore shared memory driver
<6>[    0.265550] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
more> 
<6>[    0.278933] brd: module loaded
<6>[    0.290185] loop: module loaded
<6>[    0.292291] Loading iSCSI transport class v2.0-870.
<6>[    0.295467] libphy: Fixed MDIO Bus: probed
<6>[    0.296991] usbcore: registered new interface driver r8152
<6>[    0.298322] usbcore: registered new interface driver lan78xx
<6>[    0.299626] usbcore: registered new interface driver smsc95xx
<6>[    0.301183] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
<6>[    0.330300] dwc_otg 3f980000.usb: base=(ptrval)
<4>[    0.531809] Core Release: 2.80a
<4>[    0.533050] Setting default values for core params
<4>[    0.534301] Finished setting default values for core params
<4>[    0.735828] Using Buffer DMA mode
<4>[    0.737008] Periodic Transfer Interrupt Enhancement - disabled
<4>[    0.738198] Multiprocessor Interrupt Enhancement - disabled
<4>[    0.739378] OTG VER PARAM: 0, OTG VER FLAG: 0
<4>[    0.740531] Dedicated Tx FIFOs mode
<4>[    0.742041] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = f0a60000 dma = 0x00000000fad14000 len=9024
<4>[    0.744330] FIQ FSM acceleration enabled for :
<4>[    0.744330] Non-periodic Split Transactions
<4>[    0.744330] Periodic Split Transactions
<4>[    0.744330] High-Speed Isochronous Endpoints
more> 
<7>[    0.749795] dwc_otg: Microframe scheduler enabled
<4>[    0.749856] WARN::hcd_init_fiq:457: FIQ on core 1
<4>[    0.750978] WARN::hcd_init_fiq:458: FIQ ASM at c07e19b8 length 36
<4>[    0.752130] WARN::hcd_init_fiq:497: MPHI regs_base at f0810000
<6>[    0.753319] dwc_otg 3f980000.usb: DWC OTG Controller
<6>[    0.754503] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
<6>[    0.755719] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
<4>[    0.756935] Init: Port Power? op_state=1
<4>[    0.758096] Init: Power Port (0)
<6>[    0.759462] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
<6>[    0.761814] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
<6>[    0.763068] usb usb1: Product: DWC OTG Controller
<6>[    0.764297] usb usb1: Manufacturer: Linux 4.19.93-v7l+ dwc_otg_hcd
<6>[    0.765553] usb usb1: SerialNumber: 3f980000.usb
<6>[    0.767369] hub 1-0:1.0: USB hub found
<6>[    0.768571] hub 1-0:1.0: 1 port detected
<7>[    0.770338] dwc_otg: FIQ enabled
<7>[    0.770344] dwc_otg: NAK holdoff enabled
<7>[    0.770349] dwc_otg: FIQ split-transaction FSM enabled
<7>[    0.770360] Module dwc_common_port init
more> 
<6>[    0.770559] usbcore: registered new interface driver uas
<6>[    0.771854] usbcore: registered new interface driver usb-storage
<6>[    0.773220] mousedev: PS/2 mouse device common for all mice
<6>[    0.775353] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
<4>[    0.777365] cpufreq: cpufreq_online: CPU0: Running at unlisted freq: 600000 KHz
<4>[    0.780849] cpufreq: cpufreq_online: CPU0: Unlisted initial frequency changed to: 700000 KHz
<6>[    0.782980] sdhci: Secure Digital Host Controller Interface driver
<6>[    0.783537] sdhci: Copyright(c) Pierre Ossman
<6>[    0.784280] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
<6>[    0.785027] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
<6>[    0.785653] sdhci-pltfm: SDHCI platform and OF driver helper
<6>[    0.787608] ledtrig-cpu: registered to indicate activity on CPUs
<6>[    0.788262] hidraw: raw HID events driver (C) Jiri Kosina
<6>[    0.788904] usbcore: registered new interface driver usbhid
<6>[    0.789454] usbhid: USB HID core driver
<6>[    0.790376] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
<6>[    0.791940] [vc_sm_connected_init]: start
<6>[    0.798807] [vc_sm_connected_init]: end - returning 0
<6>[    0.799897] Initializing XFRM netlink socket
<6>[    0.800466] NET: Registered protocol family 17
more> 
<5>[    0.801074] Key type dns_resolver registered
<5>[    0.801859] Registering SWP/SWPB emulation handler
<6>[    0.802724] registered taskstats version 1
<5>[    0.803276] Loading compiled-in X.509 certificates
<6>[    0.807146] uart-pl011 3f201000.serial: cts_event_workaround enabled
<6>[    0.807758] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
<6>[    1.951799] console [ttyAMA0] enabled
<6>[    1.956634] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
<6>[    1.964879] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
<6>[    1.971420] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
<6>[    2.003296] sdhost: log_buf @ (ptrval) (fad13000)
<4>[    2.045441] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
<4>[    2.052945] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
<6>[    2.058953] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
<6>[    2.065853] of_cfs_init
<6>[    2.068836] of_cfs_init: OK
<6>[    2.072431] Waiting for root device PARTUUID=106135ba-02...
<4>[    2.085285] Indeed it is in host mode hprt0 = 00021501
<4>[    2.151519] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
<4>[    2.160206] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
<5>[    2.169692] random: fast init done
more> 
<4>[    2.225123] mmc0: host does not support reading read-only switch, assuming write-enable
<6>[    2.236956] mmc1: new high speed SDIO card at address 0001
<6>[    2.243872] mmc0: new high speed SDHC card at address aaaa
<6>[    2.250565] mmcblk0: mmc0:aaaa SC32G 29.7 GiB
<6>[    2.259899]  mmcblk0: p1 p2
<6>[    2.283479] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
<6>[    2.291796] usb 1-1: new high-speed USB device number 2 using dwc_otg
<6>[    2.292601] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
<4>[    2.299588] Indeed it is in host mode hprt0 = 00001101
<6>[    2.316331] devtmpfs: mounted
<6>[    2.374054] Freeing unused kernel memory: 2048K
<6>[    2.401956] Run /sbin/init as init process
<6>[    2.551954] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
<6>[    2.561265] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
<6>[    2.569384] hub 1-1:1.0: USB hub found
<6>[    2.573787] hub 1-1:1.0: 4 ports detected
<6>[    2.891808] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
<6>[    3.021927] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
more> 
<6>[    3.031485] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
<6>[    3.039745] hub 1-1.1:1.0: USB hub found
<6>[    3.044350] hub 1-1.1:1.0: 3 ports detected
<30>[    3.075060] systemd[1]: System time before build time, advancing clock.
<6>[    3.141789] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
<6>[    3.195545] NET: Registered protocol family 10
<6>[    3.201294] Segment Routing with IPv6

<30>[    3.264267] systemd[1]: Detected architecture arm.
<30>[    3.291954] systemd[1]: Set hostname to <smartnir>.
<28>[    3.298838] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument
<6>[    3.299364] usb 1-1.3: New USB device found, idVendor=0403, idProduct=6001, bcdDevice= 6.00
<6>[    3.316301] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
<6>[    3.316306] usb 1-1.3: Product: FT232R USB UART
<6>[    3.329391] usb 1-1.3: Manufacturer: FTDI
<6>[    3.329394] usb 1-1.3: SerialNumber: AK06RXXK
<6>[    3.405243] uart-pl011 3f201000.serial: no DMA platform data
<6>[    3.811800] usb 1-1.1.1: new high-speed USB device number 5 using dwc_otg
<5>[    3.925292] random: systemd: uninitialized urandom read (16 bytes read)
more> 
<5>[    3.937933] random: systemd: uninitialized urandom read (16 bytes read)
<6>[    3.942153] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
<30>[    3.945606] systemd[1]: Listening on udev Control Socket.
<6>[    3.954844] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
<5>[    3.970390] random: systemd: uninitialized urandom read (16 bytes read)
<30>[    3.977712] systemd[1]: Reached target Swap.
<30>[    3.983965] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
<30>[    4.005242] systemd[1]: Created slice system-getty.slice.
<30>[    4.036402] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
<30>[    4.046705] systemd[1]: Created slice system-systemd\x2dfsck.slice.
<6>[    4.242467] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
<6>[    4.254612] libphy: lan78xx-mdiobus: probed
<5>[    4.272654] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
<6>[    4.517005] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
<46>[    4.569324] systemd-journald[106]: Received request to flush runtime journal from PID 1
<4>[    5.062337] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
more> 
<6>[    5.064542] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
<6>[    5.064553] [vc_sm_connected_init]: start
<6>[    5.068969] media: Linux media interface: v0.10
<6>[    5.070967] [vc_sm_connected_init]: installed successfully
<6>[    5.127118] videodev: Linux video capture interface: v2.00
<4>[    5.201899] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
<6>[    5.205133] bcm2835_audio soc:audio: card created with 8 channels
<4>[    5.215896] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    5.216523] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    5.238970] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
<4>[    5.252526] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
<6>[    5.262181] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
<6>[    5.262204] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
<6>[    5.273407] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
<6>[    5.273435] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
<6>[    5.279358] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
<6>[    5.279377] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
<6>[    5.315154] usbcore: registered new interface driver usbserial_generic
more> 
<6>[    5.315198] usbserial: USB Serial support registered for generic
<5>[    5.335249] cfg80211: Loading compiled-in X.509 certificates for regulatory database
<6>[    5.336937] usbcore: registered new interface driver ftdi_sio
<6>[    5.336979] usbserial: USB Serial support registered for FTDI USB Serial Device
<6>[    5.337117] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
<6>[    5.337189] usb 1-1.3: Detected FT232RL
<6>[    5.353547] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
<5>[    5.428097] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
<7>[    5.489214] brcmfmac: F1 signature read @0x18000000=0x15264345
<3>[    5.503027] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
<6>[    5.503520] usbcore: registered new interface driver brcmfmac
<5>[    5.712278] random: crng init done
<5>[    5.712285] random: 7 urandom warning(s) missed due to ratelimiting
<3>[    5.735332] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
<3>[    5.750635] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
<6>[    6.668488] 8021q: 802.1Q VLAN Support v1.8
<6>[    6.782847] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
more> 
<6>[    6.872544] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
<3>[    6.872717] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
<6>[    7.172230] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
<6>[    7.172239] 8021q: adding VLAN 0 to HW filter on device eth0
<6>[    8.198258] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
<6>[   42.038136] KGDB: Registered I/O driver kgdboc
<6>[   90.346009] usb 1-1.3: USB disconnect, device number 4
<6>[   90.346350] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
<6>[   90.346394] ftdi_sio 1-1.3:1.0: device disconnected
<6>[   94.485001] usb 1-1.3: new full-speed USB device number 6 using dwc_otg
<6>[   94.646484] usb 1-1.3: New USB device found, idVendor=0403, idProduct=9c70, bcdDevice= 4.00
<6>[   94.646490] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
<6>[   94.646494] usb 1-1.3: Product: Microspectrometer V4.2
<6>[   94.646498] usb 1-1.3: Manufacturer: HiperScan
<6>[   94.646502] usb 1-1.3: SerialNumber: W1811074
<1>[  102.786161] Unable to handle kernel paging request at virtual address f7eb6031
<1>[  102.793889] pgd = f45f1b53
<1>[  102.797062] [f7eb6031] *pgd=80000000007003, *pmd=00000000
<0>[  102.802953] Internal error: Oops: 206 [#1] SMP ARM
more> 
[0]kdb> 
[0]kdb> 
[0]kdb> 
[0]kdb> btc
btc: cpu status: Currently on cpu 0
Available cpus: 0-1, 2(I), 3
Stack traceback for pid 873
0xec63ad00      873      820  1    0   R  0xec63bb58 *mono
[<c0212d54>] (unwind_backtrace) from [<c020d368>] (show_stack+0x20/0x24)
[<c020d368>] (show_stack) from [<c02e0dd0>] (kdb_show_stack+0x54/0x68)
[<c02e0dd0>] (kdb_show_stack) from [<c02e0ea0>] (kdb_bt1.constprop.0+0xbc/0x104)
[<c02e0ea0>] (kdb_bt1.constprop.0) from [<c02e10b0>] (kdb_bt+0x1c8/0x44c)
[<c02e10b0>] (kdb_bt) from [<c02de6c0>] (kdb_parse+0x444/0x6cc)
[<c02de6c0>] (kdb_parse) from [<c02e116c>] (kdb_bt+0x284/0x44c)
[<c02e116c>] (kdb_bt) from [<c02de6c0>] (kdb_parse+0x444/0x6cc)
[<c02de6c0>] (kdb_parse) from [<c02df1ec>] (kdb_main_loop+0x5dc/0x7c4)
[<c02df1ec>] (kdb_main_loop) from [<c02e1fa8>] (kdb_stub+0x268/0x478)
[<c02e1fa8>] (kdb_stub) from [<c02d7618>] (kgdb_cpu_enter+0x470/0x7d0)
[<c02d7618>] (kgdb_cpu_enter) from [<c02d7bb0>] (kgdb_handle_exception+0xe8/0x22c)
[<c02d7bb0>] (kgdb_handle_exception) from [<c021229c>] (kgdb_notify+0x40/0x8c)
[<c021229c>] (kgdb_notify) from [<c0246000>] (notifier_call_chain+0x58/0x94)
[<c0246000>] (notifier_call_chain) from [<c02462a8>] (notify_die+0x58/0x78)
[<c02462a8>] (notify_die) from [<c020d4f0>] (die+0x184/0x374)
[<c020d4f0>] (die) from [<c02172dc>] (__do_kernel_fault.part.0+0x74/0x84)
[<c02172dc>] (__do_kernel_fault.part.0) from [<c0217378>] (do_DataAbort+0x0/0xe8)
more> 
[<c0217378>] (do_DataAbort) from [<c09ca420>] (do_translation_fault+0xd4/0x10c)
[<c09ca420>] (do_translation_fault) from [<c02173c8>] (do_DataAbort+0x50/0xe8)
[<c02173c8>] (do_DataAbort) from [<c0201934>] (__dabt_svc+0x54/0x80)
Exception stack(0xec469d10 to 0xec469d58)
9d00:                                     00000000 2e8bd000 c0e9e020 00000000
9d20: f7eb6031 ef001900 006000c0 00000e20 ef001900 c0799fb4 00000000 ec469d9c
9d40: ec469d60 ec469d60 0000112b c03be950 a0000013 ffffffff
[<c0201934>] (__dabt_svc) from [<c03be950>] (__kmalloc+0xa8/0x290)
[<c03be950>] (__kmalloc) from [<c0799fb4>] (proc_do_submiturb+0xd7c/0xea4)
[<c0799fb4>] (proc_do_submiturb) from [<c079b2b4>] (usbdev_ioctl+0x11d8/0x1b64)
[<c079b2b4>] (usbdev_ioctl) from [<c03ea298>] (do_vfs_ioctl+0xc0/0x7d4)
[<c03ea298>] (do_vfs_ioctl) from [<c03ea9f0>] (ksys_ioctl+0x44/0x70)
[<c03ea9f0>] (ksys_ioctl) from [<c03eaa34>] (sys_ioctl+0x18/0x1c)
[<c03eaa34>] (sys_ioctl) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
Exception stack(0xec469fa8 to 0xec469ff0)
9fa0:                   024b1214 024c7490 00000009 802c550a 024b1214 024600e0
9fc0: 024b1214 024c7490 00000001 00000036 00000002 00000001 00000001 00004000
9fe0: b43aa0b4 be83fc3c b4391608 b6c3751c
Stack traceback for pid 336
0xecfa0000      336        1  1    1   R  0xecfa0e58  in:imklog
[<c09c3d38>] (__schedule) from [<c025bd14>] (enqueue_task_fair+0xf30/0x14ec)
[<c025bd14>] (enqueue_task_fair) from [<c02d7d98>] (kgdb_nmicallback+0xa4/0xac)
[<c02d7d98>] (kgdb_nmicallback) from [<c02121e8>] (kgdb_call_nmi_hook+0x38/0x3c)
more> 
[<c02121e8>] (kgdb_call_nmi_hook) from [<c02b5ea4>] (flush_smp_call_function_queue+0xc0/0x194)
[<c02b5ea4>] (flush_smp_call_function_queue) from [<c02b6c70>] (generic_smp_call_function_single_interrupt+0x1c/0x20)
[<c02b6c70>] (generic_smp_call_function_single_interrupt) from [<c02110d0>] (handle_IPI+0x290/0x3a0)
[<c02110d0>] (handle_IPI) from [<c02021e4>] (bcm2836_arm_irqchip_handle_irq+0xa4/0xa8)
[<c02021e4>] (bcm2836_arm_irqchip_handle_irq) from [<c0201d0c>] (__irq_usr+0x4c/0x60)
Exception stack(0xece7ffb0 to 0xece7fff8)
ffa0:                                     b6568d18 0a0a0a0a 20737365 62653766
ffc0: 00000000 00000000 00000000 686f3d6c 00001fa0 b6a57264 00000000 b6a46cc4
ffe0: 01010101 b65684a8 b6a46520 b6c7efb0 60000010 ffffffff
Stack traceback for pid 0
0xef144b00        0        0  1    2   I  0xef145958  swapper/2
Stack traceback for pid 106
0xedfdad00      106        1  1    3   R  0xedfdbb58  systemd-journal
[0]kdb>

P33M commented 4 years ago

Can you do another crash dump, but after doing:

 echo 64 | sudo tee /sys/module/usbcore/parameters/usbfs_snoop_max
 echo 1 | sudo tee /sys/module/usbcore/parameters/usbfs_snoop

This might make the crash less reliable, so if it stops crashing then replace the "64" above with "0". Also, what is the expected 4-byte response from the device?

localuser2 commented 4 years ago

The expected response in this scenario (which it is if it does not crash as well) is 0x31 0x60 0x00 0x10. It is possible that only the two first bytes are transferred if the device is not ready yet. In this case the read operation is multiple times repeated after some time (and at some point a TimeoutException is thrown).

With usbfs_snoop_max=64 and usbfs_snoop=1 I was not able to crash it. However, I see a very strange behavior: The first transfer looks like expected. Then the device does not answer anymore. The status bytes 0x31 0x60 come through, but not the following 0x00 0x10, resulting in a communication timeout. If I unplug and plug-in the USB connector, it is working again. But only one time exactly. So there seems to be some kind of reset necessary.

With usbfs_snoop_max=0 its the same. No crashes, no second transmission.

This is what is written to syslog ( usbfs_snoop_max=0):

First communication after plug-in (response 0x31 0x60 0x00 0x10):

Jan  7 18:12:21 smartnir kernel: [ 2001.328019] usb 1-1.3: opened by process 2073: mono
Jan  7 18:12:21 smartnir kernel: [ 2001.328789] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.328802] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0300 wIndex=0000 wLength=0022
Jan  7 18:12:21 smartnir kernel: [ 2001.328817] usb 1-1.3: userurb 06328580, ep0 ctrl-in, length 34
Jan  7 18:12:21 smartnir kernel: [ 2001.329152] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.329160] usb 1-1.3: userurb 06328580, ep0 ctrl-in, actual_length 4 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.329192] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.329201] usb 1-1.3: reap 06328580
Jan  7 18:12:21 smartnir kernel: [ 2001.329222] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.335811] usb 1-1.3: opened by process 2073: mono
Jan  7 18:12:21 smartnir kernel: [ 2001.335875] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.335886] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0301 wIndex=0000 wLength=00ff
Jan  7 18:12:21 smartnir kernel: [ 2001.335900] usb 1-1.3: userurb 9f7778c7, ep0 ctrl-in, length 255
Jan  7 18:12:21 smartnir kernel: [ 2001.340278] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.340287] usb 1-1.3: userurb 9f7778c7, ep0 ctrl-in, actual_length 20 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.340322] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.340329] usb 1-1.3: reap 9f7778c7
Jan  7 18:12:21 smartnir kernel: [ 2001.340348] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.345466] usb 1-1.3: opened by process 2073: mono
Jan  7 18:12:21 smartnir kernel: [ 2001.345529] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.345540] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0302 wIndex=0000 wLength=00ff
Jan  7 18:12:21 smartnir kernel: [ 2001.345554] usb 1-1.3: userurb 631d5161, ep0 ctrl-in, length 255
Jan  7 18:12:21 smartnir kernel: [ 2001.354026] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.354038] usb 1-1.3: userurb 631d5161, ep0 ctrl-in, actual_length 46 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.354068] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.354076] usb 1-1.3: reap 631d5161
Jan  7 18:12:21 smartnir kernel: [ 2001.354102] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.355000] usb 1-1.3: opened by process 2073: mono
Jan  7 18:12:21 smartnir kernel: [ 2001.355055] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.355065] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0303 wIndex=0000 wLength=00ff
Jan  7 18:12:21 smartnir kernel: [ 2001.355077] usb 1-1.3: userurb 631d5161, ep0 ctrl-in, length 255
Jan  7 18:12:21 smartnir kernel: [ 2001.359401] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.359411] usb 1-1.3: userurb 631d5161, ep0 ctrl-in, actual_length 18 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.359445] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.359456] usb 1-1.3: reap 631d5161
Jan  7 18:12:21 smartnir kernel: [ 2001.359476] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.617578] usb 1-1.3: opened by process 2073: mono
Jan  7 18:12:21 smartnir kernel: [ 2001.619089] usb 1-1.3: usbdev_do_ioctl: CLAIMINTERFACE
Jan  7 18:12:21 smartnir kernel: [ 2001.635309] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.635325] usb 1-1.3: control urb: bRequestType=40 bRequest=00 wValue=0000 wIndex=0000 wLength=0000
Jan  7 18:12:21 smartnir kernel: [ 2001.635339] usb 1-1.3: userurb 4bee00e6, ep0 ctrl-out, length 0
Jan  7 18:12:21 smartnir kernel: [ 2001.635653] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.635662] usb 1-1.3: userurb 4bee00e6, ep0 ctrl-out, actual_length 0 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.635715] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.635723] usb 1-1.3: reap 4bee00e6
Jan  7 18:12:21 smartnir kernel: [ 2001.638284] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.640714] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.640727] usb 1-1.3: control urb: bRequestType=40 bRequest=03 wValue=4138 wIndex=0000 wLength=0000
Jan  7 18:12:21 smartnir kernel: [ 2001.640740] usb 1-1.3: userurb 98f42ef5, ep0 ctrl-out, length 0
Jan  7 18:12:21 smartnir kernel: [ 2001.641026] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.641035] usb 1-1.3: userurb 98f42ef5, ep0 ctrl-out, actual_length 0 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.641084] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.641093] usb 1-1.3: reap 98f42ef5
Jan  7 18:12:21 smartnir kernel: [ 2001.641137] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.660458] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.660483] usb 1-1.3: userurb 8f7222f4, ep2 bulk-out, length 1
Jan  7 18:12:21 smartnir kernel: [ 2001.660671] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.660679] usb 1-1.3: userurb 8f7222f4, ep2 bulk-out, actual_length 1 status 0
Jan  7 18:12:21 smartnir kernel: [ 2001.660747] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.660753] usb 1-1.3: reap 8f7222f4
Jan  7 18:12:21 smartnir kernel: [ 2001.661421] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.706144] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.706174] usb 1-1.3: userurb 6721db79, ep1 bulk-in, length 16384
Jan  7 18:12:21 smartnir kernel: [ 2001.706210] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:12:21 smartnir kernel: [ 2001.706219] usb 1-1.3: userurb 706c1588, ep1 bulk-in, length 3616
Jan  7 18:12:21 smartnir kernel: [ 2001.706408] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.706417] usb 1-1.3: userurb 6721db79, ep1 bulk-in, actual_length 4 status -121
Jan  7 18:12:21 smartnir kernel: [ 2001.706426] usb 1-1.3: urb complete
Jan  7 18:12:21 smartnir kernel: [ 2001.706431] usb 1-1.3: userurb 706c1588, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:12:21 smartnir kernel: [ 2001.706486] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.706495] usb 1-1.3: reap 6721db79
Jan  7 18:12:21 smartnir kernel: [ 2001.706517] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 706c1588
Jan  7 18:12:21 smartnir kernel: [ 2001.706528] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:12:21 smartnir kernel: [ 2001.706540] usb 1-1.3: reap 706c1588
Jan  7 18:12:21 smartnir kernel: [ 2001.706590] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY

Second communication (timeout after 20 unsuccessfully reads):

Jan  7 18:13:24 smartnir kernel: [ 2064.500906] usb 1-1.3: opened by process 2078: mono
Jan  7 18:13:24 smartnir kernel: [ 2064.501694] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.501709] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0300 wIndex=0000 wLength=0022
Jan  7 18:13:24 smartnir kernel: [ 2064.501723] usb 1-1.3: userurb 23f22141, ep0 ctrl-in, length 34
Jan  7 18:13:24 smartnir kernel: [ 2064.502153] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.502160] usb 1-1.3: userurb 23f22141, ep0 ctrl-in, actual_length 4 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.502191] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.502196] usb 1-1.3: reap 23f22141
Jan  7 18:13:24 smartnir kernel: [ 2064.502214] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.508652] usb 1-1.3: opened by process 2078: mono
Jan  7 18:13:24 smartnir kernel: [ 2064.508714] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.508724] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0301 wIndex=0000 wLength=00ff
Jan  7 18:13:24 smartnir kernel: [ 2064.508740] usb 1-1.3: userurb eff49390, ep0 ctrl-in, length 255
Jan  7 18:13:24 smartnir kernel: [ 2064.513233] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.513244] usb 1-1.3: userurb eff49390, ep0 ctrl-in, actual_length 20 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.513274] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.513279] usb 1-1.3: reap eff49390
Jan  7 18:13:24 smartnir kernel: [ 2064.513304] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.518173] usb 1-1.3: opened by process 2078: mono
Jan  7 18:13:24 smartnir kernel: [ 2064.518234] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.518245] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0302 wIndex=0000 wLength=00ff
Jan  7 18:13:24 smartnir kernel: [ 2064.518259] usb 1-1.3: userurb c8ada2f2, ep0 ctrl-in, length 255
Jan  7 18:13:24 smartnir kernel: [ 2064.526776] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.526788] usb 1-1.3: userurb c8ada2f2, ep0 ctrl-in, actual_length 46 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.527159] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.527168] usb 1-1.3: reap c8ada2f2
Jan  7 18:13:24 smartnir kernel: [ 2064.527192] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.528134] usb 1-1.3: opened by process 2078: mono
Jan  7 18:13:24 smartnir kernel: [ 2064.528192] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.528202] usb 1-1.3: control urb: bRequestType=80 bRequest=06 wValue=0303 wIndex=0000 wLength=00ff
Jan  7 18:13:24 smartnir kernel: [ 2064.528216] usb 1-1.3: userurb 9d138833, ep0 ctrl-in, length 255
Jan  7 18:13:24 smartnir kernel: [ 2064.532704] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.532713] usb 1-1.3: userurb 9d138833, ep0 ctrl-in, actual_length 18 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.533196] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.533204] usb 1-1.3: reap 9d138833
Jan  7 18:13:24 smartnir kernel: [ 2064.533229] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.791229] usb 1-1.3: opened by process 2078: mono
Jan  7 18:13:24 smartnir kernel: [ 2064.792819] usb 1-1.3: usbdev_do_ioctl: CLAIMINTERFACE
Jan  7 18:13:24 smartnir kernel: [ 2064.809464] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.809480] usb 1-1.3: control urb: bRequestType=40 bRequest=00 wValue=0000 wIndex=0000 wLength=0000
Jan  7 18:13:24 smartnir kernel: [ 2064.809495] usb 1-1.3: userurb 25095d47, ep0 ctrl-out, length 0
Jan  7 18:13:24 smartnir kernel: [ 2064.809778] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.809786] usb 1-1.3: userurb 25095d47, ep0 ctrl-out, actual_length 0 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.810304] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.810312] usb 1-1.3: reap 25095d47
Jan  7 18:13:24 smartnir kernel: [ 2064.813359] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.815876] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.815889] usb 1-1.3: control urb: bRequestType=40 bRequest=03 wValue=4138 wIndex=0000 wLength=0000
Jan  7 18:13:24 smartnir kernel: [ 2064.815902] usb 1-1.3: userurb 6639812b, ep0 ctrl-out, length 0
Jan  7 18:13:24 smartnir kernel: [ 2064.816152] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.816159] usb 1-1.3: userurb 6639812b, ep0 ctrl-out, actual_length 0 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.816199] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.816204] usb 1-1.3: reap 6639812b
Jan  7 18:13:24 smartnir kernel: [ 2064.816240] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.835316] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.835340] usb 1-1.3: userurb 9a0db89b, ep2 bulk-out, length 1
Jan  7 18:13:24 smartnir kernel: [ 2064.835547] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.835555] usb 1-1.3: userurb 9a0db89b, ep2 bulk-out, actual_length 1 status 0
Jan  7 18:13:24 smartnir kernel: [ 2064.836069] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.836080] usb 1-1.3: reap 9a0db89b
Jan  7 18:13:24 smartnir kernel: [ 2064.836997] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.881426] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.881455] usb 1-1.3: userurb 75b7139e, ep1 bulk-in, length 16384
Jan  7 18:13:24 smartnir kernel: [ 2064.881488] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.881497] usb 1-1.3: userurb f7cf1396, ep1 bulk-in, length 3616
Jan  7 18:13:24 smartnir kernel: [ 2064.881675] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.881682] usb 1-1.3: userurb 75b7139e, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:24 smartnir kernel: [ 2064.881691] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.881696] usb 1-1.3: userurb f7cf1396, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:24 smartnir kernel: [ 2064.881740] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.881747] usb 1-1.3: reap 75b7139e
Jan  7 18:13:24 smartnir kernel: [ 2064.881770] usb 1-1.3: usbdev_do_ioctl: DISCARDURB f7cf1396
Jan  7 18:13:24 smartnir kernel: [ 2064.881776] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.881781] usb 1-1.3: reap f7cf1396
Jan  7 18:13:24 smartnir kernel: [ 2064.881817] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.951899] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.951929] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:24 smartnir kernel: [ 2064.951955] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2064.951963] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:24 smartnir kernel: [ 2064.952035] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.952043] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:24 smartnir kernel: [ 2064.952052] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2064.952057] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:24 smartnir kernel: [ 2064.952665] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.952674] usb 1-1.3: reap 42779ca4
Jan  7 18:13:24 smartnir kernel: [ 2064.952694] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2064.952701] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2064.952706] usb 1-1.3: reap 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2064.952759] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.003187] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.003214] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:24 smartnir kernel: [ 2065.003239] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.003248] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:24 smartnir kernel: [ 2065.003417] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.003424] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:24 smartnir kernel: [ 2065.003433] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.003439] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:24 smartnir kernel: [ 2065.003481] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.003488] usb 1-1.3: reap 42779ca4
Jan  7 18:13:24 smartnir kernel: [ 2065.003506] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.003524] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.003529] usb 1-1.3: reap 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.004287] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.053949] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.053976] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:24 smartnir kernel: [ 2065.054005] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.054013] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:24 smartnir kernel: [ 2065.054166] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.054174] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:24 smartnir kernel: [ 2065.054183] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.054188] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:24 smartnir kernel: [ 2065.054673] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.054680] usb 1-1.3: reap 42779ca4
Jan  7 18:13:24 smartnir kernel: [ 2065.054698] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.054706] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.054711] usb 1-1.3: reap 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.054758] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.105172] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.105197] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:24 smartnir kernel: [ 2065.105220] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.105229] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:24 smartnir kernel: [ 2065.105411] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.105419] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:24 smartnir kernel: [ 2065.105429] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.105434] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:24 smartnir kernel: [ 2065.105963] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.105972] usb 1-1.3: reap 42779ca4
Jan  7 18:13:24 smartnir kernel: [ 2065.105990] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.106000] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.106005] usb 1-1.3: reap 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.106052] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.156462] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.156488] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:24 smartnir kernel: [ 2065.156514] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:24 smartnir kernel: [ 2065.156522] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:24 smartnir kernel: [ 2065.156667] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.156675] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:24 smartnir kernel: [ 2065.156684] usb 1-1.3: urb complete
Jan  7 18:13:24 smartnir kernel: [ 2065.156689] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:24 smartnir kernel: [ 2065.157177] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.157185] usb 1-1.3: reap 42779ca4
Jan  7 18:13:24 smartnir kernel: [ 2065.157204] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.157212] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:24 smartnir kernel: [ 2065.157216] usb 1-1.3: reap 928b44da
Jan  7 18:13:24 smartnir kernel: [ 2065.157264] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.207685] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.207711] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.207735] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.207744] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.207908] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.207915] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.207925] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.207930] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.208436] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.208444] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.208463] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.208470] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.208475] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.208527] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.258922] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.258948] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.258975] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.258983] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.259167] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.259174] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.259183] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.259188] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.259682] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.259689] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.259709] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.259716] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.259720] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.259775] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.310174] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.310200] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.310228] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.310235] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.310418] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.310424] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.310433] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.310439] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.310467] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.310473] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.310487] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.310495] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.310499] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.310541] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.360891] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.360914] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.360932] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.360940] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.361027] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.361035] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.361043] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.361049] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.361603] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.361612] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.361632] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.361640] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.361644] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.361746] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.412120] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.412143] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.412160] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.412169] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.412276] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.412283] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.412291] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.412296] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.412325] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.412330] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.412342] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.412349] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.412353] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.412397] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.462769] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.462793] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.462811] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.462819] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.462904] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.462911] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.462922] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.462927] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.463514] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.463523] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.463542] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.463550] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.463555] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.463613] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.514007] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.514032] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.514060] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.514068] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.514168] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.514176] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.514184] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.514190] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.514733] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.514742] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.514762] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.514770] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.514774] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.514868] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.565244] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.565270] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.565296] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.565304] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.565416] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.565424] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.565434] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.565439] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.565940] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.565949] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.565968] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.565975] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.565979] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.566035] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.616426] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.616454] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.616478] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.616486] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.616661] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.616669] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.616678] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.616684] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.617238] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.617249] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.617268] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.617275] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.617280] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.617378] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.667749] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.667774] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.667800] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.667808] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.667919] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.667926] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.667935] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.667940] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.668480] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.668489] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.668510] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.668518] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.668522] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.668623] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.719010] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.719035] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.719060] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.719067] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.719158] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.719166] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.719175] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.719181] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.719675] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.719685] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.719702] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.719709] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.719714] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.719769] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.770168] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.770190] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.770210] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.770218] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.770284] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.770291] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.770301] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.770307] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.770863] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.770874] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.770893] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.770900] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.770905] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.771002] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.821380] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.821407] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.821436] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.821444] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.821543] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.821550] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.821559] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.821565] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.821594] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.821599] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.821613] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.821621] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.821626] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.821666] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.872014] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.872037] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, length 16384
Jan  7 18:13:25 smartnir kernel: [ 2065.872055] usb 1-1.3: usbdev_do_ioctl: SUBMITURB
Jan  7 18:13:25 smartnir kernel: [ 2065.872063] usb 1-1.3: userurb 928b44da, ep1 bulk-in, length 3616
Jan  7 18:13:25 smartnir kernel: [ 2065.872153] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.872160] usb 1-1.3: userurb 42779ca4, ep1 bulk-in, actual_length 2 status -121
Jan  7 18:13:25 smartnir kernel: [ 2065.872169] usb 1-1.3: urb complete
Jan  7 18:13:25 smartnir kernel: [ 2065.872175] usb 1-1.3: userurb 928b44da, ep1 bulk-in, actual_length 0 status -104
Jan  7 18:13:25 smartnir kernel: [ 2065.872217] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.872222] usb 1-1.3: reap 42779ca4
Jan  7 18:13:25 smartnir kernel: [ 2065.872237] usb 1-1.3: usbdev_do_ioctl: DISCARDURB 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.872247] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY
Jan  7 18:13:25 smartnir kernel: [ 2065.872251] usb 1-1.3: reap 928b44da
Jan  7 18:13:25 smartnir kernel: [ 2065.872297] usb 1-1.3: usbdev_do_ioctl: REAPURBNDELAY

P33M commented 4 years ago

So, aside from the lack of crashing, is the device behaviour different with the debug enabled? I.e. is the response returned from the device on the bulk transfer different?

One thing that stands out is that the lower 2 bytes of your crashing address (dud pointer) are xxxx6031, i.e. byte-swapped 0x31 0x60. If you crash the Pi multiple times, what is the faulting address in each case?

I have a sneaking suspicion that this is a different bug, triggered by the way that usbfs is reaping URBs when trying to clean up after itself.

localuser2 commented 4 years ago

The first (i.e. working) transfer works as expected with the debug enabled. The response is not different.

Regarding to the crashing address: This is indeed interesting and certainly no coincidence.

Here the addresses are for several crashes:

[   86.722894] Unable to handle kernel paging request at virtual address f7eb6031
...
[   60.836620] Unable to handle kernel paging request at virtual address f7eb6031
...
[   40.836554] Unable to handle kernel paging request at virtual address f7eb6031
...
[   44.087212] Unable to handle kernel paging request at virtual address f7eb6031

i.e. it is always the same address.

This test brought something other out though: It crashes always at the second iteration. If I disconnect the USB device after the first transfer and try again it does not crash. Something seems to be in an very inconsistent state after the first transfer which leads to the crash at the second transfer. Please note that the iterations of the test are not run in a loop within a process. The test program opens, claims, writes, reads, unclaims, closes, exits. Iterations are done at the shell level.

Disconcertingly the usbfs seems to have some kind of memory which is reset if the device is unplugged and reconnected.

In this light the former test (usbfs_snoop) seems to be more consistent. The usbfs is broken somehow after the first transfer. The only difference is that it does not crash with an Oops.

P33M commented 4 years ago

Does your device always return bulk data, i.e. never NAKs transfers? My current working theory is that there's a race between freeing the URB's DMA buffer (as usbfs is busy reaping URBs) and an outstanding transfer that returns data.

dwc_otg's unlink function doesn't cancel ongoing DMA (because force-disabling a channel doesn't work), so there's a potential hole if the buffer is freed and re-used before the core finishes whatever it was doing.

localuser2 commented 4 years ago

Yes, the device always returns at least 2 bytes bulk data.

P33M commented 4 years ago

Can you try recompiling the branch (I've pushed another tentative fix)?

localuser2 commented 4 years ago

Now it is not crashing anymore. But it is still only one transfer possible. Then only the two status bytes come through resulting in a timeout.

With 16KiB buffer everything works as expected. While testing with 16k and 20k version of my test program I found another piece of the puzzle:

The timeout (without the current fix i.e. the crash) occurs even if the first transfer is a 16k transfer. Here some possible sequences to clarify:

connect device
16k transfer -> okay
20k transfer -> timeout
16k transfer -> okay ...
connect device
16k transfer -> okay
16k transfer -> okay
20k transfer -> timeout
16k transfer -> okay ...
connect device
20k transfer -> okay
20k transfer -> timeout
16k transfer -> okay

It does not seem to matter what kind of transfer buffer length the first transfer is. The usbfs is always broken afterwards (regarding 20k transfers).

P33M commented 4 years ago

Is there any way you can capture the full-speed bus traffic with an analyzer?

localuser2 commented 4 years ago

We only have a digital oscilloscope. Eventually we could capture the signal levels and send it to you. We do not have an decoder/logic analyzer at hand which is capable of the necessary sample rate.

Would a set of raw data be sufficient? Presumed we can export it in a useful format.

P33M commented 4 years ago

Decoding a raw bitstream is going to be a non-starter. If you have a Saleae Logic Pro (8 or 16 channel) analyzer then it can decode ls/fs USB and export it in a reasonable format

Other than that, without representative hardware, I'm not going to be able to debug much further.

Given that the two changes fix definite memory corruption bugs, I think those should get pushed out for wider testing anyway.

localuser2 commented 4 years ago

We have a Saleae Logic, but not the Pro version. This will not be fast enough.

So I guess this is a dead end then? What restrictions are to be considered to work around the trapdoors? Buffer lengths <= 16KiB? Multiples of 64bytes?

Would es be possible to return an error if a dangerous buffer length is used?

lurch commented 4 years ago

I dunno if it's relevant (maybe it was just a typo?), but I just noticed that in one of your earlier messages you had:

$ KERNEL=kernel7
$ make bcm2711_defconfig

AFAIK this is an invalid combination; as https://www.raspberrypi.org/documentation/linux/kernel/building.md notes, you want to use KERNEL=kernel7; make bcm2709_defconfig on a Pi3 or KERNEL=kernel7l; make bcm2711_defconfig on a Pi4.

pelwell commented 4 years ago

That was probably a cut-and-paste error in compiling the report:

$ uname -a
Linux smartnir 4.19.93-v7l+ #1 SMP Tue Jan 7 15:23:07 CET 2020 armv7l GNU/Linux

The smartnir, #1 and date suggests that this was indeed the result of a local build; had the script been followed with KERNEL=kernel7 then it would not have overwritten the old kernel7l.img. The other explanation would be that kernel7l.img had been deleted from the card, causing the firmware to load kernel7.img as a fallback.

localuser2 commented 4 years ago

Yes. This was a copy-and-paste error. Sorry

Armavica commented 4 years ago

Hello, I have a similar issue with a Raspberry Pi 3B+ that I also use to control a lab device by USB. I use pyusb with a buffer length of 1000. The kernel crashed twice in one week, following an upgrade of the Pi (it never crashed for this reason before). I can give more details as soon as I go back to the lab and reboot the Pi.

Armavica commented 4 years ago

The problem started occurring after a distribution upgrade (updating deb http://raspbian.raspberrypi.org/raspbian/ stretch main contrib non-free rpi to buster). It never happened before. This is the raspinfo of the affected configuration. I changed the buffer size from 1000 to 1024 (multiple of 64), which still resulted in a crash. I then updated the pi with rpi-update and am now running my application to see if it still crashes.

raspberrypi / linux