Sporadic USB protocol error on calling XUD_GetBuffer() Topic is solved

Technical questions regarding the XTC tools and programming with XMOS.
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Sporadic USB protocol error on calling XUD_GetBuffer()

Post by dsteinwe »

Hello,

I get a sporadic USB protocol error when I start a firmware update. I use dfu-utils under Linux. My code is:

Code: Select all

XUD_Result_t dfu_handler(...) {
	...
    log_debug("==== dfu_handler called.");

    if (sp.bmRequestType.Direction == USB_BM_REQTYPE_DIRECTION_H2D) {
        log_debug("==== dfu_handler; H2D; data_length: %u", sp.wLength);

        if (sp.wLength) {
            result = XUD_GetBuffer(ep0_out, data, data_length);
            log_debug("==== dfu_handler; H2D; result: %u", result);
            if (result != XUD_RES_OKAY) return result;
        }

        log_debug("==== dfu_handler; Request: %u", sp.bRequest);
        
   ...
}
I get following console output when the error happens:

Code: Select all

[DEBUG - usb_control] ==== dfu_handler called.
[DEBUG - usb_control] Request processed: DFU_GETSTATUS; status = 0, state = DFU_DOWNLOAD_IDLE
[DEBUG - usb_control] Host request:
	Result = ok
	Recipient = 0b00001 (Specific interface)
	Type = 0b01 (Class specific request)
	Direction = 0 (Host -> Dev; set)
	bRequest = 1 (0x1)
	wValue = 11 (0xB)
	wIndex = 0 (0x0)
	wLength = 64 (0x40)
[DEBUG - usb_control] ==== dfu_handler called.
[DEBUG - usb_control] ==== dfu_handler; H2D; data_length: 64
That means, the thread stucks on calling XUD_GetBuffer().

I have gathered following informations:

Wireshark:

Code: Select all

host to device request:
====================
Frame 2224: 128 bytes on wire (1024 bits), 128 bytes captured (1024 bits) on interface usbmon0, id 0
USB URB
Setup Data
    bmRequestType: 0x21
    bRequest: 1
    wValue: 0x0006
    wIndex: 0 (0x0000)
    wLength: 64
    Data Fragment: 4d7959e952038f6b60fcf469d52636cdc46ea0493b34d03fc9fcdb832a9629b5b8751d6d…
   
 Response:
 =========
Frame 2225: 64 bytes on wire (512 bits), 64 bytes captured (512 bits) on interface usbmon0, id 0
USB URB
    [Source: 1.14.0]
    [Destination: host]
    URB id: 0xffff895616e316c0
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (0x02)
    Endpoint: 0x00, Direction: OUT
        0... .... = Direction: OUT (0)
        .... 0000 = Endpoint number: 0
    Device: 14
    URB bus id: 1
    Device setup request: not relevant ('-')
    Data: not present ('>')
    URB sec: 1703254218
    URB usec: 705401
    URB status: Protocol error (-EPROTO) (-71)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 2224]
    [Time from request: 0.000139000 seconds]
    Unused Setup Header
    Interval: 0
    Start frame: 0
    Copy of Transfer Flags: 0x00000000
    Number of ISO descriptors: 0
    [bInterfaceClass: Application Specific (0xfe)]
In order of the host request the function dfu_handler is called. Inside this function XUD_GetBuffer() is called. It causes the error: URB status: Protocol error (-EPROTO) (-71)

xrun --dump-state:

Code: Select all

Program received signal SIGBUS, Bus error.
[Switching to tile[1] core[4] (dual issue)]
NextTokenAfterPing () at XUD_TokenJmp.S:7
7	XUD_TokenJmp.S: No such file or directory.
	in XUD_TokenJmp.S
Current language:  auto; currently asm

