TL866II+ throwing IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT #163

Open DavidGriffith opened 4 years ago

In GitLab by @bruxy on Jan 16, 2020, 18:33

Hi, new TL866 user here. I am using Fedora 31 on x86_64.

I have updated to the latest firmware:

Found TL866II+ 04.2.110 (0x26e)

Not sure if it was done okay, because it has ended with SIGSEGV and then minipro complained something about boot mode. After the restart, I have tried to read some data as root with:

./minipro -p ATMEGA328P@DIP28 -r test4

It has ended with error message IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT:

close(6)                                = 0                                                                                                                                  
openat(AT_FDCWD, "/sys/bus/usb/devices/1-8/descriptors", O_RDONLY|O_CLOEXEC) = 6                                                                                             
read(6, "\22\1\0\2\0\0\0@\332\v\21\1\"\21\1\2\3\1\t\2 \0\1\1\4\200\372\t\4\0\0\2"..., 1024) = 50                                                                             
close(6)                                = 0                                                                                                                                  
pipe2([6, 7], O_CLOEXEC)                = 0                                                                                                                                  
fcntl(7, F_GETFL)                       = 0x1 (flags O_WRONLY)                                                                                                               
fcntl(7, F_SETFL, O_WRONLY|O_NONBLOCK)  = 0                                                                                                                                  
write(7, "\1", 1)                       = 1                                                                                                                                  
timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 8                                                                                                                
recvmsg(3, {msg_namelen=128}, 0)        = -1 EAGAIN (Resource temporarily unavailable)                                                                                       
recvmsg(3, {msg_namelen=128}, 0)        = -1 EAGAIN (Resource temporarily unavailable)                                                                                       
openat(AT_FDCWD, "/dev/bus/usb/002/010", O_RDWR|O_CLOEXEC) = 9                                                                                                               
ioctl(9, USBDEVFS_GET_CAPABILITIES, 0xb9e0d8) = 0                                                                                                                            
ioctl(9, USBDEVFS_CLAIMINTERFACE, 0x7fff60ecdbbc) = 0                                                                                                                        
clock_gettime(CLOCK_MONOTONIC, {tv_sec=425406, tv_nsec=578306327}) = 0                                                                                                       
timerfd_settime(8, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=425411, tv_nsec=578306000}}, NULL) = 0                                            
ioctl(9, USBDEVFS_SUBMITURB, 0xb8da40)  = 0                                                                                                                                  
read(6, "\1", 1)                        = 1                                                                                                                                  
poll([{fd=6, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLOUT}], 3, 60000) = 1 ([{fd=8, revents=POLLIN}])                                                        
clock_gettime(CLOCK_MONOTONIC, {tv_sec=425411, tv_nsec=579203360}) = 0                                                                                                       
ioctl(9, USBDEVFS_DISCARDURB, 0xb8da40) = 0                                                                                                                                  
timerfd_settime(8, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}, NULL) = 0                                                                         
poll([{fd=6, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLOUT}], 3, 60000) = 1 ([{fd=9, revents=POLLOUT}])                                                       
ioctl(9, USBDEVFS_REAPURBNDELAY, 0x7fff60ecd8d0) = 0                                                                                                                         
timerfd_settime(8, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}, NULL) = 0                                                                         
ioctl(9, USBDEVFS_REAPURBNDELAY, 0x7fff60ecd8d0) = -1 EAGAIN (Resource temporarily unavailable)                                                                              
write(2, "\nIO error: bulk_transfer: LIBUSB"..., 47                                                                                                                          
IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT                                                                                                                                
) = 47                                                                                                                                                                       
write(2, "IO error: expected 5 bytes but 0"..., 51IO error: expected 5 bytes but 0 bytes transferred                                                                         
) = 51                                                                                                                                                                       
exit_group(1)                           = ?

I have tried the programmer in a different port on the first PC, then on the second PC via USB3 HUB and then directly in USB2 port (during the writing of this bug report). It looks like a direct connection to USB2 works.

On the first PC, I have also tried to increase MP_USBTIMEOUT in usb_nix.c from 5000 to 50000. It gets stalled in syscall:

poll([{fd=6, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLOUT}], 3, 60000

I am curious about what to check next. The first PC is quite old AMD Athlon with 2GB RAM.

In GitLab by @bruxy on Jan 16, 2020, 18:54

As a summary of the previous post, I have tried:

AMD Athlon, 2 GB on different USB2 ports ... FAIL.
Notebook with Intel(R) Core(TM) i7-4510U, 16 GB via USB3 hub Orico ... FAIL.
Same as 2 but directly in USB2 port ... OK.

Just looks like, that minipro does not like old crappy PC :)

Still curious, if there is any option on how to make it run on that old PC on my lab bench.

Can you post exactly what you see?

In GitLab by @bruxy on Jan 16, 2020, 20:08

Hi, @DavidGriffith Thanks for the reply!

./minipro -p ATMEGA328P@DIP28 -r test4

Found TL866II+ 04.2.110 (0x26e)
Warning: Firmware is newer than expected.
  Expected  04.2.109 (0x26d)
  Found     04.2.110 (0x26e)
Chip ID OK: 0x1E950F
Reading Code...  21%

IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT
IO error: expected 5 bytes but 0 bytes transferred

I am using the latest master branch. That previous strace command is catching what is going off right before that IO error.

In GitLab by @radiomanV on Jan 17, 2020, 04:30

This is a very strange issue. I don't think that how old your machine is will make any difference.
Seems like there's an interruption during data transfer like the programmer is disconnected or is disconnecting itself from the usb port. It can also be some firmware issues but this is only a guess.

Tried this atmega328 chip on some of my old machines even older than you tried, also upgraded to the latest firmware, downgraded to an old firmware and i can't reproduce your issue.
Sure your TL866II+ is ok? Sometimes a bad usb cable can do this.

Can you try this with the official windows client? You can run it under wine.
The whole idea is to check it under a Linux environment. Here: https://github.com/radiomanV/TL866 is my github repo. See the wine section.

In GitLab by @bruxy on Jan 17, 2020, 16:34

Hi @radiomanV

I have tried your suggestion and Xgpro.exe under wine32 with setupapi.dll works fine. Actually, in the first try I had to physically disconnect the device and put it back, but then self check and also read of EEPROM went well. There is console output:

000b:fixme:winediag:__wine_start_process Wine Staging 5.0-rc5 is a testing version containing experimental patches.
000b:fixme:winediag:__wine_start_process Please mention your exact version when filing bug reports on winehq.org.
Dll Loaded.
Found Xgpro v9.16
Base Address = 0x00400000
Code section = 0x00401000,0x0022E200
Open Devices found at 0x00483E90
Close Devices found at  0x00483C80
Usb Handle found at  0x006DA730
WinUsb Handle found at  0x006E4970
Devices count found at  0x006E4830
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
Open devices.
Close devices.
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
RegisterDeviceNotifications hWnd=1007A4
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
002d:fixme:ver:GetCurrentPackageId (0x11ffefc (nil)): stub
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
0009:fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)
Close devices.
Open devices.
Close devices.
Close devices.
Open devices.
Close devices.

In GitLab by @bruxy on Jan 17, 2020, 20:18

I did few other test like disable SELinux or increase this memory buffer:

echo 256 > /sys/module/usbcore/parameters/usbfs_memory_mb

Few more information about my setup:

# lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ohci-pci/10p, 12M
    |__ Port 5: Dev 3, If 0, Class=Human Interface Device, Driver=usbhid, 1.5M
    |__ Port 6: Dev 17, If 0, Class=Vendor Specific Class, Driver=usbfs, 12M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/10p, 480M
    |__ Port 8: Dev 3, If 0, Class=Mass Storage, Driver=usb-storage, 480M

# lsusb
Bus 001 Device 003: ID 0bda:0111 Realtek Semiconductor Corp. RTS5111 Card Reader Controller
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 017: ID a466:0a53 Xingong Electronicg Co..  Xingong XGecu USB Prog.. Device
Bus 002 Device 003: ID 413c:301a Dell Computer Corp. Dell MS116 USB Optical Mouse
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

In GitLab by @radiomanV on Jan 18, 2020, 07:58

This is very interesting. When you tried the official client in wine do you tried this on the same machine which cause the error and with the same chip (mega328p)?

This:

Reading Code...  21%

IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT
IO error: expected 5 bytes but 0 bytes transferred

Tell me more. The 21% is always the same? Also the error message is always the same?
There's a bit dark here because of this:

Same as 2 but directly in USB2 port ... OK.

Seems like there's some hardware failure involved here i don't know.

