viveris / uMTP-Responder

Lightweight USB Media Transfer Protocol (MTP) responder daemon for GNU/Linux
GNU General Public License v3.0
195 stars 53 forks source link

Incoming_packet : Read Error (-1)! on v1.0.0 #27

Closed smokeythebandit closed 4 years ago

smokeythebandit commented 5 years ago

Seems like v1.0.0 offers much improvements over previous versions, nice going!

I've tried running v1.0.0 on our iMX.6 based product, but there is an USB read error.

UMTP outputs this information:

Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] uMTP Responder
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Version: v1.0.0 compiled the Oct 21 2019@11:34:59
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] (c) 2018 - 2019 Viveris Technologies
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Add storage Projects - Root Path: /Voyager/Projects - Flags: 0x00000000
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Add storage Licenses - Root Path: /Voyager/Licenses - Flags: 0x00000000
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Device path : /dev/umtp/ep0
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB In End point path : /dev/umtp/ep1
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Out End point path : /dev/umtp/ep2
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Event End point path : /dev/umtp/ep3
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Max packet size : 0x200 bytes
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Manufacturer string : Microflown Technologies B.V.
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Product string : Voyager
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Serial string : 0000000
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Interface string : MTP
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Vendor ID : 0x1D6B
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Product ID : 0x0100
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB class ID : 0x06
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB subclass ID : 0x01
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Protocol ID : 0x01
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB Device version : 0x3008
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] USB FunctionFS Mode
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Wait for connection : 0
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Loop on disconnect : 1
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] Show hidden files : 1
Oct 21 10:35:25 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:25 - Info] inotify : yes
Oct 21 10:35:25 Voyagerk46xOO sudo[476]: pam_unix(sudo:session): session closed for user root
Oct 21 10:35:25 Voyagerk46xOO systemd[1]: Started umtp startup.
Oct 21 10:35:31 Voyagerk46xOO sudo[475]: [uMTPrd - 10:35:31 - Error] incoming_packet : Read Error (-1)!
Oct 21 10:47:07 Voyagerk46xOO sudo[475]: [uMTPrd - 10:47:07 - Error] incoming_packet : Read Error (-1)!
Oct 21 10:47:14 Voyagerk46xOO sudo[475]: [uMTPrd - 10:47:14 - Error] incoming_packet : Read Error (-1)!

Was previously working on v0.14.1 Device does show up on both Windows 10 and Debian, but neither of them can see the mounted storage. Our host device runs kernel 5.2.19 with an realtime patch.

smokeythebandit commented 5 years ago

When I change usb_max_packet_size from 0x200 to 0x100 umtp sometimes works.

jfdelnero commented 5 years ago

Can you rebuild the umtpd with the "DEBUG" flag and post the result ?

a1ien commented 5 years ago

same error