***** Active Cores *****
* 10 tile[1] core[4] (dual issue)  NextTokenAfterPing () at XUD_TokenJmp.S:7
  9  tile[1] core[3] (dual issue)  output_processor_task (c_output_processor=2147682050, c_output_distributor=2147680514, i_generator=524064) at ../src/audiostreams/output_processor_task.xc:311
  8  tile[1] core[2] (dual issue)  0x00048414 in queue_next_element_sent (instance=@0x54928, c=2147680770) at /home/ds/development/workspace-xmos-dsc7.1/lib_utils/src/utils_queue.xc:36
  7  tile[1] core[1] (dual issue)  XUD_GetBuffer_Finish (c=2147683074, e=339824, datalength=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_xud/lib_xud/src/user/client/XUD_EpFunctions.c:127
  6  tile[1] core[0] (dual issue)  process_cmd (cmd=<value optimized out>, c_input_processor=<value optimized out>) at ../src/audiostreams/input_processor_task.xc:307
  5  tile[0] core[4] (dual issue)  0x00044c54 in start_task ()
  4  tile[0] core[3] (dual issue)  0x00040c84 in dfu_write (ctx=<value optimized out>, i_i2c=<value optimized out>, data=<value optimized out>) at ../src/periphery/extension_card_control.xc:391
  3  tile[0] core[2] (dual issue)  process_samples () at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_master_tx/src/i2s_master_tx.xc:173
  2  tile[0] core[1] (dual issue)  output_distributor_task (c_output_distributor=2147614978, c_spdif_tx=@0x7fbec, c_i2s_tx=2147616258, p_dac_config=263424) at ../src/periphery/output_distributor.xc:164
  1  tile[0] core[0] (dual issue)  is_wclk_level_not_matched (p_wclk=66304, p_data=@0x53d18, t=<value optimized out>, timestamp=@0x7facc, port_counter=@0x1, code_location=<value optimized out>, level=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_slave_rx/src/i2s_slave_rx.xc:56
Current language:  auto; currently c

Thread 10 (tile[1] core[4] (dual issue)):

***** Call Stack *****
Current language:  auto; currently asm
#0  NextTokenAfterPing () at XUD_TokenJmp.S:7
#1  0x0004a080 in XUD_Setup_LoadBuffer () at ./included/XUD_Token_Setup_DI.S:18
#2  0x0004a080 in XUD_Setup_LoadBuffer () at ./included/XUD_Token_Setup_DI.S:18
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

***** Disassembly *****
0x4a548 <NextTokenAfterPing+8>:	inpw (l2rus)    r11, res[r0], 0x8 *
0x4a54c <NextTokenAfterPing+12>:	shr (2rus)      r11, r11, 0x18
0x4a54e <NextTokenAfterPing+14>:	nop (0r)        
0x4a550 <NextTokenAfterPing+16>:	nop (0r)        
0x4a552 <NextTokenAfterPing+18>:	ldw (3r)        r10, r10[r11]

***** Registers *****
r0             0x80100	524544
r1             0x10500	66816
r2             0x80000	524288
r3             0x0	0
r4             0x1	1
r5             0x52e30	339504
r6             0x3334	13108
r7             0xf335	62261
r8             0x493e0	300000
r9             0xa001	40961
r10            0x513c8	332744
r11            0x0	0
cp             0x4ca78	313976
dp             0x50b90	330640
sp             0x7b330	504624
lr             0x4a080	303232	 XUD_Setup_LoadBuffer + 4
pc             0x4a548	304456	 NextTokenAfterPing + 8
sr             0x19b	411
spc            0x4a548	304456	 NextTokenAfterPing + 8
ssr            0x1c3	451
et             0x0	0
ed             0x10600	67072
sed            0x10400	66560
kep            0x49d80	302464
ksp            0x4a548	304456

Thread 9 (tile[1] core[3] (dual issue)):

***** Call Stack *****
#0  output_processor_task (c_output_processor=2147682050, c_output_distributor=2147680514, i_generator=524064) at ../src/audiostreams/output_processor_task.xc:311
#1  0x000411d5 in __main__main_tile_1_task_14 (frame=0x80030102) at ../src/main.xc:357
Backtrace stopped: frame did not save the PC
Current language:  auto; currently c

***** Disassembly *****
0x41fd4 <output_processor_task+1284>:	waiteu (0r)      *
0x41fd6 <output_processor_task+1286>:	nop (0r)        
0x41fd8 <event_processor_task>:	nop (0r)        
0x41fda <event_processor_task+2>:	dualentsp (u6)  0x1a
0x41fdc <event_processor_task+4>:	std (l2rus)     r5, r4, sp[0x9]

***** Registers *****
r0             0x80030102	-2147286782
r1             0x2	2
r2             0x7b4bc	505020
r3             0x6	6
r4             0x54454	345172
r5             0x80030102	-2147286782
r6             0x80030702	-2147285246
r7             0x0	0
r8             0x1	1
r9             0x54464	345188
r10            0xcccccccd	-858993459
r11            0x0	0
cp             0x4ca78	313976
dp             0x50b90	330640
sp             0x7b568	505192
lr             0x41fcc	270284	 _Soutput_processor_task_0 + 1276
pc             0x41fd4	270292	 _Soutput_processor_task_0 + 1284
sr             0x141	321
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x80030702	-2147285246
sed            0x0	0
kep            0x49d80	302464
ksp            0x41fd4	270292

Thread 8 (tile[1] core[2] (dual issue)):

***** Call Stack *****
#0  0x00048414 in queue_next_element_sent (instance=@0x54928, c=2147680770) at /home/ds/development/workspace-xmos-dsc7.1/lib_utils/src/utils_queue.xc:36
#1  0x00042611 in process_usb_control_cmd () at ../src/events/event_processor_task.xc:925
#2  event_processor_task (c_usb_control=2147682562, c_extension_card_control=2147680770, c_input_processor=2147681282, c_output_processor=2147681794, p_mclk2_counter=65536, p_mclk2=<value optimized out>, p_out_extensions_enabled=68864, p_pwr_peri_in_enabled=<value optimized out>, i_generator=524088, c_out_audiostream=2147683586, c_in_interrupt=2147685122, c_in_feedback=2147684610, mclk2=<value optimized out>, c_sof=<value optimized out>, p_pwr_peri_out_enabled=<value optimized out>, p_compatibility_mode_enabled=<value optimized out>) at ../src/events/event_processor_task.xc:847
#3  0x00041145 in __main__main_tile_1_task_13 (frame=0x54928) at ../src/main.xc:344
Backtrace stopped: frame did not save the PC

***** Disassembly *****
0x48414 <queue_next_element_sent+8>:	nop (0r)        
0x48416 <queue_next_element_sent+10>:	ldw (2rus)      r3, r0[0x4]
0x48418 <queue_next_element_sent+12>:	ldc (ru6)       r2, 0x0
0x4841a <queue_next_element_sent+14>:	ldw (2rus)      r11, r0[0x3]
0x4841c <queue_next_element_sent+16>:	lsu (3r)        r4, r3, r11

***** Registers *****
r0             0x54928	346408
r1             0x80030202	-2147286526
r2             0x1	1
r3             0x0	0
r4             0x301	769
r5             0x80030402	-2147286014
r6             0x80030202	-2147286526
r7             0x80030902	-2147284734
r8             0x80030602	-2147285502
r9             0x0	0
r10            0x80031302	-2147282174
r11            0x425c8	271816
cp             0x4ca78	313976
dp             0x50b90	330640
sp             0x7b720	505632
lr             0x42610	271888	 _Sevent_processor_task_0 + 1592
pc             0x48414	295956	 queue_next_element_sent + 8
sr             0x100	256
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x80031702	-2147281150
sed            0x0	0
kep            0x49d80	302464
ksp            0x48414	295956

Thread 7 (tile[1] core[1] (dual issue)):

***** Call Stack *****
#0  XUD_GetBuffer_Finish (c=2147683074, e=339824, datalength=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_xud/lib_xud/src/user/client/XUD_EpFunctions.c:127
#1  XUD_GetBuffer (e=339824, buffer=0x7bc98 "0x6)\n\twIndex = 0 (0x0)\n\twLength = 64 (0x40)\npecific request)�\026r\033", datalength=0x7bcd8) at /home/ds/development/workspace-xmos-dsc7.1/lib_xud/lib_xud/src/user/client/XUD_EpFunctions.c:193
#2  0x00044e24 in dfu_handler (ep0_out=339824, ep0_in=@0x7bdb4, sp=@0x7bdb8, c_usb_control=2147682306, c_dfu=<value optimized out>, port_out_optical_enabled=68352, i_generator=524112, port_out_dac_enabled=0) at ../src/usb/control/request_handler_dfu.xc:423
#3  0x0004560d in usb_control_task (c_ep0_out=<value optimized out>, c_ep0_in=<value optimized out>, c_usb_control=2147682306, c_dfu=2147681026, port_out_dac_enabled=65792, port_out_optical_enabled=68352, i_generator=2954197179) at ../src/usb/control/usb_control_task.xc:71
#4  0x00040fc9 in __main__main_tile_1_task_12 (frame=0x0) at ../src/main.xc:309
Backtrace stopped: frame did not save the PC
Current language:  auto; currently minimal

***** Disassembly *****
0x40708 <XUD_GetBuffer+68>:	testct (2r)     r6, res[r5] *
0x4070a <XUD_GetBuffer+70>:	nop (0r)        
0x4070c <XUD_GetBuffer+72>:	bt (lru6)       r6, 0x12
0x40710 <XUD_GetBuffer+76>:	in (2r)         r6, res[r5] *
0x40712 <XUD_GetBuffer+78>:	nop (0r)        

***** Registers *****
r0             0x0	0
r1             0x7bc98	507032
r2             0x7bcd8	507096
r3             0x52f70	339824
r4             0x1e	30
r5             0x80030b02	-2147284222
r6             0x7bdb8	507320
r7             0x10b00	68352
r8             0x0	0
r9             0x2	2
r10            0x80030802	-2147284990
r11            0xffffffff	-1
cp             0x4ca78	313976
dp             0x50b90	330640
sp             0x7bc68	506984
lr             0x44e24	282148	 _Sdfu_handler_0 + 184
pc             0x40708	263944	 XUD_GetBuffer + 68
sr             0x140	320
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x80030302	-2147286270
sed            0x0	0
kep            0x49d80	302464
ksp            0x40708	263944

Thread 6 (tile[1] core[0] (dual issue)):

***** Call Stack *****
#0  process_cmd (cmd=<value optimized out>, c_input_processor=<value optimized out>) at ../src/audiostreams/input_processor_task.xc:307
#1  input_processor_task (c_in_audiostream=2147685634, c_input_processor=2147681538, c_i2s=2147680258) at ../src/audiostreams/input_processor_task.xc:227
#2  0x00041225 in __main__main_tile_1_task_14 (frame=0x7dd80) at ../src/main.xc:361
#3  0x0004aef8 in __start_other_cores ()
#4  0x00040e29 in __main__main_tile_1 ()
#5  0x0004ab28 in main ()
Current language:  auto; currently c

***** Disassembly *****
0x41308 <input_processor_task+156>:	waiteu (0r)      *
0x4130a <input_processor_task+158>:	nop (0r)        
0x4130c <input_processor_task+160>:	in (2r)         r1, res[r5] *
0x4130e <input_processor_task+162>:	nop (0r)        
0x41310 <input_processor_task+164>:	bf (lru6)       r1, 0xc

***** Registers *****
r0             0x0	0
r1             0x0	0
r2             0x0	0
r3             0x0	0
r4             0x80030002	-2147287038
r5             0x80030502	-2147285758
r6             0x80031502	-2147281662
r7             0x0	0
r8             0x54434	345140
r9             0x0	0
r10            0x10624dd3	274877907
r11            0x41898	268440
cp             0x4ca78	313976
dp             0x50b90	330640
sp             0x7bfa0	507808
lr             0x41368	267112	 input_processor_task + 252
pc             0x41308	267016	 input_processor_task + 156
sr             0x141	321
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x80030502	-2147285758
sed            0x0	0
kep            0x49d80	302464
ksp            0x41308	267016

Thread 5 (tile[0] core[4] (dual issue)):

***** Call Stack *****
#0  0x00044c54 in start_task ()
#1  0x00044ab5 in spdif_multi_tx_shared_mode_task (c_spdif_tx=<value optimized out>, p_spdif_tx=<value optimized out>, cb_mclk=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_spdif_multi_tx/src/spdif_multi_tx.xc:348
#2  0x00040911 in __main__main_tile_0_task_5 (frame=0x7fbc0) at ../src/main.xc:222
#3  0x0004714c in __start_core ()

***** Disassembly *****
0x44c54 <start_task+80>:	testct (2r)     r0, res[r6] *
0x44c56 <start_task+82>:	nop (0r)        
0x44c58 <start_task+84>:	bf (lru6)       r0, 0x1
0x44c5c <start_task+88>:	chkct (rus)     res[r6], 0x1 *
0x44c5e <start_task+90>:	nop (0r)        

***** Registers *****
r0             0x1	1
r1             0x1	1
r2             0x17	23
r3             0xb	11
r4             0x0	0
r5             0x2edff	191999
r6             0x80020502	-2147351294
r7             0x0	0
r8             0x0	0
r9             0x53d28	343336
r10            0x0	0
r11            0x17	23
cp             0x48108	295176
dp             0x53458	341080
sp             0x7f540	521536
lr             0x44d78	281976	 start_task + 372
pc             0x44c54	281684	 start_task + 80
sr             0x140	320
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x0	0
sed            0x0	0
kep            0x45b00	285440
ksp            0x44c54	281684

Thread 4 (tile[0] core[3] (dual issue)):

***** Call Stack *****
#0  0x00040c84 in dfu_write (ctx=<value optimized out>, i_i2c=<value optimized out>, data=<value optimized out>) at ../src/periphery/extension_card_control.xc:391
#1  process_request (c_dfu=<value optimized out>, request=<value optimized out>) at ../src/periphery/extension_card_control.xc:908
#2  extension_card_control_task (c_extension_card_control=<value optimized out>, c_dfu=2147615490, i_i2c=524112, p_mclk_config=262144, p_interrupt=872436429, p_reset=<value optimized out>) at ../src/periphery/extension_card_control.xc:1024
#3  0x00040821 in __main__main_tile_0_task_3 (frame=0x80020202) at ../src/main.xc:199
Backtrace stopped: frame did not save the PC

***** Disassembly *****
0x40c84 <extension_card_control_task+456>:	nop (0r)        
0x40c86 <extension_card_control_task+458>:	ldw (2rus)      r11, r11[0x0]
0x40c88 <extension_card_control_task+460>:	sub (3r)        r8, r11, r3
0x40c8a <extension_card_control_task+462>:	nop (0r)        
0x40c8c <extension_card_control_task+464>:	lss (3r)        r10, r4, r8

***** Registers *****
r0             0x80020202	-2147352062
r1             0x0	0
r2             0x0	0
r3             0xa940aaa4	-1455379804
r4             0x7fffffff	2147483647
r5             0x301	769
r6             0x0	0
r7             0x1	1
r8             0x0	0
r9             0x1	1
r10            0x0	0
r11            0x7f1a8	520616
cp             0x48108	295176
dp             0x53458	341080
sp             0x7eef8	519928
lr             0x40be4	265188	 _Sextension_card_control_task_0 + 296
pc             0x40c84	265348	 _Sextension_card_control_task_0 + 456
sr             0x100	256
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x80020302	-2147351806
sed            0x0	0
kep            0x45b00	285440
ksp            0x40c84	265348

Thread 3 (tile[0] core[2] (dual issue)):

***** Call Stack *****
#0  process_samples () at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_master_tx/src/i2s_master_tx.xc:173
#1  configure_and_process (c_i2s_tx=<value optimized out>, cb_bclk=<value optimized out>, p_i2s_wclk=<value optimized out>, p_i2s_bclk=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_master_tx/src/i2s_master_tx.xc:151
#2  process_command (c_i2s_tx=2147616514, cb_bclk=<value optimized out>, p_i2s_data=<value optimized out>, p_i2s_bclk=67584, p_i2s_wclk=68352) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_master_tx/src/i2s_master_tx.xc:181
#3  0x00043ff5 in i2s_master_tx_shared_mode_task (c_i2s_tx=<value optimized out>, p_i2s_bclk=<value optimized out>, p_i2s_wclk=<value optimized out>, p_i2s_data=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_master_tx/src/i2s_master_tx.xc:211
#4  0x00040995 in __main__main_tile_0_task_6 (frame=0x7fbc0) at ../src/main.xc:234
#5  0x000464d8 in __start_other_cores ()
#6  0x00040a21 in __main__main_tile_0_task_4 (frame=<value optimized out>) at ../src/main.xc:215
#7  0x0004714c in __start_core ()

***** Disassembly *****
0x44278 <process_command+568>:	testct (2r)     r0, res[r5] *
0x4427a <process_command+570>:	nop (0r)        
0x4427c <process_command+572>:	bf (lru6)       r0, 0x1
0x44280 <process_command+576>:	chkct (rus)     res[r5], 0x1 *
0x44282 <process_command+578>:	nop (0r)        

***** Registers *****
r0             0x1	1
r1             0x2	2
r2             0xbb80	48000
r3             0x23281	144001
r4             0x10800	67584
r5             0x80020702	-2147350782
r6             0x0	0
r7             0x10b00	68352
r8             0x10900	67840
r9             0x80000000	-2147483648
r10            0x55555555	1431655765
r11            0xbb80	48000
cp             0x48108	295176
dp             0x53458	341080
sp             0x7f6f8	521976
lr             0x43ff4	278516	 i2s_master_tx_shared_mode_task + 68
pc             0x44278	279160	 process_command + 568
sr             0x140	320
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x0	0
sed            0x0	0
kep            0x45b00	285440
ksp            0x44278	279160

Thread 2 (tile[0] core[1] (dual issue)):

***** Call Stack *****
#0  output_distributor_task (c_output_distributor=2147614978, c_spdif_tx=@0x7fbec, c_i2s_tx=2147616258, p_dac_config=263424) at ../src/periphery/output_distributor.xc:164
#1  0x0004088d in __main__main_tile_0_task_3 (frame=0x7fbc0) at ../src/main.xc:206
#2  0x0004714c in __start_core ()

***** Disassembly *****
0x439b0 <output_distributor_task+160>:	waiteu (0r)      *
0x439b2 <output_distributor_task+162>:	nop (0r)        
0x439b4 <output_distributor_task+164>:	nop (0r)        
0x439b6 <output_distributor_task+166>:	ldw (ru6)       r0, sp[0x9]
0x439b8 <output_distributor_task+168>:	setd (r2r)      res[r8], r0

***** Registers *****
r0             0x80020602	-2147351038
r1             0x2	2
r2             0xbb80	48000
r3             0x1	1
r4             0x40500	263424
r5             0x0	0
r6             0x0	0
r7             0x80020102	-2147352318
r8             0x101	257
r9             0x1	1
r10            0x80020602	-2147351038
r11            0x43980	276864
cp             0x48108	295176
dp             0x53458	341080
sp             0x7f878	522360
lr             0x43b04	277252	 output_distributor_task + 500
pc             0x439b0	276912	 output_distributor_task + 160
sr             0x141	321
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x80020102	-2147352318
sed            0x0	0
kep            0x45b00	285440
ksp            0x439b0	276912

Thread 1 (tile[0] core[0] (dual issue)):

***** Call Stack *****
#0  is_wclk_level_not_matched (p_wclk=66304, p_data=@0x53d18, t=<value optimized out>, timestamp=@0x7facc, port_counter=@0x1, code_location=<value optimized out>, level=<value optimized out>) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_slave_rx/src/i2s_slave_rx.xc:56
#1  0x00044554 in get_stream_properties (t=<value optimized out>, sample_rate=@0xd804f000, p_data=@0x53d18, p_wclk=66304) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_slave_rx/src/i2s_slave_rx.xc:83
#2  i2s_slave_multi_rx_task (c_i2s=2147614722, cb_bclk=<value optimized out>, p_bclk=<value optimized out>, p_wclk=66304, p_data=@0x53d18) at /home/ds/development/workspace-xmos-dsc7.1/lib_i2s_slave_rx/src/i2s_slave_rx.xc:273
#3  0x00040abd in extension_card_control_task (c_extension_card_control=66304, c_dfu=343320, i_i2c=1, p_mclk_config=522956, p_interrupt=2, p_reset=<value optimized out>) at ../src/periphery/extension_card_control.xc:945
Backtrace stopped: frame did not save the PC

***** Disassembly *****
0x44738 <is_wclk_level_not_matched+76>:	waiteu (0r)      *
0x4473a <is_wclk_level_not_matched+78>:	nop (0r)        
0x4473c <is_wclk_level_not_matched+80>:	getts (2r)      r11, res[r0]
0x4473e <is_wclk_level_not_matched+82>:	ldw (ru6)       r2, sp[0x3]
0x44740 <is_wclk_level_not_matched+84>:	in (2r)         r0, res[r0] *

***** Registers *****
r0             0x10300	66304
r1             0x53d18	343320
r2             0x1	1
r3             0x7facc	522956
r4             0xa9499ff3	-1454792717
r5             0x7fac4	522948
r6             0x0	0
r7             0x1	1
r8             0x6	6
r9             0x7facc	522956
r10            0x10300	66304
r11            0x44764	280420
cp             0x48108	295176
dp             0x53458	341080
sp             0x7fa80	522880
lr             0x44554	279892	 _Si2s_slave_multi_rx_task_0 + 308
pc             0x44738	280376	 is_wclk_level_not_matched + 76
sr             0x141	321
spc            0x0	0
ssr            0x0	0
et             0x0	0
ed             0x10300	66304
sed            0x0	0
kep            0x45b00	285440
ksp            0x44738	280376
Current language:  auto; currently asm
The protocol error only occurs to the dfu. All other USB communications works fine even after hours or days. I have the problem with lib_xud 2.2.1 and 2.2.4.

Currently, I have no idea, how to fix this error. I'm looking forward to your suggestions!
View Solution
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

I have added "-save-temps -fcomment-asm -fverbose-asm" to the xcc parameters. After it I had found the file "XUD_EpFunctions.c" inside "lib_xud". I have added "#include <stdio.h>" and modified following functions with some printf's:

Code: Select all

XUD_Result_t XUD_GetBuffer_Finish(chanend c, XUD_ep e, unsigned *datalength)
{   // NOCOVER
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    unsigned length;
    unsigned lengthTail;
    unsigned isReset;

    printf("************* f1\n");
    /* Wait for XUD response */
    asm volatile("testct %0, res[%1]" : "=r"(isReset) : "r"(c));
    printf("************* f2\n");

    if(isReset)
    {
        printf("************* f3\n");
        return XUD_RES_RST;
    }

    printf("************* f4\n");
    /* Input packet length (words) */
    asm volatile("in %0, res[%1]" : "=r"(length) : "r"(c));

    printf("************* f5\n");
    /* Input tail length (bytes) */
    asm volatile("int %0, res[%1]" : "=r"(lengthTail) : "r"(c));

    printf("************* f6\n");
    /* Bits to bytes */
    lengthTail >>= 3;

    /* Words to bytes */
    length <<= 2;

    /* -2 length correction for CRC */
    *datalength = length + lengthTail - 2;

    /* Load received PID */
    unsigned receivedPid = ep->actualPid;

    /* Check received PID vs expected PID */
    if(receivedPid != ep->pid)
    {
        *datalength = 0; /* Extra safety measure */
        printf("************* f7\n");
        return XUD_RES_ERR;
    }

    /* ISO == 0 */
    if(ep->epType != XUD_EPTYPE_ISO)
    {
#ifdef __XS2A__
        ep->pid ^= 0x8;
#else
        ep->pid ^= 0x88;
#endif
    }

    printf("************* f8\n");
    return XUD_RES_OKAY;
}  // NOCOVER

XUD_Result_t XUD_DoSetRequestStatus(XUD_ep ep_in)
{
    unsigned char tmp[8];

    /* Send 0 length packet */
    return XUD_SetBuffer(ep_in, tmp, 0);
}

XUD_Result_t XUD_GetBuffer(XUD_ep e, unsigned char buffer[], unsigned *datalength)
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    while(1)
    {
        printf("************* a\n");
        XUD_Result_t result = XUD_GetBuffer_Start(ep, buffer);
        printf("************* b\n");

        if(result == XUD_RES_RST)
        {
            printf("************* c\n");
            return XUD_RES_RST;
        }

        result = XUD_GetBuffer_Finish(ep->client_chanend, e, datalength);
        printf("************* d\n");

        /* If error (e.g. bad PID seq) try again */
        if(result != XUD_RES_ERR)
        {
            printf("************* e\n");
            return result;
        }
        printf("************* f\n");
    }
}
I have also add a further printf and fflush to my function "dfu_handler()" after calling "XUD_GetBuffer()":

Code: Select all

            result = XUD_GetBuffer(ep0_out, data, data_length);
            log_info("==== dfu_handler; H2D; result: %u", result);
            printf("============= ?????\n");
            fflush(stdout);
Now, I get following output on the protocol error:

Code: Select all

[INFO - usb_control] ==== dfu_handler called.
[INFO - usb_control] ==== dfu_handler; H2D; data_length: 64
************* a
************* b
************* f1
************* f2
************* f4
************* f5
************* f6
************* f8
************* d
************* e
[INFO - usb_control] ==== dfu_handler; H2D; result: 0
============= ?????
[INFO - usb_control] ==== dfu_handler; Request: 1
[DEBUG - firmware_update] total read: 128; start: 0, size 64
[DEBUG - firmware_update] ID_CONTINUE
[INFO - usb_control] ==== dfu_handler called.
************* a
************* b
************* f1
************* f2
************* f4
************* f5
************* f6
************* f8
************* d
************* e
[INFO - usb_control] ==== dfu_handler called.
[INFO - usb_control] DFU_RESPONSE_WRITTEN_OK
************* a
************* b
************* f1
************* f2
************* f4
************* f5
************* f6
************* f8
************* d
************* e
[INFO - usb_control] ==== dfu_handler called.
************* a
************* b
************* f1
************* f2
************* f4
************* f5
************* f6
************* f8
************* d
************* e
In my eyes, this output should not be possible. After the line "[INFO - usb_control] ==== dfu_handler called." the lib_xud function "XUD_GetBuffer()" is called. It is successully called, because it reaches the lines "************* f8" and "************* e". But the output "============= ?????" does not appear, even I force it with calling "fflush()". Any ideas are welcome.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

Hm, it may be, that printf per xscope has no guarantee, when the output occurs; even not with "fflush".

Probably, calling "xrun --dump-state" is the only sure way to identify the problematic code location.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

Small update: I could not reproduce the error with the module lib_xud in version 2.2.0. As of version 2.2.1, the error occurs. Currently I suspect that this is not a bug in the module, but simply the runtime behaviour of the module has changed. But I still have to verify this thesis.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

It's not a problem of the responsiveness of my dfu implementation. The requests are always answered below 80us. AFAIK, the limit was about 60ms per request.

I have also commented out all my dfu code. The problem still occurs. Very strange ...

At the moment, I use 2.2.0 instead of 2.2.4 until I have a better solution.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

I have also problems with the version 2.2.0. The difference is, when the dfu problem happens. When I use 2.2.4, I can reproduce the problem after starting the firmware about 4-18s. Mostly at 4-5s. When I use 2.2.0, I have a problem with dfu after the firmware is running more than one hour. Maybe, that the problems occurs earlier or later with this version.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

Finally, I have located the line in XUD_EpFunctions.c, that locks the thread. It is the line in the function XUD_GetBuffer_Finish:

Code: Select all

asm volatile("testct %0, res[%1]" : "=r"(isReset) : "r"(c));
Because the log output wasn't appropriated (read above), I have found another method to identify the blocking instruction. This is, how I modified XUD_EpFunctions.c

Code: Select all

// Copyright 2021-2023 XMOS LIMITED.
// This Software is subject to the terms of the XMOS Public Licence: Version 1.

#include "xud.h"
#include "XUD_USB_Defines.h"

extern XUD_ep_info ep_info[USB_MAX_NUM_EP];

volatile unsigned ds_status = 0;

void XUD_ResetEpStateByAddr(unsigned epAddr)
{
    unsigned pid = USB_PIDn_DATA0;

#if defined(__XS2A__)
    /* Check IN bit of address */
    if((epAddr & 0x80) == 0)
    {
        pid = USB_PID_DATA0;
    }
#endif

    if(epAddr & 0x80)
    {
        epAddr &= 0x7F;
        epAddr += USB_MAX_NUM_EP_OUT;
    }

    XUD_ep_info *ep = &ep_info[epAddr];
    ep->pid = pid;
}

void XUD_SetStallByAddr(int epNum)
{
    if(epNum & 0x80)
    {
        epNum &= 0x7f;
        epNum += 16;
    }

    XUD_ep_info *ep = &ep_info[epNum];

    unsigned *epReadyEntry = (unsigned *)ep->array_ptr;

    if(*epReadyEntry != 0)
    {
        /* Mark EP as not ready (and save that it was ready at Halting */
        ep->saved_array_ptr = *epReadyEntry;
        *epReadyEntry = 0;
    }
    ep->halted = USB_PIDn_STALL;
}

void XUD_SetStall(XUD_ep e)
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    XUD_SetStallByAddr(ep->epAddress);
}