I would like to see a real call stack from a gdb debugger (i'm using the Eclipse CDT to develop the minipro, i really like the debugger implementation) the strace output above doesn't tell me too much:

ioctl(9, USBDEVFS_REAPURBNDELAY, 0x7fff60ecd8d0) = -1 EAGAIN (Resource temporarily unavailable)

This looks like a communication error to me.

For example here's how reading a chip is performed:
After the initial command line parsing the action_read is called from the main function in main.c

In the action_read we decide how many sections the chip have and if there's a real disk file or a pipe. For every section the read_page_file is called.
In the read_page_file the read buffer is allocated (using malloc) and then the read_page_ram is called.

In the read_page_ram there's the actual reading. For example lets say we need to read a 2K chip. The TL866 firmware will transfer those 2048 bytes in chunks. The size of the individual chunk is defined in the database for every supported chip. This is the read_buffer_size member in the database.
So if for our device the read_buffer_size is lets say 64 bytes there should be 2048/64 = 32 data blocks (chunks).
We have a for loop here (inside the read_page_ram function). For every data block the minipro_read_block from minipro.c is called.

In the minipro_read_block we decide if the programmer used is the old TL866A or the newer TL866II+ and the appropriate function is called (by using function pointers). For example for the TL866II+ the tl866iiplus_read_block from tl866iiplus.c is called.
In the tl866iiplus_read_block there are some protocol specific inits. From here the data we send or receive we will make use of some usb transfer functions from the usb_nix.c like msg_send, msg_rcv, read_payload, write_payload.

The msg_send function calls the msg_transfer which finally sends the data by calling the libusb_bulk_transfer using the libusb framework.

Now pay attention: here (in msg_transfer) the first error is thrown: IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT. We have a timeout of 5 sec to send our message but for an unknown reason the libusb fails. So we print this timeout error message and return failure to the caller. msg_send receiving an error will throw his own error: IO error: expected 5 bytes but 0 bytes transferred.
The failure status is returned back to every function in the call stack until we get back in the main function. There are some cleanups and finally the error status is returned to the OS. This will allow us to use && for multiple commands and if something goes wrong to stop.

What's wrong here? well this: IO error: expected 5 bytes but 0 bytes transferred
We don't send a 5 bytes message anywhere in the above read chain! there are 8 byte messages, 64 bytes and so on but not 5.
There's a single function which sends a 5 bytes message: minipro_get_system_info from minipro.c which is used to read the programmer type but this function is not used in the read chain described above.

Strange eh? I really want to help you but how?

In GitLab by @bruxy on Jan 18, 2020, 18:59

Have tested it on that "broken" machine with wine32 and latest Xgpro.exe, it seems to work without any issue. I have just tried to read the chip and self-test, both is working (however, the PC is quite slow). Self-test with minipro -t is also without any problem.
The reading ends on some random percentage 2, 6, 21, 64... Biggest percentage was done with init 3 without XOrg, still not sure if something else in the FC31 system may affect that USB device. I have tried ATMEGA644 but it has stopped on 19%. Also running it with nice -20 did not have any effect. Once the minipro will crash with IO error, I need to disconnect and connect the programer back, it looks like it is getting stuck somewhere.
The usual message is IO error: expected 5 bytes but 0 bytes transferred, but I have a feeling that once or twice I have got a different number, I would say it was 8.

GDB SESSION

SIGINT, when reading get stalled on 68% and in this point 360000 ms timeout, is waiting.

gdb) run -p ATMEGA328P@DIP28 -r gdb_read
Starting program: /usr/local/src/minipro/minipro -p ATMEGA328P@DIP28 -r gdb_read
Missing separate debuginfos, use: dnf debuginfo-install glibc-2.30-8.fc31.x86_64
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff7d4a700 (LWP 939572)]
Found TL866II+ 04.2.110 (0x26e)
Warning: Firmware is newer than expected.
  Expected  04.2.109 (0x26d)
  Found     04.2.110 (0x26e)
Chip ID OK: 0x1E950F
Reading Code...  68%^C
Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7eada6f in poll () from /lib64/libc.so.6
Missing separate debuginfos, use: dnf debuginfo-install libgcc-9.2.1-1.fc31.x86_64 libusbx-1.0.22-4.fc31.x86_64 systemd-libs-243.5-1.fc31.x86_64
(gdb) bt
#0  0x00007ffff7eada6f in poll () from /lib64/libc.so.6
#1  0x00007ffff7f8a421 in handle_events.isra () from /lib64/libusb-1.0.so.0
#2  0x00007ffff7f8b62c in libusb_handle_events_timeout_completed () from /lib64/libusb-1.0.so.0
#3  0x00007ffff7f8b6d4 in libusb_handle_events_completed () from /lib64/libusb-1.0.so.0
#4  0x00007ffff7f8c009 in sync_transfer_wait_for_completion () from /lib64/libusb-1.0.so.0
#5  0x00007ffff7f8c10b in do_sync_bulk_transfer () from /lib64/libusb-1.0.so.0
#6  0x00007ffff7f8c423 in libusb_bulk_transfer () from /lib64/libusb-1.0.so.0
#7  0x000000000040bda2 in msg_transfer (handle=0x669080, buffer=0x7fffffffdd30 "9\035I", size=32, direction=128 '\200', 
    endpoint=1 '\001', bytes_transferred=0x7fffffffdcfc, timeout=360000) at usb_nix.c:126
#8  0x000000000040c446 in msg_recv (handle=0x669080, buffer=0x7fffffffdd30 "9\035I", size=32) at usb_nix.c:301
#9  0x00000000004092df in tl866iiplus_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddbf "")
    at tl866iiplus.c:441
#10 0x00000000004058d0 in minipro_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddbf "") at minipro.c:330
#11 0x000000000040e0c7 in read_page_ram (handle=0x6582a0, buf=0x65ae10 "\f\224\064", type=0 '\000', size=32768) at main.c:817
#12 0x000000000040f9ff in read_page_file (handle=0x6582a0, type=0 '\000', size=32768) at main.c:1303
#13 0x0000000000410faa in action_read (handle=0x6582a0) at main.c:1658
#14 0x0000000000412c26 in main (argc=5, argv=0x7fffffffe128) at main.c:2247

Continue and waiting for the timeout to finish (breakpoint in ubs_nix.c before fprintf):

IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT

Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7df3625 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff7df3625 in raise () from /lib64/libc.so.6
#1  0x000000000040bddb in msg_transfer (handle=0x669080, buffer=0x7fffffffdd30 "9\035I", size=32, direction=128 '\200', 
    endpoint=1 '\001', bytes_transferred=0x7fffffffdcfc, timeout=360000) at usb_nix.c:131
#2  0x000000000040c446 in msg_recv (handle=0x669080, buffer=0x7fffffffdd30 "9\035I", size=32) at usb_nix.c:301
#3  0x00000000004092df in tl866iiplus_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddbf "")
    at tl866iiplus.c:441
#4  0x00000000004058d0 in minipro_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddbf "") at minipro.c:330
#5  0x000000000040e0c7 in read_page_ram (handle=0x6582a0, buf=0x65ae10 "\f\224\064", type=0 '\000', size=32768) at main.c:817
#6  0x000000000040f9ff in read_page_file (handle=0x6582a0, type=0 '\000', size=32768) at main.c:1303
#7  0x0000000000410faa in action_read (handle=0x6582a0) at main.c:1658
#8  0x0000000000412c26 in main (argc=5, argv=0x7fffffffe128) at main.c:2247

Continue and waiting for a timeout to finish (breakpoint in ubs_nix.c after fprintf in msg_transfer):

(gdb) c
Continuing.

IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT

Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7df3625 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff7df3625 in raise () from /lib64/libc.so.6
#1  0x000000000040bddb in msg_transfer (handle=0x669080, buffer=0x7fffffffdf98 "\004\035I", size=8, direction=0 '\000', 
    endpoint=1 '\001', bytes_transferred=0x7fffffffdf68, timeout=5000) at usb_nix.c:131
#2  0x000000000040c3b9 in msg_send (handle=0x669080, buffer=0x7fffffffdf98 "\004\035I", size=8) at usb_nix.c:288
#3  0x0000000000408ab0 in tl866iiplus_end_transaction (handle=0x6582a0) at tl866iiplus.c:263
#4  0x000000000040573a in minipro_end_transaction (handle=0x6582a0) at minipro.c:292
#5  0x0000000000412cd2 in main (argc=5, argv=0x7fffffffe128) at main.c:2272
(gdb) c
Continuing.