[uMTPrd - 13:24:34 - Info] USB Device path : /dev/ffs-mtp/ep0
[uMTPrd - 13:24:34 - Info] USB In End point path : /dev/ffs-mtp/ep1
[uMTPrd - 13:24:34 - Info] USB Out End point path : /dev/ffs-mtp/ep2
[uMTPrd - 13:24:34 - Info] USB Event End point path : /dev/ffs-mtp/ep3
[uMTPrd - 13:24:34 - Info] USB Max packet size : 0x200 bytes
[uMTPrd - 13:24:34 - Info] Manufacturer string : Viveris Technologies
[uMTPrd - 13:24:34 - Info] Product string : The Viveris Product !
[uMTPrd - 13:24:34 - Info] Serial string : 01234567
[uMTPrd - 13:24:34 - Info] Interface string : MTP
[uMTPrd - 13:24:34 - Info] USB Vendor ID : 0x1D6B
[uMTPrd - 13:24:34 - Info] USB Product ID : 0x0100
[uMTPrd - 13:24:34 - Info] USB class ID : 0x06
[uMTPrd - 13:24:34 - Info] USB subclass ID : 0x01
[uMTPrd - 13:24:34 - Info] USB Protocol ID : 0x01
[uMTPrd - 13:24:34 - Info] USB Device version : 0x3008
[uMTPrd - 13:24:34 - Info] USB FunctionFS Mode
[uMTPrd - 13:24:34 - Info] Wait for connection : 0
[uMTPrd - 13:24:34 - Info] Loop on disconnect : 1
[uMTPrd - 13:24:34 - Info] Show hidden files : 1
[uMTPrd - 13:24:34 - Info] inotify : yes
[uMTPrd - 13:24:34 - Debug] fill_if_descriptor:
[uMTPrd - 13:24:34 - Debug] 09 04 00 00 03 06 01 01 01                       .........        
[uMTPrd - 13:24:34 - Debug] fill_ep_descriptor:
[uMTPrd - 13:24:34 - Debug] 07 05 81 02 00 02 00                             .......          
[uMTPrd - 13:24:34 - Debug] fill_ep_descriptor:
[uMTPrd - 13:24:34 - Debug] 07 05 02 02 00 02 00                             .......          
[uMTPrd - 13:24:34 - Debug] fill_ep_descriptor:
[uMTPrd - 13:24:34 - Debug] 07 05 83 03 1C 00 06                             .......          
[uMTPrd - 13:24:34 - Debug] fill_if_descriptor:
[uMTPrd - 13:24:34 - Debug] 09 04 00 00 03 06 01 01 01                       .........        
[uMTPrd - 13:24:34 - Debug] fill_ep_descriptor:
[uMTPrd - 13:24:34 - Debug] 07 05 81 02 00 02 00                             .......          
[uMTPrd - 13:24:34 - Debug] fill_ep_descriptor:
[uMTPrd - 13:24:34 - Debug] 07 05 02 02 00 02 00                             .......          
[uMTPrd - 13:24:34 - Debug] fill_ep_descriptor:
[uMTPrd - 13:24:34 - Debug] 07 05 83 03 1C 00 06                             .......          
[uMTPrd - 13:24:34 - Debug] init_usb_mtp_gadget :
[uMTPrd - 13:24:34 - Debug] 03 00 00 00 50 00 00 00 03 00 00 00 04 00 00 00  ....P........... 
[uMTPrd - 13:24:34 - Debug] 04 00 00 00 09 04 00 00 03 06 01 01 01 07 05 81  ................ 
[uMTPrd - 13:24:34 - Debug] 02 00 02 00 07 05 02 02 00 02 00 07 05 83 03 1C  ................ 
[uMTPrd - 13:24:34 - Debug] 00 06 09 04 00 00 03 06 01 01 01 07 05 81 02 00  ................ 
[uMTPrd - 13:24:34 - Debug] 02 00 07 05 02 02 00 02 00 07 05 83 03 1C 00 06  ................ 
[uMTPrd - 13:24:34 - Debug] write string :
[uMTPrd - 13:24:34 - Debug] 02 00 00 00 16 00 00 00 01 00 00 00 01 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 09 04 4D 54 50 00 00 00 00 00 00 00 00 00 00 00  ..MTP........... 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 [ 1725.808689] read strings
00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................ 
[uMTPrd - 13:24:34 - Debug] 00 00                                            ..               
[uMTPrd - 13:24:34 - Debug] init_usb_mtp_gadget : USB config done
[uMTPrd - 13:24:34 - Debug] uMTP Responder : FunctionFS Mode - entering handle_ffs_ep0
[uMTPrd - 13:24:34 - Debug] handle_ffs_ep0 : Entering...
# ls /sys/class/udc/ > cfg/usb_gadget/g1/UDC
[uMTPrd - 13:24:42 - Debug] 1 event(s)
[uMTPrd - 13:24:42 - Debug] EP0 FFS BIND
[uMTPrd - 13:24:42 - Debug] Select without timeout
# [ 1734.040503] configfs-gadget gadget: high-speed config #1: c
[uMTPrd - 13:24:42 - Debug] 1 event(s)
[uMTPrd - 13:24:42 - Debug] EP0 FFS ENABLE
[uMTPrd - 13:24:42 - Debug] Init end point /dev/ffs-mtp/ep1 (0)
[uMTPrd - 13:24:42 - Debug] init_ep (0):
[uMTPrd - 13:24:42 - Debug] 01 00 00 00 07 05 81 02 00 02 00 07 05 81 02 00  ................ 
[uMTPrd - 13:24:42 - Debug] 02 00                                            ..               
[uMTPrd - 13:24:42 - Debug] init_ep (0): FunctionFS Mode - Don't write the endpoint descriptor.
[uMTPrd - 13:24:42 - Debug] Init end point /dev/ffs-mtp/ep2 (1)
[uMTPrd - 13:24:42 - Debug] init_ep (1):
[uMTPrd - 13:24:42 - Debug] 01 00 00 00 07 05 02 02 00 02 00 07 05 02 02 00  ................ 
[uMTPrd - 13:24:42 - Debug] 02 00                                            ..               
[uMTPrd - 13:24:42 - Debug] init_ep (1): FunctionFS Mode - Don't write the endpoint descriptor.
[uMTPrd - 13:24:42 - Debug] Init end point /dev/ffs-mtp/ep3 (2)
[uMTPrd - 13:24:42 - Debug] init_ep (2):
[uMTPrd - 13:24:42 - Debug] 01 00 00 00 07 05 83 03 1C 00 06 07 05 83 03 1C  ................ 
[uMTPrd - 13:24:42 - Debug] 00 06                                            ..               
[uMTPrd - 13:24:42 - Debug] init_ep (2): FunctionFS Mode - Don't write the endpoint descriptor.
[uMTPrd - 13:24:42 - Debug] Select without timeout
[uMTPrd - 13:24:51 - Error] incoming_packet : Read Error (-1)!
[uMTPrd - 13:24:51 - Debug] 1 event(s)
[uMTPrd - 13:24:51 - Debug] EP0 FFS DISABLE
[uMTPrd - 13:24:51 - Debug] deinit_fs_db called
[uMTPrd - 13:24:51 - Debug] Select without timeout
[ 1742.866694] configfs-gadget gadget: high-speed config #1: c
[uMTPrd - 13:24:51 - Debug] 1 event(s)
[uMTPrd - 13:24:51 - Debug] EP0 FFS ENABLE
[uMTPrd - 13:24:51 - Debug] Select without timeout
a1ien commented 5 years ago