void XUD_ClearStallByAddr(int epNum)
{
    unsigned handshake = USB_PIDn_NAK;

    /* Reset data PID */
    XUD_ResetEpStateByAddr(epNum);

    if(epNum & 0x80)
    {
        epNum &= 0x7F;
        epNum += USB_MAX_NUM_EP_OUT;
        handshake = 0;
    }

    XUD_ep_info *ep = &ep_info[epNum];

    /* Re-mark as ready if was ready before halting */
    if(ep->saved_array_ptr != 0)
    {
        unsigned *epReadyEntry = (unsigned *)ep->array_ptr;
        *epReadyEntry = ep->saved_array_ptr;
        ep->saved_array_ptr = 0;
    }

    /* Mark EP as un-halted */
    ep->halted = handshake;
}

void XUD_ClearStall(XUD_ep e)
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    XUD_ClearStallByAddr(ep->epAddress);
}

/* ignoreHalted should only be used for Setup data */
static inline XUD_Result_t XUD_GetBuffer_Start(volatile XUD_ep_info *ep, unsigned char buffer[])
{
    ds_status = 10;
    /* If EP is marked as halted do not mark as ready.. */
    do
    {
        ds_status = 11;
        /* Check if we missed a reset */
        if(ep->resetting)
        {
            ds_status = 12;
            return XUD_RES_RST;
        }
    }
    while(ep->halted == USB_PIDn_STALL);
    ds_status = 14;

    /* Store buffer address in EP structure */
    ep->buffer = (unsigned) &buffer[0];
    ds_status = 15;

    /* Mark EP as ready */
    unsigned * array_ptr = (unsigned *)ep->array_ptr;
    ds_status = 16;
    *array_ptr = (unsigned) ep;
    ds_status = 17;

    return XUD_RES_OKAY;
}