Break point in ubs_nix.c before fprintf in msg_send:

Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7df3625 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff7df3625 in raise () from /lib64/libc.so.6
#1  0x000000000040c3d7 in msg_send (handle=0x669080, buffer=0x7fffffffdf98 "\004\035I", size=8) at usb_nix.c:291
#2  0x0000000000408ab0 in tl866iiplus_end_transaction (handle=0x6582a0) at tl866iiplus.c:263
#3  0x000000000040573a in minipro_end_transaction (handle=0x6582a0) at minipro.c:292
#4  0x0000000000412cd2 in main (argc=5, argv=0x7fffffffe128) at main.c:2272
(gdb) c
Continuing.
IO error: expected 8 bytes but 0 bytes transferred
[Thread 0x7ffff7d4a700 (LWP 939572) exited]
[Inferior 1 (process 939568) exited with code 01]
(gdb) quit

Interestingly, now it died with IO error: expected 8 bytes but 0 bytes transferred.

In GitLab by @bruxy on Jan 18, 2020, 19:20

I have added libusbx debug info, but a lot of values are optimized out, also I was playing with the MP_USB_READ_TIMEOUT. In this case, it will get stuck right at 0%.:

(gdb) r -p ATMEGA328P@DIP28 -r gdb_read
The program being debugged has been started already.
Start it from the beginning? (y or n) y
Starting program: /usr/local/src/minipro/minipro -p ATMEGA328P@DIP28 -r gdb_read
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff7d4a700 (LWP 940368)]
Found TL866II+ 04.2.110 (0x26e)
Warning: Firmware is newer than expected.
  Expected  04.2.109 (0x26d)
  Found     04.2.110 (0x26e)
Chip ID OK: 0x1E950F
Reading Code...   0%^C
Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7eada6f in poll () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff7eada6f in poll () from /lib64/libc.so.6
#1  0x00007ffff7f8a421 in poll (__timeout=60000, __nfds=<optimized out>, __fds=<optimized out>)
    at /usr/include/bits/poll2.h:46
#2  handle_events (ctx=ctx@entry=0x6583a0, tv=<optimized out>, tv=<optimized out>) at io.c:2151
#3  0x00007ffff7f8b62c in libusb_handle_events_timeout_completed (ctx=ctx@entry=0x6583a0, tv=tv@entry=0x7fffffffdb90, 
    completed=completed@entry=0x7fffffffdc04) at io.c:2348
#4  0x00007ffff7f8b6d4 in libusb_handle_events_completed (ctx=ctx@entry=0x6583a0, completed=completed@entry=0x7fffffffdc04)
    at io.c:2447
#5  0x00007ffff7f8c009 in sync_transfer_wait_for_completion (transfer=transfer@entry=0x669160) at sync.c:51
#6  0x00007ffff7f8c10b in do_sync_bulk_transfer (dev_handle=0x669080, endpoint=<optimized out>, 
    buffer=0x7fffffffdd30 "9\035I", length=<optimized out>, transferred=0x7fffffffdcfc, timeout=100000, type=2 '\002')
    at sync.c:191
#7  0x00007ffff7f8c423 in libusb_bulk_transfer (dev_handle=<optimized out>, endpoint=<optimized out>, data=<optimized out>, 
    length=<optimized out>, transferred=<optimized out>, timeout=<optimized out>) at sync.c:273
#8  0x000000000040bda2 in msg_transfer (handle=0x669080, buffer=0x7fffffffdd30 "9\035I", size=32, direction=128 '\200', 
    endpoint=1 '\001', bytes_transferred=0x7fffffffdcfc, timeout=100000) at usb_nix.c:128
#9  0x000000000040c446 in msg_recv (handle=0x669080, buffer=0x7fffffffdd30 "9\035I", size=32) at usb_nix.c:303
#10 0x00000000004092df in tl866iiplus_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddbf "")
    at tl866iiplus.c:441
#11 0x00000000004058d0 in minipro_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddbf "") at minipro.c:330
#12 0x000000000040e0c7 in read_page_ram (handle=0x6582a0, buf=0x65ae10 "\f\224\064", type=0 '\000', size=32768) at main.c:817
#13 0x000000000040f9ff in read_page_file (handle=0x6582a0, type=0 '\000', size=32768) at main.c:1303
#14 0x0000000000410faa in action_read (handle=0x6582a0) at main.c:1658
#15 0x0000000000412c26 in main (argc=5, argv=0x7fffffffe128) at main.c:2247

In GitLab by @radiomanV on Jan 19, 2020, 02:49

Thanks. This is what i wanted.
The timeout appears to be in the tl866iiplus_get_ovc_status function. We check for some overcurrent condition after each data block we read or write and if something bad is detected then we stop the transaction.
We have the folowing call stack:

main (main.c)
 |
action_read (main.c)
 |
read_page_file (main.c)
 |
read_page_ram (main.c)
 |
minipro_get_ovc_status (minipro.c)
 |
tl866iiplus_get_ovc_status (tl866iiplus.c)
 |
msg_recv (usb_nix.c)
 |
msg_transfer (usb_nix.c)
 |
libusb_bulk_transfer (libusb)

This is the simplified overcurrent function (tl866iiplus.c):

int tl866iiplus_get_ovc_status(minipro_handle_t *handle,
                               minipro_status_t *status, uint8_t *ovc) {
  uint8_t msg[32];
  msg_init(handle, TL866IIPLUS_REQUEST_STATUS, msg, sizeof(msg));
  if (msg_send(handle->usb_handle, msg, 8)) return EXIT_FAILURE;
  if (msg_recv(handle->usb_handle, msg, sizeof(msg))) return EXIT_FAILURE;
  return EXIT_SUCCESS;
}

So we send the REQUEST_STATUS command to the tl866 firmware and then we read back the status. And somehow at this point the programmer is stuck!
After the read timeout is passed we report that timeout error and then we return failure back in the chain up to the main where the cleanup routine sends the end transaction command but because the programmer is dead we get the second error IO error: expected 8 bytes but 0 bytes transferred. because we failed to successfully send this command.

Please disconnect and connect the programmer again to cycle the power after this error.

Here is a usb sniff from xgpro.exe (i'm using a debug version of that setupapi.dll)

Write 64 bytes on endpoint 1
03 18 14 00 00 00 83 2F 40 00 00 00 8C 00 00 00   
00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00   
00 00 00 00 00 00 00 00 00 02 00 12 80 00 00 00   
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   

Write 8 bytes on endpoint 1
39 18 14 00 00 00 83 2F                           

Read 32 bytes on endpoint 1
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

The first 64 bytes is the begin_transaction command then the REQUEST_STATUS command (8 bytes) and last the status read (32 bytes) so this is ok.

No one reported this kind of error until now so lets try to disable the ovc function.

In tl866iiplus.c line 445 replace that function with this:

int tl866iiplus_get_ovc_status(minipro_handle_t *handle,
                               minipro_status_t *status, uint8_t *ovc) {
  /*uint8_t msg[32];
  msg_init(handle, TL866IIPLUS_REQUEST_STATUS, msg, sizeof(msg));
  if (msg_send(handle->usb_handle, msg, 8)) return EXIT_FAILURE;
  if (msg_recv(handle->usb_handle, msg, sizeof(msg))) return EXIT_FAILURE;
  if (status)  // Check for null
  {
    // This is verify while writing feature.
    status->error = msg[0];
    status->address = load_int(&msg[8], 4, MP_LITTLE_ENDIAN);
    status->c1 = load_int(&msg[2], 2, MP_LITTLE_ENDIAN);
    status->c2 = load_int(&msg[4], 2, MP_LITTLE_ENDIAN);
  }
  */
  *ovc = 0;  // return the ovc status
  return EXIT_SUCCESS;
}

Recompile the minipro with make clean && make and try again. And please report back your result.
Thanks.

In GitLab by @bruxy on Jan 19, 2020, 07:40

I have pull the latest commit e7803bfa05 commented out tl866iiplus_get_ovc_status. Recompiled and works like a charm! Thank you very much :)

./minipro -p ATMEGA328P@DIP28 -r testx
Found TL866II+ 04.2.110 (0x26e)
Chip ID OK: 0x1E950F
Reading Code...  0.74Sec  OK
Reading Data...  0.04Sec  OK
Reading fuses... 0.01Sec  OK

I have compared checksum of EEPROM of this read and the previous one I did on working setup and it is the same.

I am not sure if that alway 0 status would be the official fix or just a temporary workaround. I will keep this ticket open until decided. Have a great day!

In GitLab by @radiomanV on Jan 19, 2020, 08:14

Yeah, this is not a fix it is more a workaround for your problem. The overcurrent protection is implemented at the firmware level so you don't have to worry but you will not be informed about this condition and the minipro will continue even if the firmware will abort the transaction.
Yes this issue should remain open until i'll have an idea for this because this is not normal. Also please do some long read/write tests like this:

minipro -p W25Q128BV@SOIC8 -r test -y

minipro -p W25Q128BV@SOIC8 -w test -y -e

Don't put any chip in the zif socket. The read test should last about 30 Sec. the write test should be a couple of minutes.

Also please tell me if you want what exact hardware setup you have there (the old machine) and which Linux distro? I want to reproduce your issue because i have a lot of old junks here to play with.

In GitLab by @radiomanV on Jan 19, 2020, 13:56

Nevermind.
Just installed Fedora 31 in a virtualbox machine and after some packages install (git, libusb-dev, make) the minipro compiled ok.
Then the show begin. Random timeout errors even if i disable the ovc test above, so this is not a fix. For small chips appears to be ok (because the read is fast) but if i'm trying something big the timeout error will throw.
Tested the old TL866A/CS same problem, timeout errors. So this is not a hardware problem or how old is your machine it's just Fedora.

Found TL866II+ 04.2.110 (0x26e)
Reading Code...  19%
IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT
IO error: expected 8 bytes but 0 bytes transferred

I tried to insert some delays after each data block but the same thing only a slowdown.

Tried this on some already installed vbox machines: Mageia, Manjaro, Mint, Ubuntu, Debian, Arch Linux both 32 and 64 bit flavour and no problem.
Never tried minipro in Fedora before but i think that something is not quite good.
I will test other Redhat based distros like CentOS to see if i have the same issue.

In GitLab by @bruxy on Jan 19, 2020, 16:14

Read test with empty socket: `` went okay, it has created file with size 16777216 bytes, full of 0xff.

Writing it back ended during erasing phase with LIBUSB_ERROR_TIMEOUT, here is the backtrace:

(gdb) r -p W25Q128BV@SOIC8 -w testx -y e
Starting program: /usr/local/src/minipro/minipro -p W25Q128BV@SOIC8 -w testx -y e
Missing separate debuginfos, use: dnf debuginfo-install glibc-2.30-8.fc31.x86_64
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff7d4a700 (LWP 130769)]
Found TL866II+ 04.2.110 (0x26e)
WARNING: Chip ID mismatch: expected 0xEF4018, got 0xFFFFFF (unknown)
Erasing... 
IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT

Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7df3625 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: dnf debuginfo-install libgcc-9.2.1-1.fc31.x86_64 systemd-libs-243.5-1.fc31.x86_64
(gdb) bt
#0  0x00007ffff7df3625 in raise () from /lib64/libc.so.6
#1  0x000000000040bcc0 in msg_transfer (handle=0x669080, buffer=0x7fffffffde20 "", size=64, direction=128 '\200', 
    endpoint=1 '\001', bytes_transferred=0x7fffffffddfc, timeout=100000) at usb_nix.c:133
#2  0x000000000040c32b in msg_recv (handle=0x669080, buffer=0x7fffffffde20 "", size=64) at usb_nix.c:303
#3  0x0000000000409227 in tl866iiplus_erase (handle=0x6582a0) at tl866iiplus.c:431
#4  0x0000000000405922 in minipro_erase (handle=0x6582a0) at minipro.c:340
#5  0x000000000040ec51 in erase_device (handle=0x6582a0) at main.c:1006
#6  0x000000000040f5be in write_page_file (handle=0x6582a0, type=0 '\000', size=16777216) at main.c:1233
#7  0x00000000004114b2 in action_write (handle=0x6582a0) at main.c:1774
#8  0x0000000000412b0e in main (argc=7, argv=0x7fffffffe128) at main.c:2249

In GitLab by @radiomanV on Jan 19, 2020, 16:22

This is normal. You type e instead of -e. Because no real chip has been present the erase failed.

In GitLab by @bruxy on Jan 19, 2020, 17:27

Sorry, my bad, works with proper parameters:

./minipro -p W25Q128BV@SOIC8 -w testx -y -e
Found TL866II+ 00.2.110 (0x26e)
WARNING: Chip ID mismatch: expected 0xEF4018, got 0xFFFFFF (unknown)
Protect off...OK
Writing Code...  359.33Sec  OK
Reading Code...  32.82Sec  OK
Verification OK
Protect on...OK

In GitLab by @bruxy on Jan 19, 2020, 17:46

I did one more test, I have compiled latest master from libusb and set LD_PRELOAD to use that library. If tl866iiplus_get_ovc_status is modified it works, but when I have put original version it is just alternating between Overcurrent protection and Uknown devices.

└──╼ ./minipro -p ATMEGA328P@DIP28 -r pokus3
Found TL866II+ 00.2.110 (0x26e)
Overcurrent protection!
┌─[✗]─[root@aspire]─[/usr/local/src/minipro]
└──╼ ./minipro -p ATMEGA328P@DIP28 -r pokus3
Unknown Device!┌─[✗]─[root@aspire]─[/usr/local/src/minipro]
└──╼ ./minipro -p ATMEGA328P@DIP28 -r pokus3
Found TL866II+ 04.2.110 (0x26e)
Overcurrent protection!

Hard to tell, what is different in Fedora... I am using one of lastest kernels here:

Linux aspire 5.4.10-200.fc31.x86_64 #1 SMP Thu Jan 9 19:58:12 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

In GitLab by @radiomanV on Jan 21, 2020, 14:25

Not necessarily different. Maybe the new 5.x kernel and a slow pc like my virtual box config or your old AMD pc can create this issue. From all Linux distros that i tested only the Fedora 31 has the new 5.x kernel.

Anyway running Fedora virtual machine under a Linux environment (Mint in my case) will produce the above timeout error. The same Fedora virtual machine but this time running under windows 10 64 bit will read the above example chip just fine. The only difference is the time: 70 sec. vbox under a Linux environment and 107 sec. vbox under a windows environment.

Perhaps running the official client under wine emulation layer is slowing down the communication process a bit and this is why it's working.

I checked the usb code and i'm not seeing anything suspect. Tried to increase some buffers size , nothing. What i have observed is that when the data transfer corruption appears you must cycle the device power because the programmer is in an undefined state.

The data corruption appears for both programmers type (the old tl866 and the new tl866ii+).

If you have more free time than me you can test an old 4.x kernel. I'm just curious. My knowledge about Redhat/fedora and rpm package management is a bit rusty :) I haven't used a Redhat based distro since the mandrake/mandriva era, years ago.

In GitLab by @bruxy on Jan 22, 2020, 18:01

Hi @radiomanV , tested with the older kernel, but the situation is the same. In the meantime, I have found 2x2GB RAM DDR2 modules so I have doubled memory :) Backtrace again, it got stalled in 0% this time:

└──╼ uname -a
Linux aspire 4.20.16-200.fc29.x86_64 #1 SMP Thu Mar 14 15:10:22 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
┌─[root@aspire]─[/usr/local/src/minipro]
└──╼ gdb ./minipro
GNU gdb (GDB) Fedora 8.3.50.20190824-26.fc31
Copyright (C) 2019 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./minipro...
(gdb) r -p ATMEGA328P@DIP28 -r ke4x
Starting program: /usr/local/src/minipro/minipro -p ATMEGA328P@DIP28 -r ke4x
Missing separate debuginfos, use: dnf debuginfo-install glibc-2.30-10.fc31.x86_64
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff7d48700 (LWP 3142)]
Found TL866II+ 04.2.110 (0x26e)
Chip ID OK: 0x1E950F
Reading Code...   0%^C
Thread 1 "minipro" received signal SIGINT, Interrupt.
0x00007ffff7eaba6f in poll () from /lib64/libc.so.6
Missing separate debuginfos, use: dnf debuginfo-install libgcc-9.2.1-1.fc31.x86_64 systemd-libs-243.5-1.fc31.x86_64
(gdb) bt
#0  0x00007ffff7eaba6f in poll () from /lib64/libc.so.6
#1  0x00007ffff7f88421 in poll (__timeout=60000, __nfds=<optimized out>, __fds=<optimized out>)
    at /usr/include/bits/poll2.h:46
#2  handle_events (ctx=ctx@entry=0x6583a0, tv=<optimized out>, tv=<optimized out>) at io.c:2151
#3  0x00007ffff7f8962c in libusb_handle_events_timeout_completed (ctx=ctx@entry=0x6583a0, tv=tv@entry=0x7fffffffdbc0, 
    completed=completed@entry=0x7fffffffdc34) at io.c:2348
#4  0x00007ffff7f896d4 in libusb_handle_events_completed (ctx=ctx@entry=0x6583a0, 
    completed=completed@entry=0x7fffffffdc34) at io.c:2447
