Crash while capturing with usbmon
Subsystems (2)
While trying to capture some USB traffic, this happened:
8<--- cut here ---
Unable to handle kernel paging request at virtual address ffeff000 pgd = e14505c9 [ffeff000] *pgd=6ffce861, *pte=00000000, *ppte=00000000 Internal error: Oops: 37 [#1] SMP ARM Modules linked in: sd_mod usb_storage scsi_mod ip6t_REJECT nf_reject_ipv6 ipt_REJECT nf_reject_ipv4 xt_tcpudp ip6table_filter ip6_tables xt_conntrack nf_conntrack nf_defrag_ipv6 libcrc32c nf_defrag_ipv4 iptable_filter ip_tables x_tables hci_uart btbcm sun4i_can edt_ft5x06 victron_cerbogx_adc can_dev victron_gxdisp_bl brcmfmac bluetooth ecdh_generic ecc cfg80211 rfkill brcmutil pwm_sun4i sun4i_emac mdio_sun4i evdev pwm_beeper CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.6.0-rc4-next-20200304-venus-1 #1 Hardware name: Allwinner sun7i (A20) Family PC is at memcpy+0x48/0x330 LR is at 0x21564032 pc : [<c069e0a8>] lr : [<21564032>] psr: 20070193
sp : c0b01ba4 ip : a2cb45df fp : ed64b180
r10: c0b04e88 r9 : 00000043 r8 : f5b57f8b
r7 : 393670c0 r6 : 08e2dffb r5 : abb694bc r4 : 44843523 r3 : 907b4c7f r2 : 00000480 r1 : ffeff000 r0 : ed661b00
Flags: nzCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment none
Control: 10c5387d Table: 6f09806a DAC: 00000051 Process swapper/0 (pid: 0, stack limit = 0x0bca7ef1)
Stack: (0xc0b01ba4 to 0xc0b02000)
1ba0: 00001000 00001000 ffefee00 ed4fd080 ed661900 00000700 c050c88c
1bc0: ed4fd080 ed6618c0 00001000 ed4fd200 00001040 c050cd2c 00000000 00000900 1be0: 00070193 00000000 00000000 00000080 00001000 00000000 00001000 00000000 1c00: 5e6004b0 00000000 2ab0f539 0b751234 0b7512c8 10961743 c0b04e88 ed4fd0c0 1c20: ee92996c 00000000 ed4fd200 ee929948 a0070193 00000001 ed4fd200 c050ade4 1c40: ed4fd200 00000000 00000000 00000000 ef026040 ef0266c4 00000001 c050ae1c 1c60: ed4fd200 ee932c00 00000000 c04f6788 ef026040 ef027040 ed4fd200 00000000 1c80: ef026040 c05216f0 ed4fd400 00000000 00000080 ef0266c4 ef026040 c0522624 1ca0: f08f8080 00000203 ed4fd200 00000000 c0b04e88 ef026040 ef027040 00000000 1cc0: 00000004 c0b04e88 c0b01cf8 ef026330 0000005d c051fbd8 ee3ebf00 ee3ebf00 1ce0: ed60f210 c0b38d80 c0b04e88 c0619098 00000000 00000000 00000010 10961743 1d00: ee4b1240 ef026040 000002ee a0070193 c0b01d70 00000022 c0b3ecfa c0880f9c 1d20: c0880f74 c05259b0 ee929780 ef14d468 00000000 c0178ed4 ed41a168 10961743 1d40: 00000000 ef14d400 ee4b1240 c0b04e88 ef14d468 ef14d400 00000001 ef00cc00 1d60: c0b00000 c0b01e4c 2eceb000 c0178fd0 00000000 10961743 ef14d400 ef14d468 1d80: c0b01f18 c0179064 ef14d400 c0b052b4 c0b01f18 c017d448 c0ab0c10 00000000 1da0: c0b01f18 c0178140 c0ab0c10 c017872c c0b052b4 f080200c f0802000 c0b01de0 1dc0: f0803000 c03c8fb4 c05a6014 60070113 ffffffff c0b01e14 ef79c940 c0101acc 1de0: 00000002 00000000 10961743 10961743 ef79c9f0 00000002 00000040 c0ab1940 1e00: ef79c940 0000012a c0b01e4c 2eceb000 00000003 c0b01e30 c05a6000 c05a6014 1e20: 60070113 ffffffff 00000051 bf000000 c0b04e88 ef79c940 c0ab1940 c0b3efcc 1e40: c08d9ff8 c08df484 00000008 c0b01e4c c0b01e4c c0b01e54 c0b01e54 10961743 1e60: c0ab03e8 00000000 00000003 c0b0308c ffffe000 00000100 c0b03080 40000003 1e80: c0b03080 c01022c8 c0b04e88 00000001 ef14dd00 c0aaa340 c0ab0c40 0000000a 1ea0: c087c59c c0aaa2cc 000092f6 c0b03d00 c0701aa0 00200002 00000000 ffffe000 1ec0: 00000000 00000000 00000001 ef00cc00 c0b00000 c0ab03e8 00000000 c0131bfc 1ee0: c0ab0c10 c0178730 c0b052b4 f080200c f0802000 c0b01f18 f0803000 c03c8fb4 1f00: c0108a68 60070013 ffffffff c0b01f4c 00000000 c0101acc 00000000 00129634 1f20: ef79c830 c0119aa0 ffffe000 c0b04ea8 c0b04eec 00000001 00000000 c0b04e88 1f40: c0ab03e8 00000000 c0b04f64 c0b01f68 c0108a64 c0108a68 60070013 ffffffff 1f60: 00000051 00000000 ffffe000 c01576ec 000000d1 c0b43a4c c0b43a00 c0b3ecd3 1f80: 00000000 10961743 effffc40 000000d1 c0b43a4c c0b43a00 c0a3aa3c 00000000 1fa0: c0a3aa3c effffc40 00000000 c01579e8 c0b04e88 c0a00d3c ffffffff ffffffff 1fc0: 00000000 c0a0059c 00000000 c0a3aa3c 10931143 00000000 c0a00330 00000051 1fe0: 10c0387d 100010bb 49ff5000 410fc074 10c5387d 00000000 00000000 00000000 [<c069e0a8>] (memcpy) from [<c050c88c>] (mon_copy_to_buff+0x4c/0x6c) [<c050c88c>] (mon_copy_to_buff) from [<c050cd2c>] (mon_bin_event+0x480/0x7b8) [<c050cd2c>] (mon_bin_event) from [<c050ade4>] (mon_bus_complete+0x50/0x6c) [<c050ade4>] (mon_bus_complete) from [<c050ae1c>] (mon_complete+0x1c/0x34) [<c050ae1c>] (mon_complete) from [<c04f6788>] (__usb_hcd_giveback_urb+0x64/0x10c) [<c04f6788>] (__usb_hcd_giveback_urb) from [<c05216f0>] (musb_giveback+0x44/0x50) [<c05216f0>] (musb_giveback) from [<c0522624>] (musb_advance_schedule+0xb4/0x278) [<c0522624>] (musb_advance_schedule) from [<c051fbd8>] (musb_interrupt+0x128/0xcd4) [<c051fbd8>] (musb_interrupt) from [<c05259b0>] (sunxi_musb_interrupt+0x98/0x120) [<c05259b0>] (sunxi_musb_interrupt) from [<c0178ed4>] (__handle_irq_event_percpu+0x50/0x120) [<c0178ed4>] (__handle_irq_event_percpu) from [<c0178fd0>] (handle_irq_event_percpu+0x2c/0x7c) [<c0178fd0>] (handle_irq_event_percpu) from [<c0179064>] (handle_irq_event+0x44/0x68) [<c0179064>] (handle_irq_event) from [<c017d448>] (handle_fasteoi_irq+0xa8/0x18c) [<c017d448>] (handle_fasteoi_irq) from [<c0178140>] (generic_handle_irq+0x24/0x34) [<c0178140>] (generic_handle_irq) from [<c017872c>] (__handle_domain_irq+0x5c/0xb4) [<c017872c>] (__handle_domain_irq) from [<c03c8fb4>] (gic_handle_irq+0x3c/0x78) [<c03c8fb4>] (gic_handle_irq) from [<c0101acc>] (__irq_svc+0x6c/0x90)
Exception stack(0xc0b01de0 to 0xc0b01e28)
1de0: 00000002 00000000 10961743 10961743 ef79c9f0 00000002 00000040 c0ab1940 1e00: ef79c940 0000012a c0b01e4c 2eceb000 00000003 c0b01e30 c05a6000 c05a6014 1e20: 60070113 ffffffff
[<c0101acc>] (__irq_svc) from [<c05a6014>] (net_rx_action+0x228/0x38c) [<c05a6014>] (net_rx_action) from [<c01022c8>] (__do_softirq+0x120/0x2b0) [<c01022c8>] (__do_softirq) from [<c0131bfc>] (irq_exit+0xcc/0xd8) [<c0131bfc>] (irq_exit) from [<c0178730>] (__handle_domain_irq+0x60/0xb4) [<c0178730>] (__handle_domain_irq) from [<c03c8fb4>] (gic_handle_irq+0x3c/0x78) [<c03c8fb4>] (gic_handle_irq) from [<c0101acc>] (__irq_svc+0x6c/0x90)
Exception stack(0xc0b01f18 to 0xc0b01f60)
1f00: 00000000 00129634
1f20: ef79c830 c0119aa0 ffffe000 c0b04ea8 c0b04eec 00000001 00000000 c0b04e88 1f40: c0ab03e8 00000000 c0b04f64 c0b01f68 c0108a64 c0108a68 60070013 ffffffff [<c0101acc>] (__irq_svc) from [<c0108a68>] (arch_cpu_idle+0x38/0x3c) [<c0108a68>] (arch_cpu_idle) from [<c01576ec>] (do_idle+0x224/0x260) [<c01576ec>] (do_idle) from [<c01579e8>] (cpu_startup_entry+0x18/0x1c) [<c01579e8>] (cpu_startup_entry) from [<c0a00d3c>] (start_kernel+0x3fc/0x420)
Code: ba000002 f5d1f03c f5d1f05c f5d1f07c (e8b151f8) ---[ end trace acd3bf978189eeca ]---
It is easily reproducible. What can I do to narrow down the cause?
Signature · 1 line
Måns Rullgård
Quoted 4 lines · On Thu, 5 Mar 2020, [iso-8859-1] M�ns Rullg�rd wrote:
While trying to capture some USB traffic, this happened:
8<--- cut here ---
Unable to handle kernel paging request at virtual address ffeff000
...
Quoted 3 lines
[<
c069e0a8>] (memcpy) from [<c050c88c>] (mon_copy_to_buff+0x4c/0x6c) [<c050c88c>] (mon_copy_to_buff) from [<c050cd2c>] (mon_bin_event+0x480/0x7b8) [<c050cd2c>] (mon_bin_event) from [<c050ade4>] (mon_bus_complete+0x50/0x6c)
...
Quoted 1 line
It is easily reproducible. What can I do to narrow down the cause?
What kind of USB traffic were you monitoring? Isochronous? Scatter-gather?
Can you add printk statements in drivers/usb/mon/mon_bin.c:mon_bin_get_data() to determine which of the pathways was used for calling mon_copy_buff() and what the values of the arguments were?
Alan Stern
Quoted 10 lines · Alan Stern
Quoted 4 lines · Måns Rullgård
While trying to capture some USB traffic, this happened:
8<--- cut here ---
Unable to handle kernel paging request at virtual address ffeff000...
Quoted 3 lines
[<
c069e0a8>] (memcpy) from [<c050c88c>] (mon_copy_to_buff+0x4c/0x6c) [<c050c88c>] (mon_copy_to_buff) from [<c050cd2c>] (mon_bin_event+0x480/0x7b8) [<c050cd2c>] (mon_bin_event) from [<c050ade4>] (mon_bus_complete+0x50/0x6c)
Quoted 6 lines
...
Quoted 1 line
It is easily reproducible. What can I do to narrow down the cause?
What kind of USB traffic were you monitoring? Isochronous? Scatter-gather?
It was bulk transfers reading from a flash stick:
# tcpdump -i usbmon5 tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on usbmon5, link-type USB_LINUX_MMAPPED (USB with padded Linux header), capture size 262144 bytes 18:52:44.785060 CONTROL SUBMIT to 5:4:0 18:52:44.785248 CONTROL COMPLETE from 5:4:0 18:52:44.786077 CONTROL SUBMIT to 5:3:0 18:52:44.786171 CONTROL COMPLETE from 5:3:0 18:52:44.786274 CONTROL SUBMIT to 5:2:0 18:52:44.786308 CONTROL COMPLETE from 5:2:0 18:52:44.786379 CONTROL SUBMIT to 5:1:0 18:52:44.786408 CONTROL COMPLETE from 5:1:0 18:52:50.693712 BULK SUBMIT to 5:4:2 18:52:50.693788 BULK COMPLETE from 5:4:2 18:52:50.694470 BULK SUBMIT to 5:4:1 18:52:50.694562 BULK COMPLETE from 5:4:1 18:52:50.694667 BULK SUBMIT to 5:4:1 18:52:50.694687 BULK COMPLETE from 5:4:1 18:52:50.695562 BULK SUBMIT to 5:4:2 18:52:50.695630 BULK COMPLETE from 5:4:2 18:52:50.695799 BULK SUBMIT to 5:4:1 18:52:50.695823 BULK SUBMIT to 5:4:1 18:52:50.695828 BULK SUBMIT to 5:4:1 18:52:50.695832 BULK SUBMIT to 5:4:1
And then it died. Sometimes it lasts a little longer, but it always happens pretty quickly.
Quoted 3 lines
Can you add printk statements in
drivers/usb/mon/mon_bin.c:mon_bin_get_data()to determine which of the pathways was used for callingmon_copy_buff()and what the values of the arguments were?
I'll do that.
Signature · 1 line
Måns Rullgård
Quoted 12 lines · Alan Stern
Quoted 4 lines · Måns Rullgård
While trying to capture some USB traffic, this happened:
8<--- cut here ---
Unable to handle kernel paging request at virtual address ffeff000...
Quoted 3 lines
[<
c069e0a8>] (memcpy) from [<c050c88c>] (mon_copy_to_buff+0x4c/0x6c) [<c050c88c>] (mon_copy_to_buff) from [<c050cd2c>] (mon_bin_event+0x480/0x7b8) [<c050cd2c>] (mon_bin_event) from [<c050ade4>] (mon_bus_complete+0x50/0x6c)...
Quoted 8 lines
Quoted 1 line
It is easily reproducible. What can I do to narrow down the cause?
What kind of USB traffic were you monitoring? Isochronous? Scatter-gather?
Can you add printk statements in
drivers/usb/mon/mon_bin.c:mon_bin_get_data()to determine which of the pathways was used for callingmon_copy_buff()and what the values of the arguments were?
OK, I added a printk to mon_bin_get_data(), and the bad call has offset=4736, length=4096 urb->num_sgs=0 urb->transfer_flags=0x281, urb->transfer_buffer=0xffefee00.
I guess the question now is how transfer_buffer got assigned that value.
Signature · 1 line
Måns Rullgård
Quoted 19 lines · On Fri, 6 Mar 2020, [iso-8859-1] M�ns Rullg�rd wrote:
Quoted 17 lines · Alan Stern
Quoted 4 lines · M�ns Rullg�rd
While trying to capture some USB traffic, this happened:
8<--- cut here ---
Unable to handle kernel paging request at virtual address ffeff000...
Quoted 3 lines
[<
c069e0a8>] (memcpy) from [<c050c88c>] (mon_copy_to_buff+0x4c/0x6c) [<c050c88c>] (mon_copy_to_buff) from [<c050cd2c>] (mon_bin_event+0x480/0x7b8) [<c050cd2c>] (mon_bin_event) from [<c050ade4>] (mon_bus_complete+0x50/0x6c)...
Quoted 1 line
It is easily reproducible. What can I do to narrow down the cause?
What kind of USB traffic were you monitoring? Isochronous? Scatter-gather?
Quoted 7 lines
Quoted 3 lines
Can you add printk statements in
drivers/usb/mon/mon_bin.c:mon_bin_get_data()to determine which of the pathways was used for callingmon_copy_buff()and what the values of the arguments were?OK, I added a printk to
mon_bin_get_data(), and the bad call has offset=4736, length=4096 urb->num_sgs=0 urb->transfer_flags=0x281, urb->transfer_buffer=0xffefee00.
The values seem reasonable enough, except for transfer_buffer.
Quoted 1 line
I guess the question now is how
transfer_buffergot assigned that value.
Depending on how your kernel is configured (in particular, whether CONFIG_MUSB_PIO_ONLY is enabled), it might be assigned in musb_alloc_temp_buffer() (in drivers/usb/musb/musb_host.c) or usb_sg_init() (in drivers/usb/core/message.c).
With a little more detective work you ought to be to determine which pathway is being used and what its important values are. I wouldn't be surprised to learn that 0xffefee0 was the value from sg_virt(sg) in usb_sg_init().
Alan Stern
Quoted 38 lines · Alan Stern
Quoted 19 lines · Måns Rullgård
Quoted 17 lines · Alan Stern
Quoted 4 lines · Måns Rullgård
While trying to capture some USB traffic, this happened:
8<--- cut here ---
Unable to handle kernel paging request at virtual address ffeff000...
Quoted 3 lines
[<
c069e0a8>] (memcpy) from [<c050c88c>] (mon_copy_to_buff+0x4c/0x6c) [<c050c88c>] (mon_copy_to_buff) from [<c050cd2c>] (mon_bin_event+0x480/0x7b8) [<c050cd2c>] (mon_bin_event) from [<c050ade4>] (mon_bus_complete+0x50/0x6c)...
Quoted 1 line
It is easily reproducible. What can I do to narrow down the cause?
What kind of USB traffic were you monitoring? Isochronous? Scatter-gather?
Quoted 7 lines
Quoted 3 lines
Can you add printk statements in
drivers/usb/mon/mon_bin.c:mon_bin_get_data()to determine which of the pathways was used for callingmon_copy_buff()and what the values of the arguments were?OK, I added a printk to
mon_bin_get_data(), and the bad call has offset=4736, length=4096 urb->num_sgs=0 urb->transfer_flags=0x281, urb->transfer_buffer=0xffefee00.The values seem reasonable enough, except for
transfer_buffer.Quoted 1 line
I guess the question now is how
transfer_buffergot assigned that value.Depending on how your kernel is configured (in particular, whether
CONFIG_MUSB_PIO_ONLYis enabled), it might be assigned inmusb_alloc_temp_buffer()(indrivers/usb/musb/musb_host.c) orusb_sg_init()(indrivers/usb/core/message.c).
Quoted 4 lines
With a little more detective work you ought to be to determine which pathway is being used and what its important values are. I wouldn't be surprised to learn that
0xffefee0was the value fromsg_virt(sg)inusb_sg_init().
I found the problem. Initially, usb_sg_init() sets transfer_buffer to NULL like this:
if (!PageHighMem(sg_page(sg))) urb->transfer_buffer = sg_virt(sg); else urb->transfer_buffer = NULL;
Later, musb_host_rx() uses sg_miter_next() to assign a temporary address:
/*
* We need to map sg if the transfer_buffer is
* NULL.
*/
if (!urb->transfer_buffer) {
qh->use_sg = true;
sg_miter_start(&qh->sg_miter, urb->sg, 1,
sg_flags);
}
if (qh->use_sg) {
if (!sg_miter_next(&qh->sg_miter)) {
dev_err(musb->controller, "error: sg list empty\n");
sg_miter_stop(&qh->sg_miter);
status = -EINVAL;
done = true;
goto finish;
}
urb->transfer_buffer = qh->sg_miter.addr;
received_len = urb->actual_length;
qh->offset = 0x0;
done = musb_host_packet_rx(musb, urb, epnum,
iso_err);
/* Calculate the number of bytes received */
received_len = urb->actual_length -
received_len;
qh->sg_miter.consumed = received_len;
sg_miter_stop(&qh->sg_miter);
} else {
done = musb_host_packet_rx(musb, urb,
epnum, iso_err);
}When the transfer has completed, a bogus value is left behind in urb->transfer_buffer, and this trips up usbmon. Apparently nothing else uses that value before the urb is released.
This patch makes it not crash:
drivers/usb/musb/musb_host.c +6 -2
@@ -1459,8 +1459,10 @@ void musb_host_tx(struct musb *musb, u8 epnum) qh->segsize = length;if (qh->use_sg) { -if (offset + length >= urb->transfer_buffer_length) +if (offset + length >= urb->transfer_buffer_length) { qh->use_sg = false; + urb->transfer_buffer =NULL ; + } }musb_ep_select (mbase, epnum);
@@ -1977,8 +1979,10 @@ void musb_host_rx(struct musb *musb, u8 epnum) urb->actual_length += xfer_len; qh->offset += xfer_len;if (done) { -if (qh->use_sg) +if (qh->use_sg) { qh->use_sg = false; + urb->transfer_buffer =NULL ; + }if (urb->status == -EINPROGRESS ) urb->status = status;
Signature · 1 line
Måns Rullgård
Quoted 68 lines · On Fri, 6 Mar 2020, [iso-8859-1] M�ns Rullg�rd wrote:
I found the problem. Initially,
usb_sg_init()setstransfer_bufferto NULL like this:if (!PageHighMem(sg_page(sg))) urb->transfer_buffer = sg_virt(sg); else urb->transfer_buffer = NULL;Later,
musb_host_rx()usessg_miter_next()to assign a temporary address:/* * We need to map sg if the transfer_buffer is * NULL. */ if (!urb->transfer_buffer) { qh->use_sg = true; sg_miter_start(&qh->sg_miter, urb->sg, 1, sg_flags); } if (qh->use_sg) { if (!sg_miter_next(&qh->sg_miter)) { dev_err(musb->controller, "error: sg list empty\n"); sg_miter_stop(&qh->sg_miter); status = -EINVAL; done = true; goto finish; } urb->transfer_buffer = qh->sg_miter.addr; received_len = urb->actual_length; qh->offset = 0x0; done = musb_host_packet_rx(musb, urb, epnum, iso_err); /* Calculate the number of bytes received */ received_len = urb->actual_length - received_len; qh->sg_miter.consumed = received_len; sg_miter_stop(&qh->sg_miter); } else { done = musb_host_packet_rx(musb, urb, epnum, iso_err); }When the transfer has completed, a bogus value is left behind in
urb->transfer_buffer, and this trips up usbmon. Apparently nothing else uses that value before the urb is released.This patch makes it not crash:
drivers/usb/musb/musb_host.c +3
-1@@ -1459,8 +1459,10 @@ void musb_host_tx(struct musb *musb, u8 epnum) qh->segsize = length;if (qh->use_sg) { -if (offset + length >= urb->transfer_buffer_length) +if (offset + length >= urb->transfer_buffer_length) { qh->use_sg = false; + urb->transfer_buffer =NULL ; + } }musb_ep_select (mbase, epnum);@@ -1977,8 +1979,10 @@ void musb_host_rx(struct musb *musb, u8 epnum) urb->actual_length += xfer_len;
drivers/usb/musb/musb_host.c void musb_host_rx(struct musb *musb, u8 epnum) · line 1988
Quoted 10 lines
drivers/usb/musb/musb_host.c +3
-1qh->offset += xfer_len;if (done) { -if (qh->use_sg) +if (qh->use_sg) { qh->use_sg = false; + urb->transfer_buffer =NULL ; + }if (urb->status == -EINPROGRESS ) urb->status = status;
Good detective work, and I'm glad I was able to help.
Alan Stern