XUD_Result_t XUD_GetBuffer_Finish(chanend c, XUD_ep e, unsigned *datalength)
{   // NOCOVER
    ds_status = 100;
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    unsigned length;
    unsigned lengthTail;
    unsigned isReset;

    ds_status = 101;
    /* Wait for XUD response */
    asm volatile("testct %0, res[%1]" : "=r"(isReset) : "r"(c));
    ds_status = 102;

    if(isReset)
    {
        ds_status = 103;
        return XUD_RES_RST;
    }

    ds_status = 104;
    /* Input packet length (words) */
    asm volatile("in %0, res[%1]" : "=r"(length) : "r"(c));

    ds_status = 105;
    /* Input tail length (bytes) */
    asm volatile("int %0, res[%1]" : "=r"(lengthTail) : "r"(c));

    ds_status = 106;
    /* Bits to bytes */
    lengthTail >>= 3;

    ds_status = 107;
    /* Words to bytes */
    length <<= 2;

    ds_status = 108;
    /* -2 length correction for CRC */
    *datalength = length + lengthTail - 2;

    ds_status = 109;
    /* Load received PID */
    unsigned receivedPid = ep->actualPid;

    ds_status = 110;
    /* Check received PID vs expected PID */
    if(receivedPid != ep->pid)
    {
        *datalength = 0; /* Extra safety measure */
        ds_status = 111;
        return XUD_RES_ERR;
    }

    ds_status = 112;
    /* ISO == 0 */
    if(ep->epType != XUD_EPTYPE_ISO)
    {
#ifdef __XS2A__
        ds_status = 113;
        ep->pid ^= 0x8;
#else
        ds_status = 114;
        ep->pid ^= 0x88;
#endif
    }

    ds_status = 115;
    return XUD_RES_OKAY;
}  // NOCOVER