#5  0x00007ffff7f8a009 in sync_transfer_wait_for_completion (transfer=transfer@entry=0x669160) at sync.c:51
#6  0x00007ffff7f8a10b in do_sync_bulk_transfer (dev_handle=0x669080, endpoint=<optimized out>, 
    buffer=0x7fffffffdd60 "9\035I", length=<optimized out>, transferred=0x7fffffffdd2c, timeout=360000, type=2 '\002')
    at sync.c:191
#7  0x00007ffff7f8a423 in libusb_bulk_transfer (dev_handle=<optimized out>, endpoint=<optimized out>, 
    data=<optimized out>, length=<optimized out>, transferred=<optimized out>, timeout=<optimized out>) at sync.c:273
#8  0x000000000040bd60 in msg_transfer (handle=0x669080, buffer=0x7fffffffdd60 "9\035I", size=32, direction=128 '\200', 
    endpoint=1 '\001', bytes_transferred=0x7fffffffdd2c, timeout=360000) at usb_nix.c:125
#9  0x000000000040c3f0 in msg_recv (handle=0x669080, buffer=0x7fffffffdd60 "9\035I", size=32) at usb_nix.c:297
#10 0x000000000040929d in tl866iiplus_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddef "")
    at tl866iiplus.c:440
#11 0x0000000000405899 in minipro_get_ovc_status (handle=0x6582a0, status=0x0, ovc=0x7fffffffddef "") at minipro.c:330
#12 0x000000000040e047 in read_page_ram (handle=0x6582a0, buf=0x65ae10 "\f\224\064", type=0 '\000', size=32768)
    at main.c:815
#13 0x000000000040f97f in read_page_file (handle=0x6582a0, type=0 '\000', size=32768) at main.c:1301
#14 0x0000000000410f2a in action_read (handle=0x6582a0) at main.c:1656
#15 0x0000000000412bbf in main (argc=5, argv=0x7fffffffe138) at main.c:2246
(gdb)

In GitLab by @rdearman on Nov 15, 2020, 17:23

I'm having the same issue on Linux Mint 20. Any resolution for this? I have posted an issue on Github, don't know which is the correct place to raise and issue.

https://github.com/vdudouyt/minipro/issues/128

In GitLab by @radiomanV on Nov 15, 2020, 21:06

I have posted an issue on Github, don't know which is the correct place to raise and issue.

This project has moved to https://gitlab.com/DavidGriffith/minipro/

So you must raise your issue here.

Found TL866II+ 04.2.112 (0x270)
Warning: Firmware is out of date.
  Expected  04.2.122 (0x27a)
  Found     04.2.112 (0x270)

IO error: bulk_transfer: LIBUSB_ERROR_NO_DEVICE
IO error: expected 8 bytes but 0 bytes transferred

IO error: bulk_transfer: LIBUSB_ERROR_NO_DEVICE
IO error: expected 8 bytes but 0 bytes transferred

Looks like a communication issue to me. Open a new terminal window and dmesg -w. Then (in another terminal) try to read/write something with minipro and watch the dmesg window for any funny message.

In GitLab by @rdearman on Nov 16, 2020, 06:24

It seems to disconnect itself, then reconnect.

~/minipro/minipro -p AT28C256F@PLCC32 -w ~/Desktop/Motorola68000/tutor13.bin -S
Found TL866II+ 04.2.112 (0x270)
Warning: Firmware is out of date.
  Expected  04.2.122 (0x27a)
  Found     04.2.112 (0x270)

IO error: bulk_transfer: LIBUSB_ERROR_NO_DEVICE
IO error: expected 8 bytes but 0 bytes transferred

IO error: bulk_transfer: LIBUSB_ERROR_NO_DEVICE
IO error: expected 8 bytes but 0 bytes transferred

[1611036.147095] usb 3-1: USB disconnect, device number 67
[1611036.584611] usb 3-1: new full-speed USB device number 68 using xhci_hcd
[1611036.755157] usb 3-1: New USB device found, idVendor=a466, idProduct=0a53, bcdDevice= 0.00
[1611036.755160] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[1611036.755161] usb 3-1: Product: Xingong XGecu USB Prog.. Device
[1611036.755163] usb 3-1: Manufacturer: Xingong Electronicg Co..

In GitLab by @radiomanV on Nov 16, 2020, 07:37

Yeah. Never seen this for TL866II+. This is somewhat related to #148. If you can use a Usb 2.0 hub and test it again.

If there's no module issue or any related driver interference this can be a usb3 xhci driver not playing nice with the firmware usb stack.
Can you post your configuration please? motherboard/cpu/ram would be ok. And an output from lsusb and lsmod.
Thanks.

In GitLab by @rdearman on Nov 16, 2020, 09:23

OK, changed the USB port and got slightly different behaviour.

[1621027.870369] usb 1-3: new full-speed USB device number 6 using xhci_hcd
[1621028.041279] usb 1-3: New USB device found, idVendor=a466, idProduct=0a53, bcdDevice= 0.00
[1621028.041282] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[1621028.041283] usb 1-3: Product: Xingong XGecu USB Prog.. Device
[1621028.041285] usb 1-3: Manufacturer: Xingong Electronicg Co..

 ~/minipro/minipro -p AT28C256F@PLCC32 -w ~/Desktop/Motorola68000/tutor13.bin -S
Found TL866II+ 04.2.112 (0x270)
Warning: Firmware is out of date.
  Expected  04.2.122 (0x27a)
  Found     04.2.112 (0x270)
Erasing... 0.02Sec OK
Protect off...OK
Writing Code...  2.32Sec  OK
Reading Code...  0.31Sec  OK
Verification failed at address 0x0000: File=0x00, Device=0x7F

