search

8devices / carambola

Carambola - RT305x/SoC based PCB
http://openwrt.org/
GNU General Public License v2.0
26 stars 12 forks source link

usb audio issue #12

Closed shroukkhan closed 10 years ago

shroukkhan commented 11 years ago

when running USB headset ( Logitec USB headset ) , insufficient bandwidth error appears:

root@OpenWrt:/# [ 1202.390000] dwc_otg: check_periodic_bandwidth: already claimed usecs 157, required usecs 83 [ 1202.390000] dwc_otg: schedule_periodic: Insufficient periodic bandwidth for periodic transfer. [ 1202.390000] dwc_otg: DWC OTG HCD URB Enqueue failed adding QTD. Error status -28 [ 1202.390000] cannot submit datapipe for urb 0, error -28: not enough bandwidth

my demsg:

root@OpenWrt:~# dmesg | grep -i usb [ 9.120000] usbcore: registered new interface driver usbfs [ 9.130000] usbcore: registered new interface driver hub [ 9.140000] usbcore: registered new device driver usb [ 10.010000] usbcore: registered new interface driver rt2500usb [ 10.390000] usbcore: registered new interface driver rt2800usb [ 12.250000] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 13.430000] dwc_otg dwc_otg.0: new USB bus registered, assigned bus number 1 [ 13.460000] hub 1-0:1.0: USB hub found [ 14.040000] usbcore: registered new interface driver snd-usb-audio [ 14.060000] usb 1-1: new full-speed USB device number 2 using dwc_otg [ 14.160000] Initializing USB Mass Storage driver... [ 14.160000] usbcore: registered new interface driver usb-storage [ 14.170000] USB Mass Storage support registered. [ 14.510000] usbcore: registered new interface driver usbhid [ 14.510000] usbhid: USB HID core driver [ 14.540000] usbcore: registered new interface driver yealink [ 1444.000000] usb 1-1: USB disconnect, device number 2 [ 1451.090000] usb 1-1: new full-speed USB device number 3 using dwc_otg [ 1451.390000] input: Logitech Logitech USB Headset as /devices/platform/dwc_otg.0/usb1/1-1/1-1:1.3/input/input0 [ 1451.400000] generic-usb 0003:046D:0A0B.0001: input: USB HID v1.00 Device [Logitech Logitech USB Headset] on usb-dwc_otg.0-1/input3

------- similar to issue submitted here: https://dev.openwrt.org/ticket/12209 ------- also submitted in : http://www.8devices.com/community/viewtopic.php?f=6&t=247

shroukkhan commented 11 years ago

further information:

407@58.97.11.13: Incoming call from: sip:409@58.97.11.13 - (press ENTER to accept) [ 175.400000] CPU 0 Unable to handle kernel paging request at virtual address 00000024, epc == 80d37924, ra == 81ba71fc [ 175.400000] Oops[#1]: [ 175.400000] Cpu 0 [ 175.400000] $ 0 : 00000000 00000000 00000000 00000184 [ 175.400000] $ 4 : 00000000 804fd300 ffffff7d 00000001 [ 175.400000] $ 8 : 00000000 0001609e 80e7b800 00000000 [ 175.400000] $12 : 00000000 76e2c030 00000f15 00000000 [ 175.400000] $16 : 80e7bb80 00000000 804fd300 80ce8e00 [ 175.400000] $20 : 00000000 80ce8ed8 ffffff7d 00000014 [ 175.400000] $24 : 00000000 80d37878
[ 175.400000] $28 : 80224000 80225af0 00000500 81ba71fc [ 175.400000] Hi : 00000001 [ 175.400000] Lo : 00000000 [ 175.400000] epc : 80d37924 0x80d37924 [ 175.400000] Tainted: G O [ 175.400000] ra : 81ba71fc 0x81ba71fc [ 175.400000] Status: 1100a402 KERNEL EXL [ 175.400000] Cause : 00800008 [ 175.400000] BadVA : 00000024 [ 175.400000] PrId : 0001964c (MIPS 24KEc) [ 175.400000] Modules linked in: yealink usbhid hid usb_storage snd_usb_audio snd_usbmidi_lib usbatm evdev i2c_gpio i2c_algo_bit dwc_otg i2c_dev i2c_core nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp ipt_MASQUERADE iptable_nat nf_nat pppoe xt_conntrack xt_CT xt_NOTRACK iptable_raw xt_state nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack ehci_hcd sd_mod pppox ipt_REJECT xt_TCPMSS ipt_LOG xt_comment xt_multiport xt_mac xt_limit iptable_mangle iptable_filter ip_tables xt_tcpudp x_tables snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_rawmidi snd_seq_device snd_hwdep snd_page_alloc snd soundcore ppp_async ppp_generic slhc br2684 atm rt2800usb(O) rt2800pci(O) rt2800lib(O) rt2500usb(O) rt2x00usb(O) rt2x00soc(O) rt2x00pci(O) rt2x00lib(O) mac80211(O) lib80211_crypt_tkip(O) lib80211_crypt_ccmp(O) lib80211_crypt_wep(O) lib80211(O) usbcore usb_common scsi_mod nls_base crc_itu_t crc_ccitt eeprom_93cx6 cfg80211(O) compat(O) arc4 aes_generic crypto_algapi leds_gpio input_core [ 175.400000] Process swapper (pid: 0, threadinfo=80224000, task=80227cc0, tls=00000000) [ 175.400000] Stack : 81870b00 80225b80 00000000 81870b44 00000000 804fd300 00000000 ffffff7d [ 175.400000] 81ae3c84 81ae3c88 00000001 81ba71fc 00000001 00000000 00000001 80034110 [ 175.400000] 80e74428 81ae3c10 00000002 00000001 00000020 80d61470 80230000 00000003 [ 175.400000] 80e74428 80031ba0 80e50c00 00000010 00000180 00000000 00000001 80c19f00 [ 175.400000] 80c9bc10 00000500 00000040 00000001 00000000 80c93954 00013bc0 80c19f00 [ 175.400000] ... [ 175.400000] Call Trace:[<81ba71fc>] 0x81ba71fc [ 175.400000] [<80034110>] 0x80034110 [ 175.400000] [<80d61470>] 0x80d61470 [ 175.400000] [<80031ba0>] 0x80031ba0 [ 175.400000] [<80c93954>] 0x80c93954 [ 175.400000] [<80c937a4>] 0x80c937a4 [ 175.400000] [<80c986bc>] 0x80c986bc [ 175.400000] [<80c98468>] 0x80c98468 [ 175.400000] [<80c98880>] 0x80c98880 [ 175.400000] [<80d6210c>] 0x80d6210c [ 175.400000] [<80d61ad8>] 0x80d61ad8 [ 175.400000] [<80d61cf8>] 0x80d61cf8 [ 175.400000] [<81ba5e04>] 0x81ba5e04 [ 175.400000] [<80d39660>] 0x80d39660 [ 175.400000] [<80d3a07c>] 0x80d3a07c [ 175.400000] [<8003b880>] 0x8003b880 [ 175.400000] [<8002d0a4>] 0x8002d0a4 [ 175.400000] [<80d3a5fc>] 0x80d3a5fc [ 175.400000] [<80d39b90>] 0x80d39b90 [ 175.400000] [<8002dc88>] 0x8002dc88 [ 175.400000] [<80d3a710>] 0x80d3a710 [ 175.400000] [<80d3779c>] 0x80d3779c [ 175.400000] [<81ba5318>] 0x81ba5318 [ 175.400000] [<800433f8>] 0x800433f8 [ 175.400000] [<80254dc0>] 0x80254dc0 [ 175.400000] [<800435ac>] 0x800435ac [ 175.400000] [<800460f0>] 0x800460f0 [ 175.400000] [<80042d20>] 0x80042d20 [ 175.400000] [<800479cc>] 0x800479cc [ 175.400000] [<800036e8>] 0x800036e8 [ 175.400000] [<80001d10>] 0x80001d10 [ 175.400000] [<80001ee0>] 0x80001ee0 [ 175.400000] [<80254dc0>] 0x80254dc0 [ 175.400000] [<80033e08>] 0x80033e08 [ 175.400000] [<80003748>] 0x80003748 [ 175.400000] [<80001f00>] 0x80001f00 [ 175.400000] [<802368c8>] 0x802368c8 [ 175.400000] [<80254dc0>] 0x80254dc0 [ 175.400000] [<802360dc>] 0x802360dc [ 175.400000] [ 175.400000] [ 175.400000] Code: 41626000 30420001 000000c0 <8e230024> 8e240020 ac830004 ac640000 3c030010 24630100 [ 175.780000] ---[ end trace 6ed6b42990429aa0 ]--- [ 175.780000] Kernel panic - not syncing: Fatal exception in interrupt [ 175.790000] Rebooting in 3 seconds..

valinskas commented 11 years ago

Hi, shroukkhan,

can you recompile kernel with additionally enabled options that decodes magic addresses -> function names in backtraces ?

And then recreate a problem again ?

I could create an upgrade image with those kernel options enabled but you would have to reinstall packages & etc after upgrade.

valinskas commented 11 years ago

Option to decode addresses to function names is KERNEL_KALLSYMS. Run 'make menuconfig' then under 'Global build settings' turn on option: 'Compile the kernel with symbol table information'

serra82 commented 11 years ago

I have the same problem with an usb-audio, I compiled the kernel with debug:

[ 3735.520000] CPU 0 Unable to handle kernel paging request at virtual address 00000024, epc == 80e37924, ra == 80c671fc [ 3735.520000] Oops[#1]: [ 3735.520000] Cpu 0 [ 3735.520000] $ 0 : 00000000 00000000 00000000 00000184 [ 3735.520000] $ 4 : 00000000 80981700 ffffff7d 0000113a [ 3735.520000] $ 8 : 00000030 80107860 00000000 00000000 [ 3735.520000] $12 : 00000000 00000001 00000001 00000000 [ 3735.520000] $16 : 802f3800 00000000 80981700 80d2ae00 [ 3735.520000] $20 : 00000000 80d2aed8 ffffff7d 00000014 [ 3735.520000] $24 : 00000000 80e37878 [ 3735.520000] $28 : 80830000 80831510 000044e8 80c671fc [ 3735.520000] Hi : 00000000 [ 3735.520000] Lo : 00000000 [ 3735.520000] epc : 80e37924 dwc_otg_hcd_urb_dequeue+0xac/0x178 [dwc_otg] [ 3735.520000] Tainted: G O [ 3735.520000] ra : 80c671fc usb_hcd_unlink_urb+0x70/0xa4 [usbcore] [ 3735.520000] Status: 1100e402 KERNEL EXL [ 3735.520000] Cause : 00800008 [ 3735.520000] BadVA : 00000024 [ 3735.520000] PrId : 0001964c (MIPS 24KEc) [ 3735.520000] Modules linked in: usb_storage snd_usb_audio snd_usbmidi_lib cdc_acm i2c_gpio i2c_algo_bit dwc_otg i2c_dev i2c_core nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp ipt_MASQUERADE iptable_nat nf_nat pppoe xt_conntrack xt_CT xt_NOTRACK iptable_raw xt_state nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack sd_mod pppox ipt_REJECT xt_TCPMSS ipt_LOG xt_comment xt_multiport xt_mac xt_limit iptable_mangle iptable_filter ip_tables xt_tcpudp x_tables snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_rawmidi snd_seq_device snd_hwdep snd_page_alloc snd soundcore ppp_async ppp_generic slhc rt2800usb(O) rt2800pci(O) rt2800lib(O) rt2500usb(O) rt2x00usb(O) rt2x00soc(O) rt2x00pci(O) rt2x00lib(O) mac80211(O) lib80211_crypt_tkip(O) lib80211_crypt_ccmp(O) lib80211_crypt_wep(O) lib80211(O) usbcore usb_common scsi_mod nls_base crc_itu_t crc_ccitt eeprom_93cx6 cfg80211(O) compat(O) arc4 aes_generic crypto_algapi leds_gpio input_core [ 3735.520000] Process top (pid: 1237, threadinfo=80830000, task=8190b608, tls=77a6c440) [ 3735.520000] Stack : 000000c3 8024daf4 80e76400 80158074 00000000 80981700 00000000 ffffff7d [ 3735.520000] 80e0ac84 80e0ac88 00000001 80c671fc 00000020 80c8c4b4 00000000 80e76400 [ 3735.520000] 81aa49c0 80e0ac10 00000001 00000001 00000020 80e61470 81aa49c0 80e76400 [ 3735.520000] 81aa49c0 80182694 80692000 000000dc 0000113c 00000000 00000004 80e09c00 [ 3735.520000] 80dfbc10 000044e8 00000160 00000001 00000000 80df3954 0004bb07 80e09c00 [ 3735.520000] ... [ 3735.520000] Call Trace: [ 3735.520000] [<80e37924>] dwc_otg_hcd_urb_dequeue+0xac/0x178 [dwc_otg] [ 3735.520000] [<80c671fc>] usb_hcd_unlink_urb+0x70/0xa4 [usbcore] [ 3735.520000] [<80e61470>] snd_usb_init_sample_rate+0x6a8/0x1448 [snd_usb_audio] [ 3735.520000] [ 3735.520000] [ 3735.520000] Code: 41626000 30420001 000000c0 <8e230024> 8e240020 ac830004 ac640000 3c030010 24630100 [ 3735.790000] ---[ end trace 4d3b0bdd8f3f7e8c ]--- [ 3735.800000] Kernel panic - not syncing: Fatal exception in interrupt [ 3735.800000] Rebooting in 3 seconds..

U-Boot 1.1.3 (Nov 3 2009 - 15:19:34)

Board: Ralink APSoC DRAM: 32 MB relocate_code Pointer at: 81fb0000 flash_protect ON: from 0xBF000000 to 0xBF01D4A3 flash_protect ON: from 0xBF030000 to 0xBF030FFF *\ Warning - bad CRC, using default environment

Ralink UBoot Version: 3.3

ASIC 3052_MP2 (Port5<->None) DRAM component: 256 Mbits SDR DRAM bus: 16 bit Total memory: 32 MBytes Flash component: 8 MBytes NOR Flash Date:Nov 3 2009 Time:15:19:34

icache: sets:256, ways:4, linesz:32 ,total:32768 dcache: sets:128, ways:4, linesz:32 ,total:16384

The CPU freq = 320 MHZ

SDRAM bus set to 16 bit SDRAM size =32 Mbytes

Please choose the operation: 1: Load system code to SDRAM via TFTP. 2: Load system code then write to Flash via TFTP. 3: Boot system code via Flash (default). 4: Entr boot command line interface. 9: Load Boot Loader code then write to Flash via TFTP.

valinskas commented 11 years ago

Good work, serra82

serra82 commented 11 years ago

Hi valinskas, any news? Is it a problem of the Ralink usb driver? How can I help you to resolve the problem? actually I don't know where to start!

valinskas commented 11 years ago

Hi,

So far nothing obvious is standing out. And yes, you can help me a great deal. Please run the following command:

$ cd build_dir/linux-ramips_rt305x/linux-3.3.8/ $ gdb drivers/usb/dwc_otg/dwc_otg_hcd.o (gdb) list *dwc_otg_hcd_urb_dequeue+0xac

serra82 commented 11 years ago

I enabled "Compile the kernel with debug information" on "Global build settings", this is the result:

(gdb) list dwc_otg_hcd_urb_dequeue+0xac 0xc64 is in dwc_otg_hcd_urb_dequeue (include/linux/list.h:106). 101 __list_del(entry->prev, entry->next); 102 } 103 104 static inline void list_del(struct list_head entry) 105 { 106 __list_del(entry->prev, entry->next); 107 entry->next = LIST_POISON1; 108 entry->prev = LIST_POISON2; 109 } 110 #else

next step?! :-)