XUD_Result_t XUD_DoSetRequestStatus(XUD_ep ep_in)
{
    unsigned char tmp[8];

    /* Send 0 length packet */
    return XUD_SetBuffer(ep_in, tmp, 0);
}

unsigned get_ds_status() {
    return ds_status;
}

XUD_Result_t XUD_GetBuffer(XUD_ep e, unsigned char buffer[], unsigned *datalength)
{
    ds_status = 1;
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;
    ds_status = 2;

    while(1)
    {
        ds_status = 3;
        XUD_Result_t result = XUD_GetBuffer_Start(ep, buffer);

        ds_status = 4;
        if(result == XUD_RES_RST)
        {
            ds_status = 0;
            return XUD_RES_RST;
        }

        ds_status = 5;
        result = XUD_GetBuffer_Finish(ep->client_chanend, e, datalength);
        ds_status = 6;

        /* If error (e.g. bad PID seq) try again */
        if(result != XUD_RES_ERR)
        {
            ds_status = 0;
            return result;
        }
    }
}

int XUD_SetReady_Out(XUD_ep e, unsigned char buffer[])
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    return XUD_GetBuffer_Start(ep, buffer);
}

void XUD_GetData_Select(chanend c, XUD_ep e, unsigned *datalength, XUD_Result_t *result)
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    *result = XUD_GetBuffer_Finish(ep->client_chanend, e, datalength);
}