lsusb & lsmod

Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 005 Device 005: ID 045e:00cb Microsoft Corp. Basic Optical Mouse v2.0
Bus 005 Device 004: ID 04ca:0022 Lite-On Technology Corp. USB Keyboard
Bus 005 Device 003: ID 1130:1620 Tenx Technology, Inc. USB  AUDIO  
Bus 005 Device 002: ID 0bda:58b0 Realtek Semiconductor Corp. FULL HD 1080P Webcam
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 002: ID 0b05:18f3 ASUSTek Computer, Inc. AURA LED Controller
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 002: ID 05e3:0626 Genesys Logic, Inc. USB3.1 Hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 006: ID a466:0a53 Xingong Electronicg Co..  Xingong XGecu USB Prog.. Device
Bus 001 Device 002: ID 05e3:0610 Genesys Logic, Inc. 4-port hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Module                  Size  Used by
cp210x                 32768  0
ufs                    81920  0
qnx4                   16384  0
hfsplus               110592  0
hfs                    61440  0
minix                  36864  0
ntfs                  106496  0
msdos                  20480  0
jfs                   188416  0
xfs                  1277952  0
cpuid                  16384  0
uas                    28672  0
usb_storage            77824  1 uas
snd_seq_dummy          16384  0
ch341                  20480  0
usbserial              53248  2 cp210x,ch341
xt_CHECKSUM            16384  1
xt_MASQUERADE          20480  3
xt_conntrack           16384  1
ipt_REJECT             16384  2
nf_reject_ipv4         16384  1 ipt_REJECT
xt_tcpudp              20480  9
ip6table_mangle        16384  1
ip6table_nat           16384  1
iptable_mangle         16384  1
iptable_nat            16384  1
nf_nat                 40960  3 ip6table_nat,iptable_nat,xt_MASQUERADE
nf_conntrack          139264  3 xt_conntrack,nf_nat,xt_MASQUERADE
nf_defrag_ipv6         24576  1 nf_conntrack
nf_defrag_ipv4         16384  1 nf_conntrack
nf_tables             135168  0
nfnetlink              16384  1 nf_tables
ip6table_filter        16384  1
ip6_tables             32768  3 ip6table_filter,ip6table_nat,ip6table_mangle
iptable_filter         16384  1
bpfilter               32768  0
bridge                176128  0
stp                    16384  1 bridge
llc                    16384  2 bridge,stp
usblp                  24576  0
nls_iso8859_1          16384  1
snd_hda_codec_hdmi     61440  2
uvcvideo               98304  0
snd_hda_codec_realtek   126976  1
videobuf2_vmalloc      20480  1 uvcvideo
videobuf2_memops       20480  1 videobuf2_vmalloc
snd_hda_codec_generic    81920  1 snd_hda_codec_realtek
videobuf2_v4l2         24576  1 uvcvideo
ledtrig_audio          16384  2 snd_hda_codec_generic,snd_hda_codec_realtek
videobuf2_common       49152  2 videobuf2_v4l2,uvcvideo
videodev              225280  3 videobuf2_v4l2,uvcvideo,videobuf2_common
snd_hda_intel          53248  5
snd_usb_audio         270336  3
snd_usbmidi_lib        36864  1 snd_usb_audio
snd_intel_dspcfg       24576  1 snd_hda_intel
snd_hda_codec         135168  4 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec_realtek
snd_hda_core           90112  5 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec,snd_hda_codec_realtek
mc                     53248  5 videodev,snd_usb_audio,videobuf2_v4l2,uvcvideo,videobuf2_common
snd_hwdep              20480  2 snd_usb_audio,snd_hda_codec
snd_seq_midi           20480  0
snd_seq_midi_event     16384  1 snd_seq_midi
snd_rawmidi            36864  2 snd_seq_midi,snd_usbmidi_lib
snd_pcm               106496  6 snd_hda_codec_hdmi,snd_hda_intel,snd_usb_audio,snd_hda_codec,snd_hda_core
snd_seq                69632  3 snd_seq_midi,snd_seq_midi_event,snd_seq_dummy
snd_seq_device         16384  3 snd_seq,snd_seq_midi,snd_rawmidi
snd_timer              36864  2 snd_seq,snd_pcm
input_leds             16384  0
snd                    90112  28 snd_hda_codec_generic,snd_seq,snd_seq_device,snd_hda_codec_hdmi,snd_hwdep,snd_hda_intel,snd_usb_audio,snd_usbmidi_lib,snd_hda_codec,snd_hda_codec_realtek,snd_timer,snd_pcm,snd_rawmidi
soundcore              16384  1 snd
edac_mce_amd           32768  0
kvm_amd                98304  0
k10temp                16384  0
eeepc_wmi              16384  0
asus_wmi               32768  1 eeepc_wmi
ccp                    86016  1 kvm_amd
mac_hid                16384  0
sparse_keymap          16384  1 asus_wmi
kvm                   663552  1 kvm_amd
wmi_bmof               16384  0
sch_fq_codel           20480  4
cuse                   16384  3
parport_pc             40960  0
ppdev                  24576  0
lp                     20480  0
parport                53248  3 parport_pc,lp,ppdev
ip_tables              32768  3 iptable_filter,iptable_nat,iptable_mangle
x_tables               40960  11 ip6table_filter,xt_conntrack,iptable_filter,xt_tcpudp,xt_CHECKSUM,ip6_tables,ipt_REJECT,ip_tables,ip6table_mangle,xt_MASQUERADE,iptable_mangle
autofs4                45056  2
btrfs                1253376  0
xor                    24576  1 btrfs
zstd_compress         167936  1 btrfs
raid6_pq              114688  1 btrfs
libcrc32c              16384  4 nf_conntrack,nf_nat,btrfs,xfs
dm_mirror              24576  0
dm_region_hash         20480  1 dm_mirror
dm_log                 20480  2 dm_region_hash,dm_mirror
hid_generic            16384  0
usbhid                 57344  0
hid                   131072  2 usbhid,hid_generic
nouveau              1949696  32
crct10dif_pclmul       16384  1
crc32_pclmul           16384  0
ghash_clmulni_intel    16384  0
video                  49152  2 asus_wmi,nouveau
ttm                   106496  1 nouveau
aesni_intel           372736  0
mxm_wmi                16384  1 nouveau
drm_kms_helper        184320  1 nouveau
syscopyarea            16384  1 drm_kms_helper
crypto_simd            16384  1 aesni_intel
sysfillrect            16384  1 drm_kms_helper
cryptd                 24576  2 crypto_simd,ghash_clmulni_intel
sysimgblt              16384  1 drm_kms_helper
glue_helper            16384  1 aesni_intel
fb_sys_fops            16384  1 drm_kms_helper
drm                   491520  15 drm_kms_helper,ttm,nouveau
i2c_piix4              28672  0
igb                   221184  0
ahci                   40960  5
libahci                32768  1 ahci
dca                    16384  1 igb
i2c_algo_bit           16384  2 igb,nouveau
wmi                    32768  4 asus_wmi,wmi_bmof,mxm_wmi,nouveau

Hardware:

ASUS AMD Ryzen ROG STRIX X570 F AM4 PCIe 4.0 ATX Gaming Motherboard
AMD Ryzen 7 2700X - 3.7GHz 8x Core Processor / CPU

In GitLab by @radiomanV on Nov 16, 2020, 10:29

Looks ok. lsusb -tv should output something like that:

Port 2: Dev 5, If 0, Class=Vendor Specific Class, Driver=, 12M
                ID a466:0a53

unfortunately this is a firmware compatibility issue with some USB3 XHCI motherboard controllers in Linux kernel. Use a USB 2.0 port or (much better) a USB 2.0 powered hub.
In your case the communication is ok so leave the programmer plugged in that port.

Verification failed at address 0x0000: File=0x00, Device=0x7F

This is a bad pin contact or worse the AT28c256 is fake. First try the bad pin contact check like this (note the -z switch):

 ~/minipro/minipro -p AT28C256F@PLCC32 -w ~/Desktop/Motorola68000/tutor13.bin -S -z

And then if all is ok tweak the chip version by changing the chip suffix (AT28C256E@PLCC32, AT28C256@PLCC32). This is related to issue #149

In GitLab by @rdearman on Nov 16, 2020, 14:11

Probably a bad chip. Luckily I have an entire box of Eprom. So I tried it again with: "AM27C1024@DIP40"

~/minipro/minipro -r my.tmp.mem -p "AM27C1024@DIP40"
Found TL866II+ 04.2.112 (0x270)
Warning: Firmware is out of date.
  Expected  04.2.122 (0x27a)
  Found     04.2.112 (0x270)
Chip ID OK: 0x1008C00
Reading Code...  0.84Sec  OK

~/minipro/minipro -w ~/Desktop/Motorola68000/tutor13.bin -S -p "AM27C1024@DIP40"
Found TL866II+ 04.2.112 (0x270)
Warning: Firmware is out of date.
  Expected  04.2.122 (0x27a)
  Found     04.2.112 (0x270)

VPP=13V, VDD=6.5V, VCC=5V, Pulse=100us
Chip ID OK: 0x1008C00
Writing Code...  34.52Sec  OK
Reading Code...  0.84Sec  OK
Verification OK

So it does appear to work. I'm guessing that as long as I leave it in the old USB-2 port I'll be OK. I did try another eprom which failed verification. But this might be due to it not being wiped properly (have to use UV for these old ones). But I've tested a couple and it seems to be working.

~/minipro/minipro -w ~/Desktop/Motorola68000/tutor13.bin -S -p "AM27C512@DIP28" -y
Found TL866II+ 04.2.112 (0x270)
Warning: Firmware is out of date.
  Expected  04.2.122 (0x27a)
  Found     04.2.112 (0x270)

VPP=13V, VDD=6.5V, VCC=5V, Pulse=100us
WARNING: Chip ID mismatch: expected 0x0191, got 0x0FFF (unknown)
Writing Code...  28.53Sec  OK
Reading Code...  0.98Sec  OK
Verification OK

In GitLab by @radiomanV on Nov 17, 2020, 07:32

I'm guessing that as long as I leave it in the old USB-2 port I'll be OK

Yes.

Probably a bad chip

Not necessarily. The AT28C256 doesn't have a chip ID to check before any operation. So we must check if there are bad pin contacts (notorious for this programer).

For some PLCC32 chips when you put it in the PLCC32 adapter and the chip is inserted to the bottom sometimes a bad contact may occur. So when you insert the chip just gently press it with your fingertip and then turn it upside down and press the chip against the table. This way the chip is not inserted to the bottom of the adapter. I have observed this behaviour for some chips, don't know why, perhaps the chip pins are different.

In GitLab by @tusker42 on Nov 23, 2020, 18:40

Hi guys,

I am having a very similar issue, running on Debian 10 64bit:

$ LIBUSB_DEBUG=4 minipro -p K9F1G08U0D@TSOP48 --read 1g.bin
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000008] [0000178f] libusb: debug [libusb_init] created default context
[ 0.000054] [0000178f] libusb: debug [libusb_init] libusb v1.0.22.11312
[ 0.000097] [0000178f] libusb: debug [find_usbfs_path] found usbfs at /dev/bus/usb
[ 0.000119] [0000178f] libusb: debug [get_kernel_version] reported kernel version is 5.8.0-0.bpo.2-amd64
[ 0.000127] [0000178f] libusb: debug [op_init] bulk continuation flag supported
[ 0.000134] [0000178f] libusb: debug [op_init] zero length packet flag supported
[ 0.000140] [0000178f] libusb: debug [op_init] max iso packet length is (likely) 49152 bytes
[ 0.000158] [0000178f] libusb: debug [op_init] sysfs can relate devices
[ 0.000165] [0000178f] libusb: debug [op_init] sysfs has complete descriptors
[ 0.000429] [00001790] libusb: debug [linux_udev_event_thread_main] udev event thread entering.
[ 0.004846] [0000178f] libusb: debug [linux_get_device_address] getting address for device: usb1 detached: 0
[ 0.004862] [0000178f] libusb: debug [linux_get_device_address] scan usb1
[ 0.004918] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=1
[ 0.004926] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 1 session_id 257
[ 0.004933] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/1 (session 257)
[ 0.005097] [0000178f] libusb: debug [linux_get_device_address] getting address for device: 1-1 detached: 0
[ 0.005107] [0000178f] libusb: debug [linux_get_device_address] scan 1-1
[ 0.005152] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=11
[ 0.005159] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 11 session_id 267
[ 0.005165] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/11 (session 267)
[ 0.005211] [0000178f] libusb: debug [linux_get_parent_info] Dev 0x559d2bad6690 (1-1) has parent 0x559d2bad5e60 (usb1) port 1
[ 0.005326] [0000178f] libusb: debug [linux_get_device_address] getting address for device: 1-10 detached: 0
[ 0.005334] [0000178f] libusb: debug [linux_get_device_address] scan 1-10
[ 0.005378] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=7
[ 0.005386] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 7 session_id 263
[ 0.005393] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/7 (session 263)
[ 0.005435] [0000178f] libusb: debug [linux_get_parent_info] Dev 0x559d2bad5f20 (1-10) has parent 0x559d2bad5e60 (usb1) port 10
[ 0.005555] [0000178f] libusb: debug [linux_get_device_address] getting address for device: 1-3 detached: 0
[ 0.005564] [0000178f] libusb: debug [linux_get_device_address] scan 1-3
[ 0.005613] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=3
[ 0.005621] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 3 session_id 259
[ 0.005627] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/3 (session 259)
[ 0.005667] [0000178f] libusb: debug [linux_get_parent_info] Dev 0x559d2bad6000 (1-3) has parent 0x559d2bad5e60 (usb1) port 3
[ 0.005776] [0000178f] libusb: debug [linux_get_device_address] getting address for device: 1-5 detached: 0
[ 0.005784] [0000178f] libusb: debug [linux_get_device_address] scan 1-5
[ 0.005826] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=4
[ 0.005833] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 4 session_id 260
[ 0.005839] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/4 (session 260)
[ 0.005880] [0000178f] libusb: debug [linux_get_parent_info] Dev 0x559d2bad6170 (1-5) has parent 0x559d2bad5e60 (usb1) port 5
[ 0.005988] [0000178f] libusb: debug [linux_get_device_address] getting address for device: 1-7 detached: 0
[ 0.005997] [0000178f] libusb: debug [linux_get_device_address] scan 1-7
[ 0.006041] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=5
[ 0.006048] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 5 session_id 261
[ 0.006055] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/5 (session 261)
[ 0.006099] [0000178f] libusb: debug [linux_get_parent_info] Dev 0x559d2bab9b60 (1-7) has parent 0x559d2bad5e60 (usb1) port 7
[ 0.006222] [0000178f] libusb: debug [linux_get_device_address] getting address for device: 1-8 detached: 0
[ 0.006232] [0000178f] libusb: debug [linux_get_device_address] scan 1-8
[ 0.006277] [0000178f] libusb: debug [linux_get_device_address] bus=1 dev=6
[ 0.006285] [0000178f] libusb: debug [linux_enumerate_device] busnum 1 devaddr 6 session_id 262
[ 0.006293] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 1/6 (session 262)
[ 0.006334] [0000178f] libusb: debug [linux_get_parent_info] Dev 0x559d2baba430 (1-8) has parent 0x559d2bad5e60 (usb1) port 8
[ 0.006472] [0000178f] libusb: debug [linux_get_device_address] getting address for device: usb2 detached: 0
[ 0.006485] [0000178f] libusb: debug [linux_get_device_address] scan usb2
[ 0.006533] [0000178f] libusb: debug [linux_get_device_address] bus=2 dev=1
[ 0.006540] [0000178f] libusb: debug [linux_enumerate_device] busnum 2 devaddr 1 session_id 513
[ 0.006546] [0000178f] libusb: debug [linux_enumerate_device] allocating new device for 2/1 (session 513)
[ 0.006669] [0000178f] libusb: debug [usbi_add_pollfd] add fd 6 events 1
[ 0.006690] [0000178f] libusb: debug [usbi_io_init] using timerfd for timeouts
[ 0.006697] [0000178f] libusb: debug [usbi_add_pollfd] add fd 8 events 1
[ 0.006706] [0000178f] libusb: debug [libusb_get_device_list]
[ 0.006728] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006735] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006742] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006749] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006755] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006762] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006769] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006775] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006783] [0000178f] libusb: debug [libusb_get_device_list]
[ 0.006793] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006800] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006807] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006814] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006820] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006827] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006833] [0000178f] libusb: debug [libusb_get_device_descriptor]
[ 0.006841] [0000178f] libusb: debug [libusb_open] open 1.11
[ 0.119261] [0000178f] libusb: debug [usbi_add_pollfd] add fd 9 events 4
[ 0.119294] [0000178f] libusb: debug [libusb_claim_interface] interface 0
[ 0.119340] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bad1e70
[ 0.119353] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bad1e70
[ 0.119362] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.119380] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 5
[ 0.119406] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.119417] [0000178f] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.119429] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.119486] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.119503] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=5
[ 0.119511] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.119518] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.119525] [0000178f] libusb: debug [disarm_timerfd]
[ 0.119534] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bad1e70 has callback 0x7fa30cc8d2c0
[ 0.119543] [0000178f] libusb: debug [sync_transfer_cb] actual_length=5
[ 0.119562] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bad1e70
[ 0.119574] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bad3d70
[ 0.119582] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bad3d70
[ 0.119591] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 360000ms (first in line)
[ 0.119602] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 62
[ 0.119623] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.119633] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.119744] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.119773] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=41
[ 0.119783] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.119793] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.119803] [0000178f] libusb: debug [disarm_timerfd]
[ 0.119814] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bad3d70 has callback 0x7fa30cc8d2c0
[ 0.119823] [0000178f] libusb: debug [sync_transfer_cb] actual_length=41
[ 0.119835] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bad3d70
Found TL866II+ 04.2.123 (0x27b)
Warning: Firmware is newer than expected.
  Expected  04.2.122 (0x27a)
  Found     04.2.123 (0x27b)
