Cannot upload binaries to V5 brain: couldn't find the response header in the device response

Qrtn commented 5 years ago

Expected Behavior:

Successful upload of binary to microcontroller.

Actual Behavior:

Uploading /Users/jeffrey/Documents/hello/bin/output.bin to v5 device on /dev/cu.usbmodem1421 as hello to slot 1
Uploading slot_1.bin (/Users/jeffrey/Documents/hello/bin/output.bin) [#-----------------------------------]   2%
ERROR - pros.cli.upload:upload - Couldn't find the response header in the device response. Got  but was expecting aa55
  File "/usr/local/Cellar/pros-cli/3.1.2/libexec/lib/python3.7/site-packages/pros/serial/devices/vex/vex_device.py", line 69, in _rx_packet
    raise IOError(f"Couldn't find the response header in the device response. "
OSError: Couldn't find the response header in the device response. Got  but was expecting aa55

Steps to reproduce:

prosv5 conductor new-project test-upload-mac
cd test-upload-mac
prosv5 make
prosv5 upload

System information:

Operating System: macOS High Sierra (10.13.6)

PROS Version: 3.1.2

Additional Information

I installed PROS 3 using the instructions for macOS installs involving Homebrew for the latest release (3.1.2). Uploading works fine on another computer running Windows 10.

The percentage at which prosv5 upload fails and outputs the above error message varies from about 0 to 25.

Screenshots/Output Dumps/Stack Traces

Full output of prosv5 --debug upload

jwalk511 commented 5 years ago

We're trying to reproduce; in the meantime could you try restarting your Mac and the V5, and if that fails, plugging the V5 into a different port on the Mac? We'll respond in a bit after more testing.

Qrtn commented 5 years ago

Will do, thanks for the immediate response!

Qrtn commented 5 years ago

I've restarted my Mac and the V5, which seemed to have no effect. Using different USB ports, however, yielded varying degrees of success.

Uploading with either of the two onboard USB ports on my Macbook Pro has never succeeded, with percentages varying from 0 to 40.
When I connected a powered USB 3.0 hub to my Mac and the V5 to the hub, uploading has succeeded (100%) approximately 1 in 2 times, albeit very slow (around 1 min 30 sec, whereas on another Windows machine the upload takes below 3 sec). When it did not succeed, percentages were in the 90s and close to completion.

The errors when uploading fails are all identical to my original error.

jwalk511 commented 5 years ago

What kind of USB ports are on your Pro? USB C or A? And what do you get when you run prosv5 v5 status?

Qrtn commented 5 years ago

USB A 3.0. prosv5 v5 status for one of the onboard ports:

Connected to V5 on /dev/cu.usbmodem1421
System version: 1.0.0-0
CPU0 F/W version: 1.0.0-23
CPU1 SDK version: 1.0.0-0
System ID: 0xd5442800

For the hub:

Connected to V5 on /dev/cu.usbmodem14141
System version: 1.0.0-0
CPU0 F/W version: 1.0.0-23
CPU1 SDK version: 1.0.0-0
System ID: 0xd5442800

By the way, short-term commands like prosv5 v5 ls-files, etc. work.

jwalk511 commented 5 years ago

Thanks for the info.

The System version, CPU0 F/W version, and CPU1 SDK version all match what I've been testing with, and we're both using USB 3.0 type A. The only difference I've noticed between us is the size of the upload file, and that's because I've been using an older version of gcc-arm-none-eabi, so I'm not sure why I can't reproduce.

Do you have any other devices you can connect to you computer through USB? Have you noticed that they have or have not been communicating well?

jwalk511 commented 5 years ago

If you suspect that the physical ports may be an issue you can follow the steps at https://www.makeuseof.com/tag/mac-hardware-diagnostic-tests/ to run Apple Diagnostics and see if you get error code NDD001 (Possible problems with USB hardware), but I doubt that's the issue since you do get some connectivity. We can try giving you a version of the uploader with delays built in so it has more time to receive a response, though that may not come until later.

Qrtn commented 5 years ago

Thanks very much for your help. I've never really had a problem with other USB devices. I will be testing it on another MacBook (though that will take some time); meanwhile I am also testing uploads on another Windows computer.

Are you also using a Mac? And do your upload speeds take upwards of a minute as well?

jwalk511 commented 5 years ago

I'm using macOS High Sierra version 10.13.6 on a 2017 27-inch iMac through a USB A 3.0 port with prosv5 cli version 3.1.2.

The only appreciable differences I've noticed is that

I'm not on a laptop
I'm possibly running a computer made in a different year

My upload times are in a few seconds, but your slow upload speeds are almost certainly related to whatever is causing total failure

jwalk511 commented 5 years ago

I'm going to sign off for the night. We'll test with other machines as they become available, but I'm afraid there isn't much we can do until we can reproduce the issue

Qrtn commented 5 years ago

Thanks again for your help. I ran a hardware diagnostics test and there seems to be no problem. I'm currently using a retina mid-2012 MBP and will do my best to reproduce the issue on another computer.

Edit: I'm not sure if this helps, but uploading works fine with VEX Coding Studio on the same computer.

Qrtn commented 5 years ago

I just booted up Arch Linux inside VirtualBox on the same computer and installed the latest version of pros-cli3 via pip (along with the arm-none-eabi dependencies). When I forward the V5 to the virtual machine and upload a PROS project, it works perfectly.

HotelCalifornia commented 5 years ago

we pushed a potential fix to the develop branch. you can test it by running the following commands:

> brew update
> brew unlink pros-cli
> brew install pros-cli --HEAD

Qrtn commented 5 years ago

Unfortunately the upload didn't work. The ini and bin file upload were switched though.

Uploading /Users/jeffrey/Documents/test-upload-mac/bin/output.bin to v5 device on /dev/cu.usbmodem1421 as test-upload-mac to slot 1                                                                      
Uploading slot_1.ini [####################################] 100%
Uploading slot_1.bin (/Users/jeffrey/Documents/test-upload-mac/bin/output.bin) [#-----------------------------------]   2% 0d 00:02:12                                                                   
ERROR - pros.cli.upload:upload - Couldn't find the response header in the device response. Got  but was expecting aa55                                                                                   
  File "/usr/local/Cellar/pros-cli/HEAD-df2850d/libexec/lib/python3.7/site-packages/pros/serial/devices/vex/vex_device.py", line 69, in _rx_packet                                                       
    raise IOError(f"Couldn't find the response header in the device response. "
OSError: Couldn't find the response header in the device response. Got  but was expecting aa55

Full output of prosv5 --debug upload

edjubuh commented 5 years ago

Can you run those brew commands again? I've halved the packet size from 4096 byte chunks to 2048 byte chunks to see if that helps resolve your issue.

Qrtn commented 5 years ago

That didn't seem to do it either. Most of the uploads now actually break at 0 percent.

HotelCalifornia commented 5 years ago

Just to make sure, you don't have VCS open while you're using PROS to upload, right?

Qrtn commented 5 years ago

No, VCS is closed. When it is open, PROS says that the resource is busy.

Qrtn commented 5 years ago

We just tested the PROS uploading on another MacBook Pro on High Sierra 10.13.6. It's having the same error as the one on the original Mac. So I think this is macOS-specific issue.

HotelCalifornia commented 5 years ago

@Qrtn have you been using the same USB cable for all these tests?

Qrtn commented 5 years ago

I have. I can try using a different USB cable tomorrow.

HotelCalifornia commented 5 years ago

@Qrtn did you ever try a new cable?

NoMod-Programming commented 5 years ago

Hi, I'm hoping that I can provide a bit of info here, since I've had a similar issue with Ubuntu 18.04 on a Macbook Pro (2013), and found a bit of a workaround: If I plug in a v5 brain, wait about a minute or two without trying to access any of the serial ports for the brain, and then download, it works. This is with multiple USB cables, and fuser /dev/ttyACM0 as root doesn't show any processes using the serial port until then, even though it's "in use" for about a minute until I can actually open it.

HotelCalifornia commented 5 years ago

Closing due to inactivity. If you're still having problems with this, feel free to reopen

pieceofpie commented 5 years ago

I have the same error to upload to v5 brain with macbook. window seems fine

HotelCalifornia commented 5 years ago

We're still looking for a reliable way to reproduce this issue. Any further information you can provide regarding what was happening when you got this error will be helpful

pieceofpie commented 5 years ago

I install pros as suggested in the instruction install brew brew tap purduesigbots/pros brew cask install gcc-arm-embedded pros-editor.

I also install atom, git, and python separately. I also try to uninstall and reinstall several times. Same error when upload to v5 brain.

Let me know anything else you need to know.

pbchase commented 5 years ago

I am also unable to upload from MacOSX to V5. I am running pros-cli 3.1.3 on MacOSX High Sierra 10.13.6:

→ brew list pros-cli
/usr/local/Cellar/pros-cli/3.1.3/bin/prosv5
/usr/local/Cellar/pros-cli/3.1.3/libexec/bin/ (27 files)
/usr/local/Cellar/pros-cli/3.1.3/libexec/lib/ (2378 files)
/usr/local/Cellar/pros-cli/3.1.3/libexec/.Python

Here's a log of my build and upload session

(20:50:29) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✗) 
→ prosv5 build all
Cleaning project
-n Compiling src/autonomous.cpp 
-e \x1b[32;01m[OK]\x1b[0m
-n Compiling src/initialize.cpp 
-e \x1b[32;01m[OK]\x1b[0m
-n Compiling src/opcontrol.cpp 
-e \x1b[32;01m[OK]\x1b[0m
-n Adding timestamp 
-e \x1b[32;01m[OK]\x1b[0m
-n Linking project with libpros,okapilib 
-e \x1b[32;01m[OK]\x1b[0m
Section sizes:
   text    data     bss   total     hex filename
459.35KB  3.22KB  2.59MB  3.04MB  3098a6 bin/output.elf
-n Creating bin/output.bin for VEX EDR V5 
-e \x1b[32;01m[DONE]\x1b[0m
Capturing metadata for PROS Editor...
(20:51:04) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✗) 
→ prosv5 lsusb
VEX EDR V5 System Ports:
/dev/cu.usbmodem1411 - VEX Robotics V5 Brain - 00000000
VEX EDR V5 User ports:
/dev/cu.usbmodem1413 - VEX Robotics V5 Brain - 00000000
There are no connected VEX EDR Cortex Microcontroller Ports
(20:51:10) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✗) 
→ prosv5 upload --slot=3
Uploading /Users/pbc/vex_projects/okapi_drive/bin/output.bin to v5 device on /dev/cu.usbmodem1411 as okapi_drive to slot 3
Uploading slot_3.ini [####################################] 100%
Uploading slot_3.bin (/Users/pbc/vex_projects/okapi_drive/bin/output.bin) [##----------------------------------]   6% 0d 00:00:55
ERROR - pros.cli.upload:upload - Couldn't find the response header in the device response. Got  but was expecting aa55
  File "/usr/local/Cellar/pros-cli/3.1.3/libexec/lib/python3.7/site-packages/pros/serial/devices/vex/vex_device.py", line 69, in _rx_packet
    raise IOError(f"Couldn't find the response header in the device response. "
OSError: Couldn't find the response header in the device response. Got  but was expecting aa55
We detected something went wrong! Would you like to send a bug report to the PROS Development team? [Y/n]: y
Sending report...
Sentry is attempting to send 1 pending error messages
Waiting up to 10 seconds
Press Ctrl-C to quit
(20:51:39) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✗)

I ran the brew commands to reinstall the pros-cli from HEAD, but the results were differently bad:

→ brew list pros-cli
/usr/local/Cellar/pros-cli/HEAD-96ce7d0/bin/prosv5
/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/bin/ (27 files)
/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/ (2374 files)
/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/.Python
(21:46:16) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✗) 
→ prosv5 lsusb
Traceback (most recent call last):
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/bin/prosv5", line 6, in <module>
    from pkg_resources import load_entry_point
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/python3.7/site-packages/pkg_resources/__init__.py", line 3126, in <module>
    @_call_aside
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/python3.7/site-packages/pkg_resources/__init__.py", line 3110, in _call_aside
    f(*args, **kwargs)
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/python3.7/site-packages/pkg_resources/__init__.py", line 3139, in _initialize_master_working_set
    working_set = WorkingSet._build_master()
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/python3.7/site-packages/pkg_resources/__init__.py", line 581, in _build_master
    ws.require(__requires__)
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/python3.7/site-packages/pkg_resources/__init__.py", line 898, in require
    needed = self.resolve(parse_requirements(requirements))
  File "/usr/local/Cellar/pros-cli/HEAD-96ce7d0/libexec/lib/python3.7/site-packages/pkg_resources/__init__.py", line 784, in resolve
    raise DistributionNotFound(req, requirers)
pkg_resources.DistributionNotFound: The 'rfc6266' distribution was not found and is required by pros-cli-v5
(21:46:19) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✗)

HotelCalifornia commented 5 years ago

Yeah, don't install from HEAD. The last thing we pushed there was a test, and it hasn't been updated since.

Someone on discord the other day reminded me of #29, which may fix this issue. I'll update the branch the HEAD formula points to later today with that fix, so we can see if that works.

pbchase commented 5 years ago

Yeah, I backed the HEAD install out pretty fast. ;-) Let me know when you need a test of the PR #29 commits.

HotelCalifornia commented 5 years ago

@pbchase I've updated and pushed the test change to HEAD. let me know how it goes

pieceofpie commented 5 years ago

recently update to the MacOS mojave and reinstall the pros. stuck in the uploading forever.

brew cask reinstall gcc-arm-embedded pros-editor

prosv5 upload --slot 5 MacBookPro:v5debug $ prosv5 upload --slot 5 Uploading /Users/BitTorrent Sync/v5debug/bin/output.bin to v5 device on /dev/cu.usbmodem14101 as v5debug to slot 5 Uploading slot_5.ini [####################################] 100% Uploading slot_5.bin (/Users/BitTorrent Sync/v5debug/bin/output.bin) [------------------------------------] 0%

pbchase commented 5 years ago

I reinstalled pros-cli with the --HEAD option, but it failed again in the same way as the initial report:

ERROR - pros.cli.upload:upload - Couldn't find the response header in the device response. Got  but was expecting aa55
  File "/usr/local/Cellar/pros-cli/HEAD-ae037ea/libexec/lib/python3.7/site-packages/pros/serial/devices/vex/vex_device.py", line 69, in _rx_packet
    raise IOError(f"Couldn't find the response header in the device response. "
OSError: Couldn't find the response header in the device response. Got  but was expecting aa55

Here's the entire session:

(20:43:00) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✓) 
→ brew list pros-cli
/usr/local/Cellar/pros-cli/HEAD-ae037ea/bin/prosv5
/usr/local/Cellar/pros-cli/HEAD-ae037ea/libexec/bin/ (27 files)
/usr/local/Cellar/pros-cli/HEAD-ae037ea/libexec/lib/ (2378 files)
/usr/local/Cellar/pros-cli/HEAD-ae037ea/libexec/.Python
(20:43:16) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✓) 
→ prosv5 build all
Cleaning project
-n Compiling src/autonomous.cpp 
-e \x1b[32;01m[OK]\x1b[0m
-n Compiling src/initialize.cpp 
-e \x1b[32;01m[OK]\x1b[0m
-n Compiling src/opcontrol.cpp 
-e \x1b[32;01m[OK]\x1b[0m
-n Adding timestamp 
-e \x1b[32;01m[OK]\x1b[0m
-n Linking project with libpros,okapilib 
-e \x1b[32;01m[OK]\x1b[0m
Section sizes:
   text    data     bss   total     hex filename
459.44KB  3.22KB  2.59MB  3.04MB  30990e bin/output.elf
-n Creating bin/output.bin for VEX EDR V5 
-e \x1b[32;01m[DONE]\x1b[0m
Capturing metadata for PROS Editor...
(20:45:08) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✓) 
→ prosv5 lsusb
VEX EDR V5 System Ports:
/dev/cu.usbmodem1421 - VEX Robotics V5 Brain - 00000000
VEX EDR V5 User ports:
/dev/cu.usbmodem1423 - VEX Robotics V5 Brain - 00000000
There are no connected VEX EDR Cortex Microcontroller Ports
(20:45:13) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✓) 
→ prosv5 upload --slot=3
Uploading /Users/pbc/vex_projects/okapi_drive/bin/output.bin to v5 device on /dev/cu.usbmodem1421 as okapi_drive to slot 3
Uploading slot_3.ini [####################################] 100%
Uploading slot_3.bin (/Users/pbc/vex_projects/okapi_drive/bin/output.bin) [------------------------------------]   2% 0d 00:05:26
ERROR - pros.cli.upload:upload - Couldn't find the response header in the device response. Got  but was expecting aa55
  File "/usr/local/Cellar/pros-cli/HEAD-ae037ea/libexec/lib/python3.7/site-packages/pros/serial/devices/vex/vex_device.py", line 69, in _rx_packet
    raise IOError(f"Couldn't find the response header in the device response. "
OSError: Couldn't find the response header in the device response. Got  but was expecting aa55
We detected something went wrong! Would you like to send a bug report to the PROS Development team? [Y/n]: y
Sending report...
Sentry is attempting to send 1 pending error messages
Waiting up to 10 seconds
Press Ctrl-C to quit
(20:45:35) ± [pbc@MyMac.local] ~/vex_projects/okapi_drive (master ✓)

HotelCalifornia commented 5 years ago

Thanks for testing. Can you try uploading again with the --debug flag and share the output of that?

oliverwjay commented 5 years ago

I am having the same issue on High Sierra with PROS cli 3.1.3 installed using pip. I am getting the following output from prosv5 upload --debug PROS Upload response.txt

Bottersnike commented 5 years ago

@oliverwjay If you go into the installed pros source, then go to pros/serial/devices/vex/vex_device and change the 0.01 in the line

def _rx_packet(self, timeout: float = 0.01) -> Dict[str, Union[Union[int, bytes, bytearray], Any]]:

(around line 50) to something like timeout: float = 1.0 do you still get the same error?

oliverwjay commented 5 years ago

It appears that it is not exiting because of the timeout. Even setting the timeout to 30s, it is still raising the error within a few seconds.

Bottersnike commented 5 years ago

Are you able to toss print(repr(b)) just after b = self.port.read(1) to see what's going on there?

oliverwjay commented 5 years ago

Here is the output PROS Upload rep b.txt

Bottersnike commented 5 years ago

And does the error persist if you replace time.time() - start_time < timeout with True?

oliverwjay commented 5 years ago

It stops responding. It appears to be receiving a timeout of .1 _txrx_ext_packet in v5_device.py. By increasing that it lasts longer, but still errors.

HotelCalifornia commented 5 years ago

from the last log you posted, it looks like we retry the packet 3 times (which is by design) and just get nothing back from the v5 device. this is really perplexing to me.

someone mentioned to me that, in their experience, unplugging the USB cable and putting it in a different port solves the issue temporarily. does this work for you?

oliverwjay commented 5 years ago

Switching between my usb ports has not had any noticeable affect for me

HotelCalifornia commented 5 years ago

Switching between my usb ports has not had any noticeable affect for me

Okay, that's about what I expected.

oliverwjay commented 5 years ago

I just tried running it through a simple USB 2.0 hub and it worked fine. I am guessing it has to do with the unusual handling of the USB 3.0/2.0 combined ports

HotelCalifornia commented 5 years ago

I just tried running it through a simple USB 2.0 hub and it worked fine. I am guessing it has to do with the unusual handling of the USB 3.0/2.0 combined ports

now that's interesting, and may explain why this has been reported as happening on surface tablets as well.

Bottersnike commented 5 years ago

I have achieved highly reproducible results:

+ [OK ] Laptop USB 3
+ [OK ] Laptop USB 2

- [ERR] Dell FPIO "USB2 Enhanced Host controller"
- [ERR] Dell FPIO "USB 3.0 eXtensible Host Controller"
+ [OK ] Dell FPIO "USB2 Enhanced Host controller" -> USB 2.0 Hub

+ [OK ] Dell RPIO "USB2 Enhanced Host controller"
+ [OK ] Dell RPIO "USB 3.0 eXtensible Host Controller"
+ [OK ] Dell RPIO "USB2 Enhanced Host controller" -> USB 2.0 Hub

I'm thinking the problem is due to a difference in the physical connections to front-panel I/O (in this case) rather than rear-panel I/O. Without a doubt though, the workaround is to use a USB Hub.

Bottersnike commented 5 years ago

Update 8 minutes later: Just used the firmware update utility and it communicated fine in all situations. Then went back and tested pros: Worked perfectly.

I believe the issue to be a PySerial problem. When the DFU or VCS open a connection to a V5, they sent the following initial packets to the system driver: http://mystb.in/arosucecep.css When pros begins a connection, it sends: http://mystb.in/ibiyomobuq.css

Key differences:

Params to IOCTL_SERIAL_SET_CHARS differ
IOCTL_SERIAL_SET_HANDFLOW starts with 01 00 00 80 in VEX stuff instead of 01 00 00 00 in pros
Pros has a call to IOCTL_SERIAL_SET_TIMEOUTS

My thinking is that the cause for the fact that pyserial is producing about 3 times as many pre-data things is due to IOCTL_SERIAL_PURGE

Note: These two logs were recorded on my laptop which is not experiencing the issue as I don't have the tools installed on my Dell that are required to do serial introspection

HotelCalifornia commented 5 years ago

Note also that there seem to be two problems:

The edge case in packet size detection which is fixed by #29
The weird USB behavior as documented in @Bottersnike's comments

pbchase commented 5 years ago

I'm also having good results with the USB 2.0 hub workaround. Downloads complete in under 5 seconds.

purduesigbots / pros-cli