XUD_Result_t XUD_GetSetupBuffer(XUD_ep e, unsigned char buffer[], unsigned *datalength)
{
    volatile XUD_ep_info *ep = (XUD_ep_info*) e;
    unsigned isReset;
    unsigned length;
    unsigned lengthTail;

    /* Check if we missed a reset */
    if(ep->resetting)
    {
        return XUD_RES_RST;
    }

    /* Store buffer address in EP structure */
    ep->buffer = (unsigned) &buffer[0];

    /* Mark EP as ready for SETUP data */
    unsigned * array_ptr_setup = (unsigned *)ep->array_ptr_setup;
    *array_ptr_setup = (unsigned) ep;

    /* Wait for XUD response */
    asm volatile("testct %0, res[%1]" : "=r"(isReset) : "r"(ep->client_chanend));

    if(isReset)
    {
        return XUD_RES_RST;
    }

    /* Input packet length (words) */
    asm volatile("in %0, res[%1]" : "=r"(length) : "r"(ep->client_chanend));

    /* Input tail length (bytes) */
    /* TODO Check CT vs T */
    asm volatile("inct %0, res[%1]" : "=r"(lengthTail) : "r"(ep->client_chanend));

    /* Reset PID toggling on receipt of SETUP (both IN and OUT) */
#ifdef __XS2A__
    ep->pid = USB_PID_DATA1;
#else
    ep->pid = USB_PIDn_DATA1;
#endif

    /* Reset IN EP PID */
    XUD_ep_info *ep_in = (XUD_ep_info*) ((unsigned)ep + (USB_MAX_NUM_EP_OUT * sizeof(XUD_ep_info)));
    ep_in->pid = USB_PIDn_DATA1;

    /* TODO check that this is the case */
    *datalength = 8;

    return XUD_RES_OKAY;
}