valinskas commented 11 years ago

Most likely it's a NULL pointer:

drivers/usb/dwc_otg/dwc_otg_hcd.c:

1019         dwc_otg_hcd_qtd_remove_and_free(dwc_otg_hcd, urb_qtd); <--- 
1020         if (urb_qtd == qh->qtd_in_process) {
1021                 dwc_otg_hcd_qh_deactivate(dwc_otg_hcd, qh, 0);
1022                 qh->channel = NULL;
1023                 qh->qtd_in_process = NULL;
1024         } else if (list_empty(&qh->qtd_list)) {
1025                 dwc_otg_hcd_qh_remove(dwc_otg_hcd, qh);
1026         }

dwc_otg_hcd_qtd_remove_and_free() calls dwc_otg_hcd_qtd_remove().

drivers/usb/dwc_otg/dwc_otg_hcd.h:

529 static inline void dwc_otg_hcd_qtd_remove(dwc_otg_hcd_t *hcd, dwc_otg_qtd_t *qtd)
530 {
531         unsigned long flags;
532         SPIN_LOCK_IRQSAVE(&hcd->lock, flags);
533         list_del(&qtd->qtd_list_entry);  <---- qtd is NULL ?
534         SPIN_UNLOCK_IRQRESTORE(&hcd->lock, flags);
535 }

Can you add check like this before list_del():