[ 0.134417] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bac9150
[ 0.134426] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bac9150
[ 0.134431] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.134440] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[ 0.134458] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.134463] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.134554] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.134561] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=64
[ 0.134564] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.134566] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.134569] [0000178f] libusb: debug [disarm_timerfd]
[ 0.134573] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bac9150 has callback 0x7fa30cc8d2c0
[ 0.134576] [0000178f] libusb: debug [sync_transfer_cb] actual_length=64
[ 0.134580] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bac9150
[ 0.134584] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bac9340
[ 0.134587] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bac9340
[ 0.134589] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.134594] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 0.134600] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.134603] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.194879] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.194933] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 0.195035] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.195063] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.195084] [0000178f] libusb: debug [disarm_timerfd]
[ 0.195113] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bac9340 has callback 0x7fa30cc8d2c0
[ 0.195135] [0000178f] libusb: debug [sync_transfer_cb] actual_length=8
[ 0.195161] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bac9340
[ 0.195183] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacdd90
[ 0.195196] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacdd90
[ 0.195211] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 360000ms (first in line)
[ 0.195231] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 32
[ 0.195272] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.195285] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.195354] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.195375] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=32
[ 0.195387] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.195400] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.195414] [0000178f] libusb: debug [disarm_timerfd]
[ 0.195429] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacdd90 has callback 0x7fa30cc8d2c0
[ 0.195442] [0000178f] libusb: debug [sync_transfer_cb] actual_length=32
[ 0.195458] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacdd90
[ 0.195475] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb2c0
[ 0.195486] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb2c0
[ 0.195499] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.195515] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 0.195540] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.195551] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.195616] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.195633] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 0.195646] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.195659] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.195672] [0000178f] libusb: debug [disarm_timerfd]
[ 0.195687] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb2c0 has callback 0x7fa30cc8d2c0
[ 0.195699] [0000178f] libusb: debug [sync_transfer_cb] actual_length=8
[ 0.195715] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb2c0
[ 0.195729] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bad58c0
[ 0.195740] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bad58c0
[ 0.195753] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 360000ms (first in line)
[ 0.195769] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 6
[ 0.195793] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.195804] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.196243] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.196261] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=6
[ 0.196274] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.196287] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.196300] [0000178f] libusb: debug [disarm_timerfd]
[ 0.196315] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bad58c0 has callback 0x7fa30cc8d2c0
[ 0.196327] [0000178f] libusb: debug [sync_transfer_cb] actual_length=6
[ 0.196344] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bad58c0
[ 0.196358] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 0.196370] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 0.196383] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.196399] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 0.196420] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.196431] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.196498] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.196514] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 0.196527] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.196540] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.196553] [0000178f] libusb: debug [disarm_timerfd]
[ 0.196568] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x7fa30cc8d2c0
[ 0.196580] [0000178f] libusb: debug [sync_transfer_cb] actual_length=8
[ 0.196596] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
Chip ID OK: 0xECF1
[ 0.196633] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 0.196644] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 0.196657] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.196673] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[ 0.196699] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.196710] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.296698] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.296727] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=64
[ 0.296736] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.296743] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.296754] [0000178f] libusb: debug [disarm_timerfd]
[ 0.296767] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x7fa30cc8d2c0
[ 0.296774] [0000178f] libusb: debug [sync_transfer_cb] actual_length=64
[ 0.296786] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
[ 0.296798] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 0.296805] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 0.296812] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.296823] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 0.296842] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.296850] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.356865] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.356898] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 0.356914] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.356926] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.356939] [0000178f] libusb: debug [disarm_timerfd]
[ 0.356954] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x7fa30cc8d2c0
[ 0.356964] [0000178f] libusb: debug [sync_transfer_cb] actual_length=8
[ 0.356980] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
[ 0.356993] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 0.357001] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 0.357010] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 360000ms (first in line)
[ 0.357023] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 32
[ 0.357050] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.357058] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.357131] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.357145] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=32
[ 0.357153] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.357162] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.357171] [0000178f] libusb: debug [disarm_timerfd]
[ 0.357182] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x7fa30cc8d2c0
[ 0.357190] [0000178f] libusb: debug [sync_transfer_cb] actual_length=32
[ 0.357202] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
Reading Code...   0%[ 0.382465] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 0.382482] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 0.382487] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.382495] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 0.382510] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.382514] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.382589] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 0.382606] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 0.382610] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.382613] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.382618] [0000178f] libusb: debug [disarm_timerfd]
[ 0.382622] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x7fa30cc8d2c0
[ 0.382626] [0000178f] libusb: debug [sync_transfer_cb] actual_length=8
[ 0.382631] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
[ 0.382638] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 0.382641] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacc0c0
[ 0.382645] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 0.382649] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 0.382653] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4224
[ 0.382665] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacc0c0
[ 0.382669] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4224
[ 0.382677] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.382680] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 5.382786] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 5.382826] [0000178f] libusb: debug [handle_events] timerfd triggered
[ 5.382841] [0000178f] libusb: debug [libusb_cancel_transfer] transfer 0x559d2bacb0b0
[ 5.382979] [0000178f] libusb: debug [libusb_cancel_transfer] transfer 0x559d2bacc0c0
[ 5.383060] [0000178f] libusb: debug [disarm_timerfd]
[ 5.383084] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.383092] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 5.383107] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 5.383120] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 5.383136] [0000178f] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 5.383148] [0000178f] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 5.383158] [0000178f] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 5.383175] [0000178f] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 5.383188] [0000178f] libusb: debug [disarm_timerfd]
[ 5.383203] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x559d2ad78de0
[ 5.383222] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 5.383237] [0000178f] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 5.383250] [0000178f] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 5.383263] [0000178f] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 5.383274] [0000178f] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 5.383286] [0000178f] libusb: debug [disarm_timerfd]
[ 5.383298] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacc0c0 has callback 0x559d2ad78de0

IO Error: Async transfer failed: LIBUSB_TRANSFER_TIMED_OUT
[ 5.383330] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
[ 5.383349] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacc0c0
[ 5.384340] [0000178f] libusb: debug [libusb_alloc_transfer] transfer 0x559d2bacb0b0
[ 5.384358] [0000178f] libusb: debug [libusb_submit_transfer] transfer 0x559d2bacb0b0
[ 5.384373] [0000178f] libusb: debug [add_to_flying_list] arm timerfd for timeout in 5000ms (first in line)
[ 5.384395] [0000178f] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 5.384428] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.384439] [0000178f] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 5.384507] [0000178f] libusb: debug [handle_events] poll() returned 1
[ 5.384523] [0000178f] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 5.384532] [0000178f] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 5.384540] [0000178f] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 5.384547] [0000178f] libusb: debug [disarm_timerfd]
[ 5.384557] [0000178f] libusb: debug [usbi_handle_transfer_completion] transfer 0x559d2bacb0b0 has callback 0x7fa30cc8d2c0
[ 5.384567] [0000178f] libusb: debug [sync_transfer_cb] actual_length=8
[ 5.384583] [0000178f] libusb: debug [libusb_free_transfer] transfer 0x559d2bacb0b0
[ 5.384600] [0000178f] libusb: debug [libusb_release_interface] interface 0
[ 5.384646] [0000178f] libusb: debug [libusb_close]
[ 5.384669] [0000178f] libusb: debug [usbi_remove_pollfd] remove fd 9
[ 5.384694] [0000178f] libusb: debug [libusb_exit]
[ 5.384704] [0000178f] libusb: debug [libusb_exit] destroying default context
[ 5.384723] [0000178f] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.384735] [0000178f] libusb: debug [handle_events] poll fds modified, reallocating
[ 5.384757] [0000178f] libusb: debug [handle_events] poll() 2 fds with timeout in 0ms
[ 5.384771] [0000178f] libusb: debug [handle_events] poll() returned 0
[ 5.384784] [0000178f] libusb: debug [libusb_unref_device] destroy device 2.1
[ 5.384799] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.6
[ 5.384812] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.5
[ 5.384826] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.4
[ 5.384839] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.3
[ 5.384853] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.7
[ 5.384867] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.11
[ 5.384880] [0000178f] libusb: debug [libusb_unref_device] destroy device 1.1
[ 5.384894] [0000178f] libusb: debug [usbi_remove_pollfd] remove fd 6
[ 5.384931] [0000178f] libusb: debug [usbi_remove_pollfd] remove fd 8
[ 5.385042] [00001790] libusb: debug [linux_udev_event_thread_main] udev event thread exiting
tusker@n550jv:~
$

The same device works fine in Windows and can read the exact same chip with no timeout or error.

I have made the changes to tl866iiplus_get_ovc_status as per above, and it doesn't help my chip reading.

I have tried connecting via a USB2.0 hub, and it doesn't help matters.

EDIT: Testing inside a VirtualBox instance of Debian 9 and CentOS 8 both exhibit the same behaviour, regardless of USB1, USB2 etc.

Cheers,

Damien

In GitLab by @radiomanV on Nov 25, 2020, 10:56

This is not the same issue. This is related to NAND support. You have this timeout because NAND chips are not supported yet. For NAND chips there's an extra initialization protocol. Once this protocol will be reverse engineered we can add NAND support.

In GitLab by @tusker42 on Nov 25, 2020, 11:40

Oh OK, apologies for the noise on this ticket!

Do you need any USB captures (or anything else) from Windows while reading the NAND chip?

EDIT: New ticket created #194 with USBPCap added

In GitLab by @Gandalf1783 on May 30, 2021, 04:58

Hello, sorry to warm this Thread back up.

This exact issue with the timeout also occurs on my Raspberry Pi 4 using Raspbian. Under Windows, it works perfectly fine, but not on this device. I tried multiple of the 4 USB Ports (also the USB 3.0 ports) which didnt seem to change anything. I did compile it from the latest commit a few days ago, and it seems to get stuck again.

Running dmesg -w it did not seem to disconnect in my case, and it is stuck at some of the first percentages of reading the EEPROM. I am using a RPi 4, 4GB with kernel version 5.10.17-v7l+ with minipro version 0.5 from 2021-04-30 08:22.

Do you need any log files (more like which do you need)?

EDIT: Using a TL866II+ with an AT28C256 EEPROM.

In GitLab by @tannm102 on Oct 26, 2021, 04:38

I got the same thing on Raspberry Pi 4 Linux pi4 version 5.10.63-v7l+ and latest minipro version. Any update for this issues? Thank you.

DavidGriffith / minipro-import-test

TL866II+ throwing IO error: bulk_transfer: LIBUSB_ERROR_TIMEOUT #163