XUD_Result_t XUD_SetBuffer_Start(XUD_ep e, unsigned char buffer[], unsigned datalength)
{   // NOCOVER
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    while(1)
    {
        /* Check if we missed a reset */
        if(ep->resetting)
        {
            return XUD_RES_RST;
        }

        /* If EP is marked as halted do not mark as ready.. */
        if(ep->halted != USB_PIDn_STALL)
        {
            break;
        }
    }

    int lengthWords = datalength >> 2;
    unsigned lengthTail = (datalength << 3) & 0x1f; // zext(5)?

    if((lengthTail == 0) && (lengthWords != 0))
    {
        lengthWords -= 1;
        lengthTail = 32;
    }

    /* Store end of buffer address in EP structure */
    ep->buffer = (unsigned) &buffer[0] + (lengthWords * 4);

    /* XUD uses negative index */
    lengthWords *= -1;
    ep->actualPid = lengthWords; /* Re-use of actualPid entry - TODO rename */
    ep->tailLength = lengthTail;

    unsigned * array_ptr = (unsigned *)ep->array_ptr;
    *array_ptr = (unsigned) ep;

    return XUD_RES_OKAY;
}

XUD_Result_t XUD_SetBuffer_Finish(chanend c, XUD_ep e)
{   // NOCOVER
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;
    unsigned isReset;
    unsigned tmp;

    /* Wait for XUD response */
    asm volatile("testct %0, res[%1]" : "=r"(isReset) : "r"(ep->client_chanend));

    if(isReset)
    {
        return XUD_RES_RST;
    }

    /* Data sent okay */
    asm volatile("in %0, res[%1]" : "=r"(tmp) : "r"(ep->client_chanend));

    /* Don't do any PID toggling for Iso EP's */
    if(ep->epType != XUD_EPTYPE_ISO)
    {
        ep->pid ^= 0x88;
    }

    return XUD_RES_OKAY;
}   // NOCOVER