if (qtd == NULL) {
      printk("qtd is NULL\n");
      BUG();
}
list_del(&qtd->qtd_list_entry);  <---- qtd is NULL ?
...
serra82 commented 11 years ago

you found the problem, carambola print the following message before rebooting root@OpenWrt:/# [ 123.440000] qtd is NULL

do you know a possible solution?!? thank you Andrea

valinskas commented 11 years ago

Hi,

I am still digging through the code. I don't have a solution yet. You could still try attached patch:

Index: linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd.h
===================================================================
--- linux-3.3.8.orig/drivers/usb/dwc_otg/dwc_otg_hcd.h
+++ linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd.h
@@ -537,8 +537,10 @@ static inline void dwc_otg_hcd_qtd_remov
 /** Remove and free a QTD */
 static inline void dwc_otg_hcd_qtd_remove_and_free(dwc_otg_hcd_t *hcd, dwc_otg_qtd_t *qtd)
 {
-   dwc_otg_hcd_qtd_remove(hcd, qtd);
-   dwc_otg_hcd_qtd_free(qtd);
+   if (qtd != NULL) {
+       dwc_otg_hcd_qtd_remove(hcd, qtd);
+       dwc_otg_hcd_qtd_free(qtd);
+   }
 }

 /** @} */
valinskas commented 11 years ago

Andrea,

I am not sure the patch above is correct. But it should help to avoid NULL pointer problem. Btw, when does the problem happens ? Can you walk through what you are doing ?

serra82 commented 11 years ago

the patch improve, but not resolve the problem, I added in your patch printk("qtd is NULL\n") if qts is NULL. I downloaded two mp3 in /tmp and played them with madplay, when the song ends now carabola print qtd is NULL but not crash always. Other errors that sometimes I see are:

1) an infinite list of:

root@OpenWrt:/# [ 84.300000] qtd is NULL [ 86.680000] cannot submit datapipe for urb 0, error -22: internal error [ 86.690000] cannot submit datapipe for urb 0, error -22: internal error [ 86.680000] cannot submit datapipe for urb 0, error -22: internal error [ 86.690000] cannot submit datapipe for urb 0, error -22: internal error .....

2) another crash, in console shell I play a song with madplay and in ssh shell I run a commad as ls or top:

[ 433.350000] qtd is NULL [ 433.380000] CPU 0 Unable to handle kernel paging request at virtual address 0000001c, epc == 80d86eb0, ra == 80d87da0 [ 433.380000] Oops[#1]: [ 433.380000] Cpu 0 [ 433.380000] $ 0 : 00000000 00000001 80e75400 80e276a0 [ 433.380000] $ 4 : 80d22ed8 80d77f00 00506b05 00000000 [ 433.380000] $ 8 : 00000001 000000b0 81b089f8 80710680 [ 433.380000] $12 : 81aded90 00000000 00000034 00000000 [ 433.380000] $16 : 80d77f2c 80710700 00000000 80d22f20 [ 433.380000] $20 : 80d22f04 80d22f0c 802b0000 80e276a0 [ 433.380000] $24 : 00000000 8000cc3c [ 433.380000] $28 : 80e24000 80e25ad0 802227d0 80d87da0 [ 433.380000] Hi : 00000064 [ 433.380000] Lo : e7760100 [ 433.380000] epc : 80d86eb0 dwc_otg_hcd_hub_status_data+0x1d8/0x4d8 [dwc_otg] [ 433.380000] Tainted: G O [ 433.380000] ra : 80d87da0 dwc_otg_hcd_select_transactions+0x50/0x164 [dwc_otg] [ 433.380000] Status: 1100e402 KERNEL EXL [ 433.380000] Cause : 00800008 [ 433.380000] BadVA : 0000001c [ 433.380000] PrId : 0001964c (MIPS 24KEc) [ 433.380000] Modules linked in: usb_storage snd_usb_audio snd_usbmidi_lib cdc_acm i2c_gpio i2c_algo_bit dwc_otg i2c_dev i2c_core nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp ipt_MASQUERADE iptable_nat nf_nat pppoe xt_conntrack xt_CT xt_NOTRACK iptable_raw xt_state nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack sd_mod pppox ipt_REJECT xt_TCPMSS ipt_LOG xt_comment xt_multiport xt_mac xt_limit iptable_mangle iptable_filter ip_tables xt_tcpudp x_tables snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_rawmidi snd_seq_device snd_hwdep snd_page_alloc snd soundcore ppp_async ppp_generic slhc rt2800usb(O) rt2800pci(O) rt2800lib(O) rt2500usb(O) rt2x00usb(O) rt2x00soc(O) rt2x00pci(O) rt2x00lib(O) mac80211(O) lib80211_crypt_tkip(O) lib80211_crypt_ccmp(O) lib80211_crypt_wep(O) lib80211(O) usbcore usb_common scsi_mod nls_base crc_itu_t crc_ccitt eeprom_93cx6 cfg80211(O) compat(O) arc4 aes_generic crypto_algapi leds_gpio input_core [ 433.380000] Process ls (pid: 1204, threadinfo=80e24000, task=8189e990, tls=770a9440) [ 433.380000] Stack : 80d22ed8 80255598 00000000 00000000 802b0000 80d22ed8 80710720 80d87da0 [ 433.380000] 80710880 800f1954 80710880 8140b870 80d22ed8 80d49300 80710700 b01c0580 [ 433.380000] 80d22ed8 00000000 802b0000 80e276a0 802227d0 80d88c34 00000000 80d8779c [ 433.380000] 80e25b2c 00000000 80e27680 80d49300 80e75400 80d896d4 80255598 00000080 [ 433.380000] 00000001 802b0000 00000001 80045684 8140b870 80d49300 b01c0580 80d22ed8 [ 433.380000] ... [ 433.380000] Call Trace: [ 433.380000] [<80d86eb0>] dwc_otg_hcd_hub_status_data+0x1d8/0x4d8 [dwc_otg] [ 433.380000] [<80d87da0>] dwc_otg_hcd_select_transactions+0x50/0x164 [dwc_otg] [ 433.380000] [ 433.380000] [ 433.380000] Code: 7ce693c4 ae06ffd4 8c470028 <8ce9001c> 15280003 24070002 08361bb4 7c06ad04 55270002 [ 433.640000] ---[ end trace 45bc6b88570d3491 ]--- [ 433.640000] Kernel panic - not syncing: Fatal exception in interrupt [ 433.650000] Rebooting in 3 seconds..

this is the debug symbol, I think the problem is in urb that is NULL

(gdb) list dwc_otg_hcd_hub_status_data+0x1d8 0x1f0 is in assign_and_init_hc (drivers/usb/dwc_otg/dwc_otg_hcd.c:2105). 2100 * 0 before the SET_ADDRESS command and the correct address afterward. 2101 / 2102 hc->dev_addr = usb_pipedevice(urb->pipe); 2103 hc->ep_num = usb_pipeendpoint(urb->pipe); 2104 2105 if (urb->dev->speed == USB_SPEED_LOW) { 2106 hc->speed = DWC_OTG_EP_SPEED_LOW; 2107 } else if (urb->dev->speed == USB_SPEED_FULL) { 2108 hc->speed = DWC_OTG_EP_SPEED_FULL; 2109 } else { (gdb)

Do you think that it is a problem only of usb-audio or of usb in general? thank you Andrea

valinskas commented 11 years ago

Hi Andrea,

2103         hc->ep_num = usb_pipeendpoint(urb->pipe);
2104    
2105         if (urb->dev->speed == USB_SPEED_LOW) {
2106                 hc->speed = DWC_OTG_EP_SPEED_LOW;
2107         } else if (urb->dev->speed == USB_SPEED_FULL) {
2108                 hc->speed = DWC_OTG_EP_SPEED_FULL;
2109         } else {
2110                 hc->speed = DWC_OTG_EP_SPEED_HIGH;
2111         }

My guess is either urb is NULL or urb->dev is NULL (i bet on this). If you don't mind please change code like this and it will tell as exactly what is the cause:

2102         hc->dev_addr = usb_pipedevice(urb->pipe);
2103         hc->ep_num = usb_pipeendpoint(urb->pipe);
2104    
2105         if (urb == NULL)
2106                 printk("urb is NULL\n");
2107         if (urb->dev == NULL)
2108                 printk("urb->dev is NULL\n");
2109         
2110         if (urb->dev->speed == USB_SPEED_LOW) {
2111                 hc->speed = DWC_OTG_EP_SPEED_LOW;
2112         } else if (urb->dev->speed == USB_SPEED_FULL) {
2113                 hc->speed = DWC_OTG_EP_SPEED_FULL;
2114         } else {
2115                 hc->speed = DWC_OTG_EP_SPEED_HIGH;
2116         }
serra82 commented 11 years ago

when playing a song if I run ls command in a different shell this is the result:

root@OpenWrt:/# ls [ 1465.950000] qtd is NULL [ 1466.050000] urb->dev is NULL [ 1466.050000] CPU 0 Unable to handle kernel paging request at virtual address 0000001c, epc == 80d96f14, ra == 80d96f0c [ 1466.050000] Oops[#1]: [ 1466.050000] Cpu 0 [ 1466.050000] $ 0 : 00000000 00000001 00000000 80250000 [ 1466.050000] $ 4 : 00000001 802527ac 00000001 00000000 [ 1466.050000] $ 8 : 00000020 00000001 00000001 00000000 [ 1466.050000] $12 : 00000000 00000000 00000034 fffd009c [ 1466.050000] $16 : 80da3e2c 80fea600 80e1f520 80718500 [ 1466.050000] $20 : 80d43ed8 80da3e00 802b0000 80e1f420 [ 1466.050000] $24 : 00000001 8012952c [ 1466.050000] $28 : 80e1c000 80e1d700 802227d0 80d96f0c [ 1466.050000] Hi : 00000000 [ 1466.050000] Lo : 4ac12000 [ 1466.050000] epc : 80d96f14 dwc_otg_hcd_connect_timeout+0xd8/0x494 [dwc_otg] [ 1466.050000] Tainted: G O [ 1466.050000] ra : 80d96f0c dwc_otg_hcd_connect_timeout+0xd0/0x494 [dwc_otg] [ 1466.050000] Status: 1100e402 KERNEL EXL [ 1466.050000] Cause : 40808008 [ 1466.050000] BadVA : 0000001c [ 1466.050000] PrId : 0001964c (MIPS 24KEc) [ 1466.050000] Modules linked in: usb_storage snd_usb_audio snd_usbmidi_lib cdc_acm i2c_gpio i2c_algo_bit dwc_otg i2c_dev i2c_core nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp ipt_MASQUERADE iptable_nat nf_nat pppoe xt_conntrack xt_CT xt_NOTRACK iptable_raw xt_state nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack sd_mod pppox ipt_REJECT xt_TCPMSS ipt_LOG xt_comment xt_multiport xt_mac xt_limit iptable_mangle iptable_filter ip_tables xt_tcpudp x_tables snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_rawmidi snd_seq_device snd_hwdep snd_page_alloc snd soundcore ppp_async ppp_generic slhc rt2800usb(O) rt2800pci(O) rt2800lib(O) rt2500usb(O) rt2x00usb(O) rt2x00soc(O) rt2x00pci(O) rt2x00lib(O) mac80211(O) lib80211_crypt_tkip(O) lib80211_crypt_ccmp(O) lib80211_crypt_wep(O) lib80211(O) usbcore usb_common scsi_mod nls_base crc_itu_t crc_ccitt eeprom_93cx6 cfg80211(O) compat(O) arc4 aes_generic crypto_algapi leds_gpio input_core [ 1466.050000] Process ls (pid: 1202, threadinfo=80e1c000, task=81af2990, tls=778ab440) [ 1466.050000] Stack : 3a69c2c7 80718500 00002b5f 0003ed58 80c52c00 80d43ed8 80718520 00000000 [ 1466.050000] 80d43f20 80d43f04 80d43f0c 80d97df4 00000000 802b0000 80e1f420 80dc1d08 [ 1466.050000] 80d43ed8 80da3d80 80718500 b01c0500 80d43ed8 00000000 802b0000 80e1f420 [ 1466.050000] 802227d0 80d98c84 00000000 80d977f0 80252460 00000007 80e1f400 80da3d80 [ 1466.050000] 80fea100 80d99724 80255598 00000080 80d43ed8 00000000 00000002 80255598 [ 1466.050000] ... [ 1466.050000] Call Trace: [ 1466.050000] [<80d96f14>] dwc_otg_hcd_connect_timeout+0xd8/0x494 [dwc_otg] [ 1466.050000] [ 1466.050000] [ 1466.050000] Code: 2484d2e8 8e220028 24040001 <8c45001c> 14a40003 8e02ffd4 08365bce 7c02ad04 24030002 [ 1466.310000] ---[ end trace ae851e39994e0dbb ]--- [ 1466.310000] Kernel panic - not syncing: Fatal exception in interrupt [ 1466.320000] Rebooting in 3 seconds..

serra82 commented 11 years ago

I checked the kernel changelog and I found this: (http://www.kernel.org/pub/linux/kernel/v3.0/ChangeLog-3.6.11)

commit f063c3cae7e16c5d45941ab358aa8063349724f8 Author: Alan Stern stern@rowland.harvard.edu Date: Thu Nov 8 10:17:01 2012 -0500

USB: EHCI: bugfix: urb->hcpriv should not be NULL

commit 2656a9abcf1ec8dd5fee6a75d6997a0f2fa0094e upstream.

This patch (as1632b) fixes a bug in ehci-hcd.  The USB core uses
urb->hcpriv to determine whether or not an URB is active; host
controller drivers are supposed to set this pointer to a non-NULL
value when an URB is queued.  However ehci-hcd sets it to NULL for
isochronous URBs, which defeats the check in usbcore.

In itself this isn't a big deal.  But people have recently found that
certain sequences of actions will cause the snd-usb-audio driver to
reuse URBs without waiting for them to complete.  In the absence of
proper checking by usbcore, the URBs get added to their endpoint list
twice.  This leads to list corruption and a system freeze.

The patch makes ehci-hcd assign a meaningful value to urb->hcpriv for
isochronous URBs.  Improving robustness always helps.

Signed-off-by: Alan Stern <stern@rowland.harvard.edu>
Reported-by: Artem S. Tashkinov <t.artem@lycos.com>
Reported-by: Christof Meerwald <cmeerw@cmeerw.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

Could be the same problem?!

valinskas commented 11 years ago

Hi, Andrea,

I think that upstream change 2656a9abcf1ec8dd5fee6a75d6997a0f2fa0094e "USB: EHCI: bugfix: urb->hcpriv should not be NULL" addresses other problem. Although It might solve crash when 'ls is run while playing audio'.

From drivers/usb/dwc_otg/dwc_otg_hcd.c:

2080 static void assign_and_init_hc(dwc_otg_hcd_t *hcd, dwc_otg_qh_t *qh)
2081 {
2082         dwc_hc_t        *hc;
2083         dwc_otg_qtd_t   *qtd;
2084         struct urb      *urb;
2085    
2086         DWC_DEBUGPL(DBG_HCDV, "%s(%p,%p)\n", __func__, hcd, qh);
2087 
2088         hc = list_entry(hcd->free_hc_list.next, dwc_hc_t, hc_list_entry);
2089    
2090         /* Remove the host channel from the free list. */
2091         list_del_init(&hc->hc_list_entry);
2092 
2093         qtd = list_entry(qh->qtd_list.next, dwc_otg_qtd_t, qtd_list_entry);
2094         urb = qtd->urb;
2095         qh->channel = hc;
2096         qh->qtd_in_process = qtd;

From kernel log:

[ 1466.050000] urb->dev is NULL

Problem is on lines 2093 and 2094. 'URB' on qtd list has ->dev == NULL. Which should not be and I don't have an explanation how it happens yet.

Žilvinas

dasMopo commented 11 years ago

I'm not sure, if issue #13 (which I wrote) fits to the issue described here, or maybe I noticed some detail which may help finding the source of the issue ?

For instance, openWRT issue #12209 is told to be similar to the issue I encountered, but in contrast to what is described there (#12209) I'm actually able to stream mp3 for very long times (read: hours) without encounting any problems - that is no dmesg error output, let alone system crashes (in contrast to what is described in #12209 for the same scenario)

I"m also using a C-Media based usb sound adapter (Behring uc202, that is.)

So maybe that's in fact another issue ?

Nevertheless, what I actually did encounter was the device resetting itself after the playback of a mp3 file stopped. Interestingly, I was able to play back a number of files (17 !) in sequence, without any problem noticed. The crash eventually took place after the playback of the very last file finished. (Without any further playback in list, so maybe when the sound device is released ?)

More oddly, while testing things at a later time ( again using 17 distinct mp3 files which were read from some usb stick) I noticed, that I was also able to pause, seek and even stop playback without any problem arising (using mpd for playback)

The crash only occured after playback of the very last file finished ("by itself", when I stopped playback manually [using mpc stop, for instance], I was even able to shutdown mpd safely afterwards [iirc])

Will try to test some other scenarios and verify my findings.

valinskas commented 11 years ago

dasMopo,

What do you mean here by:

I actually did encounter was the device resetting itself after the playback of a mp3 file stopped.

I am not sure I am reading this correctly but the way I understand it is that "USB device is reset". USB sub-system resets, re-enumerates devices and starts it again. Kernel is not crashing at all. Instead it's a user-space mpd(?) process that is dying ?

Softverk commented 11 years ago

i think dasMopo is talking about madplay resulting in kernel panic when the end of the song is reached. i m not sure if mpd does the same? although i have not found out how to play mp3/wav using mpd yet!

valinskas commented 11 years ago

dasMopo,

just checked OpenWRT issue #12209 it seems it's exactly the same kernel crash like in this ticket.

dasMopo commented 11 years ago

Valinksas, when the issue occurs, the whole system is reset (a.k.a. kernel panic). Still, I don't totally agree the match of 12209 to this ticket, as at least I do see some differences. (12209 describes issues while playing streamed sound - I didn't encounter any problems with streamed sound, only with local files; also does 12209 mention a lot of dmesg outputs, which simply don't occur in my setup.)

Softverk, you were totally right - although I used mpd for mp3 playback. Actually, I also tried madplay before - which displayed the exact same behavior - but switched to mpd, because I mainly wanted internet radio playback. Btw: to play mp3 files using mpd, you jut have to add them the very same way you'd add a station. (Remember to setup music dir in mpd.conf and to run mpc update at least once though.)

Softverk commented 11 years ago

any update on the mp3 playback resulting in kernel panic ?

valinskas commented 11 years ago

Hi Softverk,

I have not forgotten. It is just at them moment I am very busy with my primarily work duties. I hope to come back to this in future.

shroukkhan commented 11 years ago

the patch given by valinskas seems to solves the issue:

static inline void dwc_otg_hcd_qtd_remove_and_free(dwc_otg_hcd_t hcd, dwc_otg_qtd_t qtd) { if (qtd != NULL) { dwc_otg_hcd_qtd_remove(hcd, qtd); dwc_otg_hcd_qtd_free(qtd); } } and for the insufficient bandwidth error : ( sorry dont know how to generate a patch, and kinda in a hurry right now) you need to change the:

build_dir/linux-ramips_rt305x/linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd_queue.c

and change the function named schedule_periodic(dwc_otg_hcd_t hcd, dwc_otg_qh_t qh) like the following:

/**

valinskas commented 11 years ago

I have generated a diff. Hmm, it interesting - you have made code to ignore errors ... yet it cause no problem! Does it work as you expect ?

--- /tmp/f2     2013-03-27 10:01:43.203668207 +0200
+++ /tmp/f      2013-03-27 10:02:14.983668290 +0200
@@ -13,14 +13,14 @@ static int schedule_periodic(dwc_otg_hcd
        if (status) {
                DWC_NOTICE("%s: Insufficient periodic bandwidth for "
                           "periodic transfer.\n", __func__);
-               return status;
+               //return status;
        }

        status = check_max_xfer_size(hcd, qh);
        if (status) {
                DWC_NOTICE("%s: Channel max transfer size too small "
                           "for periodic transfer.\n", __func__);
-               return status;
+               //return status;
        }

        /* Always start in the inactive schedule. */
@@ -43,6 +43,7 @@ static int schedule_periodic(dwc_otg_hcd
                DWC_DEBUGPL(DBG_HCD, "Scheduled isoc: qh %p, usecs %d, period %d\n",
                            qh, qh->usecs, qh->interval);
        }
+       DWC_NOTICE("%s: khan made changes here !!! .\n", __func__);

-       return status;
+       return 0;
 }
shroukkhan commented 11 years ago

yes, actually there is enough bandwidth available ( i noticed this error when using usb audio with baresip ) , but for some reason call to check_periodic_bandwidth(hcd, qh) and check_max_xfer_size(hcd, qh); function returned incorrect assessment. if i have more time i shall look deeper into it, but for now, just returning 0 ( sucess ) from this function solves my issue.

here is a successful output from baresip call:

root@OpenWrt:/# baresip
baresip v0.4.1 Copyright (C) 2010 - 2011 Alfred E. Heggestad <aeh@db.org>
aucodec: PCMA 8000Hz 1ch
aucodec: PCMU 8000Hz 1ch
ausrc: alsa
auplay: alsa
medianat: stun
medianat: turn
medianat: ice
Populated 2 audio codecs
Populated 0 video codecs
Populated 0 audio filters
Local IP address: IPv4=eth0.2:192.168.1.3 IPv6=:::1
ua: 631235@27.254.11.6
Populated 1 account
Populated 1 contact
631235@27.254.11.6: 200 OK (FPBX-2.8.1(1.8.4.4)) [1 binding]
ui: All 1 useragents registered successfully! (2689 ms)
>                       0908805894
connecting to 'sip:0908805894@xxx.xxx.xxx;transport=udp'..
SIP Progress: 100 Trying ()
Set audio encoder: PCMA 8000Hz 1ch
Set audio decoder: PCMA 8000Hz 1ch
[ 7312.710000] dwc_otg: schedule_periodic: khan made changes here !!! .
[ 7313.420000] dwc_otg: schedule_periodic: khan made changes here !!! .
Enable telephone-event: pt_tx=101, pt_rx=101
video stream is disabled..
631235@xxx.xxx.xxx: Call established: sip:0908805894@xxx.xxx.xxx
sip:0908805894@xxx.xxx.xxx; session closed: Connection reset by peer

631235@27.254.11.6: Call terminated (duration: 23 secs)
valinskas commented 11 years ago

Thanks for testing ;)

shroukkhan commented 11 years ago

for the "cannot submit datapipe for urb 0, error -22: internal error" and URB is null issue, [https://github.com/8devices/carambola/issues/12#issuecomment-11532657 this comment] , did you look at the :

linux-ramips_rt305x/linux-3.3.8/sound/usb/usx2y/usbusx2yaudio.c

at about line 501~502, i added the URB check , 

if (urb!=NULL && usb_pipein(urb->pipe)) { ...

as a result the madplay does not crash anymore

full function:

static int usX2Y_urbs_start(struct snd_usX2Y_substream *subs)
{
    int i, err;
    struct usX2Ydev *usX2Y = subs->usX2Y;

    if ((err = usX2Y_urbs_allocate(subs)) < 0)
        return err;
    subs->completed_urb = NULL;
    for (i = 0; i < 4; i++) {
        struct snd_usX2Y_substream *subs = usX2Y->subs[i];
        if (subs != NULL && atomic_read(&subs->state) >= state_PREPARED)
            goto start;
    }

 start:
    usX2Y_subs_startup(subs);
    for (i = 0; i < NRURBS; i++) {
        struct urb *urb = subs->urb[i];
        snd_printk (KERN_ERR "going to check URB\n");
        if (urb!=NULL && usb_pipein(urb->pipe)) {
            unsigned long pack;
            if (0 == i)
                atomic_set(&subs->state, state_STARTING3);
            urb->dev = usX2Y->dev;
            urb->transfer_flags = URB_ISO_ASAP;
            for (pack = 0; pack < nr_of_packs(); pack++) {
                urb->iso_frame_desc[pack].offset = subs->maxpacksize * pack;
                urb->iso_frame_desc[pack].length = subs->maxpacksize;
            }
            urb->transfer_buffer_length = subs->maxpacksize * nr_of_packs(); 
            if ((err = usb_submit_urb(urb, GFP_ATOMIC)) < 0) {
                snd_printk (KERN_ERR "cannot submit datapipe for urb %d, err = %d\n", i, err);
                err = -EPIPE;
                goto cleanup;
            } else
                if (i == 0)
                    usX2Y->wait_iso_frame = urb->start_frame;
            urb->transfer_flags = 0;
        } else {
            snd_printk (KERN_ERR "URB was null..so going into atomic set\n");
            atomic_set(&subs->state, state_STARTING1);
            break;
        }
    }
    err = 0;
    wait_event(usX2Y->prepare_wait_queue, NULL == usX2Y->prepare_subs);
    if (atomic_read(&subs->state) != state_PREPARED)
        err = -EPIPE;

 cleanup:
    if (err) {
        usX2Y_subs_startup_finish(usX2Y);
        usX2Y_clients_stop(usX2Y);      // something is completely wroong > stop evrything
    }
    return err;
}
valinskas commented 11 years ago

Hi,

Do you know if the same USB device is working correctly under PC (Ubuntu, whatever) ?

Driver assumes that subs->urb[0] != NULL and subs->urb[1] != NULL and yet such thing does happen. It might be that real culprit is still burred under dwg_otg code. Your fix is fine otherwise -- I prefer it rather then kernel crash.

shroukkhan commented 11 years ago

oh yes..i use this usb headset with my ubuntu and windows 7 all the time..no problem there

valinskas commented 11 years ago

Khan,

Can you verify if this patch contains all fixes that prevent kernel crashes and USB audio device malfunctioning ? I will push these fixes.

Index: linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd.h
===================================================================
--- linux-3.3.8.orig/drivers/usb/dwc_otg/dwc_otg_hcd.h
+++ linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd.h
@@ -537,8 +537,10 @@ static inline void dwc_otg_hcd_qtd_remov
 /** Remove and free a QTD */
 static inline void dwc_otg_hcd_qtd_remove_and_free(dwc_otg_hcd_t *hcd, dwc_otg_qtd_t *qtd)
 {
-   dwc_otg_hcd_qtd_remove(hcd, qtd);
-   dwc_otg_hcd_qtd_free(qtd);
+   if (qtd != NULL) {
+       dwc_otg_hcd_qtd_remove(hcd, qtd);
+       dwc_otg_hcd_qtd_free(qtd);
+   }
 }

 /** @} */
Index: linux-3.3.8/sound/usb/usx2y/usbusx2yaudio.c
===================================================================
--- linux-3.3.8.orig/sound/usb/usx2y/usbusx2yaudio.c
+++ linux-3.3.8/sound/usb/usx2y/usbusx2yaudio.c
@@ -498,7 +498,7 @@ static int usX2Y_urbs_start(struct snd_u
    usX2Y_subs_startup(subs);
    for (i = 0; i < NRURBS; i++) {
        struct urb *urb = subs->urb[i];
-       if (usb_pipein(urb->pipe)) {
+       if (urb != NULL && usb_pipein(urb->pipe)) {
            unsigned long pack;
            if (0 == i)
                atomic_set(&subs->state, state_STARTING3);
Index: linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd_queue.c
===================================================================
--- linux-3.3.8.orig/drivers/usb/dwc_otg/dwc_otg_hcd_queue.c
+++ linux-3.3.8/drivers/usb/dwc_otg/dwc_otg_hcd_queue.c
@@ -372,12 +372,14 @@ static int schedule_periodic(dwc_otg_hcd
        return status;
    }

+#if 0 /* disable for now */
    status = check_periodic_bandwidth(hcd, qh);
    if (status) {
        DWC_NOTICE("%s: Insufficient periodic bandwidth for "
               "periodic transfer.\n", __func__);
        return status;
    }
+#endif

    status = check_max_xfer_size(hcd, qh);
    if (status) {
valinskas commented 11 years ago

Khan,

you can pull and merge this fix: valinskas/carambola@ee0cb473a0b7fbf0833e87cc7100cbf8dcd93425 Then you need to:

$ make target/linux/clean
make[1] target/linux/clean
make[2] -C target/linux clean

$ make
make[1] world
make[2] target/compile
make[3] -C target/linux compile
... # it should rebuild kernel & depending packages

Then test ;) if it works.