2106863b89ee388a58cc6f4561aca8d041b42dd1 broken commit If revert all work good

a1ien commented 5 years ago

also after e0752308d6d21236b607c41450664b5bc94b422a I see many reset on usb

[  359.029142] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  364.026522] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  366.536551] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  369.026542] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  373.846474] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
jfdelnero commented 5 years ago

@a1ien : Same target ? (i.MX 6 ?)

a1ien commented 5 years ago

Yes, same target. And same kernel version. But without realtime patch

jfdelnero commented 5 years ago

Can you try to just change CONFIG_MAX_TX_USB_BUFFER_SIZE and CONFIG_MAX_RX_USB_BUFFER_SIZE to 2048 ?

a1ien commented 5 years ago

With this config

#define CONFIG_MAX_TX_USB_BUFFER_SIZE (4*512)   // Must be a multiple of 512 and less than CONFIG_READ_FILE_BUFFER_SIZE 
#define CONFIG_MAX_RX_USB_BUFFER_SIZE (4*512)

work. But low speed( around 6.7MB/s) and periodical kernel print

[  949.297272] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  951.797233] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  956.817297] usb 1-1: reset high-speed USB device number 2 using ci_hdrc
[  986.797248] usb 1-1: reset high-speed USB device number 2 using ci_hdrc

If if change CONFIG_READ_FILE_BUFFER_SIZE to 16*1024 I get seeped around 3.7MB/s and no kernel message.

jfdelnero commented 5 years ago

Ok thanks. It is quite strange that reducing CONFIG_READ_FILE_BUFFER_SIZE suppress the kernel message. It looks like there is a timing or USB buffer overflow issue in the iMX USB driver. Reducing these buffers just make uMTPrd slower and write and read data chunk size to the usb stack are lower. I am not sure yet if this a uMTPrd or a iMX USB driver issue. At least now we know the workaround. This may need to turn these build configuration into some config file options.

jfdelnero commented 4 years ago

@a1ien I have just added the possibility to set the buffers size in the config file. All is on the trunk. Can you test this version ?

a1ien commented 4 years ago

I will try this Wednesday

a1ien commented 4 years ago

With option in config I make more test. For stable work i set

usb_max_rd_buffer_size 0x200     
usb_max_wr_buffer_size 0x200  

If set to 0x400 I prosodical get usb 1-1: reset high-speed USB device number 2 using ci_hdrc But it's maybe because imx connect to hub with many usb device.

ttmms commented 4 years ago

EDIT: Sorry for confusion. Setting above mentioned buffers indeed solved the problem, I just thought they were default values since they were commented out, but I didn't read the comments very well...

I'm also getting read errors with the current master branch and default config files and starting with umtprd-ffs.sh. Connecting to Windows, I get nothing. Connecting to Linux, device is recognized with correct name but trying to open it fails (and file manager crashes). Trying to mount manually with jmtpfs gives PTP_ERROR_IO: failed to open session, trying again after resetting USB interface and eventually MtpErrorCantOpenDevice

jfdelnero commented 4 years ago

EDIT: Sorry for confusion. Setting above mentioned buffers indeed solved the problem, I just thought they were default values since they were commented out, but I didn't read the comments very well...

ok fine. I suppose you are using an iMX 6 based hardware ?