XUD_Result_t XUD_SetBuffer(XUD_ep e, unsigned char buffer[], unsigned datalength)
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    XUD_Result_t result = XUD_SetBuffer_Start(e, buffer, datalength);

    if(result == XUD_RES_RST)
    {
        return result;
    }

    return XUD_SetBuffer_Finish(ep->client_chanend, e);
}

void XUD_SetData_Select(chanend c, XUD_ep e, XUD_Result_t *result)
{
    volatile XUD_ep_info * ep = (XUD_ep_info*) e;

    *result = XUD_SetBuffer_Finish(ep->client_chanend, e);
}

XUD_Result_t XUD_SetBuffer_EpMax(XUD_ep ep_in, unsigned char buffer[], unsigned datalength, unsigned epMax)
{
    int i = 0;
    XUD_Result_t result;

    /* Note: We could encompass this in the SetData function */
    if (datalength <= epMax)
    {
        /* Datalength is less than the maximum per transaction of the EP, so just send */
        result = XUD_SetBuffer(ep_in, buffer, datalength);
        return result;
    }
    else
    {
        /* Send first packet out and reset PID */
        if((result = XUD_SetBuffer(ep_in, buffer, epMax)) != XUD_RES_OKAY)
        {
            return result;
        }

        i += epMax;
        datalength -= epMax;

        while (1)
        {
            unsigned char *bufferPtr = &buffer[i];

            if (datalength > epMax)
            {
                /* PID Automatically toggled */
                if ((result = XUD_SetBuffer(ep_in, bufferPtr, epMax)) != XUD_RES_OKAY)
                    return result;

                datalength -= epMax;
                i += epMax;
            }
            else
            {
                /* PID automatically toggled */
                if ((result = XUD_SetBuffer(ep_in, bufferPtr, datalength)) != XUD_RES_OKAY)
                    return result;

                break; //out of while loop
            }
        }
    }

    return XUD_RES_OKAY;
}
Of course, I have also added the new function get_ds_status to xud.h.

I have used another thread that calls repeatedly the new introduced function get_ds_status. If the returned value haven't changed a longer time and is greater 0, the blocking instruction is found. It was in my case always 101.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

I'm guessing the error is caused by the host. I don't think it's caused by the dfu-util tool itself, but by libusb, that is used by the tool. With libusb 1.0.26, the DFU seems to work in most cases. With libusb 1.0.25, it seems almost impossible to end the DFU. These observations are not 100% tested, but currently I don't think it's a problem of the lib_xud.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

Today, I have done some tests again. The results are very odd.

I have started ubuntu 22.04 live on an old laptop. Then, I have installed fwupd (dfu-tool) und dfu-util. Both tools finish the dfu without any problems. Then I have upgraded libusb from 1.0.25 to 1.0.26. Again, both tools work fine.

Then, I have started ubuntu 22.04 live on my working station. Again, I have installed fwupd (dfu-tool) und dfu-util. Now, the dfu fails with both tools.

Then, I have done this procedure with a celeron based nuc. Again, I can reproduce the fails.

I have no idea, where the source of the fails are.
Top
User avatar
dsteinwe
XCore Addict
Posts: 144
Joined: Wed Jun 29, 2016 8:59 am

Post by dsteinwe »

I have an update: it seems that the EP0 channel is being changed by another thread. The other thread doesn't have access to EP0, but when I set a variable within a timer event handler to a special value in the other thread at a given time interval, it seems like a control token is added to the EP0 channel. The above protocol error occurs because a control token is removed from the EP0 channel. I guess, both are caused because by memory overwriting.
Top

Return to “Development Tools and Programming”