Flashing throws often a failure on RPi

[Icesory]

First of all. Big thanks for this great work!

I have build an Plugin for Pimatic https://github.com/Icesory/pimatic-arduino-updater. When we run a flash process on an RPi often an Time out error occurs. This is testet with Nano328(CH340), Nano328(FT232RL), ProMini 5V328(FT232RL).

Most times this error occurs:

connected
reset complete.
flashing, please wait...
flash complete(red)
{ cause: [Error: Sending 3020: receiveData timeout after 400ms], isOperational: true}

Or this

connected
reset complete.
flashing, please wait...
flash complete(red)
{ cause: [Error: Sending 55001620: receiveData timeout after 400ms], isOperational: true}

This is an complete log from Pimatic with an other failure

22:31:55.805 [pimatic-arduino-updater] Start Arduino flash for homeduino
connected
reset complete.
flashing, please wait...
22:32:02.960 [pimatic] A uncaught exception occured: TypeError: Cannot call method 'toString' of undefined
22:32:02.960 [pimatic]>    at /home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/index.js:311:44
22:32:02.960 [pimatic]>    at /home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/sendCommand.js:37:16
22:32:02.960 [pimatic]>    at finished (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:38:5)
22:32:02.960 [pimatic]>    at null._onTimeout (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:43:7)
22:32:02.960 [pimatic]>    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
22:36:24.314 [pimatic]> This is most probably a bug in pimatic or in a module, please report it!
22:36:24.360 [pimatic] shutting pimatic down...

The used node version is v0.10.24. On my dev machine (Ubuntu 14.04LTS) all works right. But on the RPi almost every flash throws an error. But in most times the Arduino is flashed with the given hexfile.

Any suggestions to isolate the failure?

[noopkat]

Hi @Icesory!

Uh oh, looks like a few teething issues in the RaspPi for flashing, huh. Thank you so much for the multiple error logs, this is really very helpful for me to look into what's perhaps going on. I have a couple of Raspberry Pi's in possession, so I'll start by trying to replicate your experience with some boards.

Just two clarifying questions first to help me further debug:

1. Which distro of Linux are you running on the Pi (I have Raspian on both of mine)?
2. Which edition Pi do you have (Model A, A+, B, B+, 2, Zero, etc)?

Thanks! PS. Pimatic looks really cool btw!

[Icesory]

1. We have tested with Raspbian wheezy. A test with Jessi will follow.
2. As pi we have tested the B+ and Pi2.

I have tested only in combination with Pimatic. On the weekend I try a avrgirl-arduino only test, to see if it a load problem.

[Icesory]

I have done some tests. To find the bug i used a simple javascript file to test the module

var Avrgirl = require('avrgirl-arduino');
var Promise = require('bluebird');

var board = 'nano';
var port = '/dev/ttyUSB0';
var file = '/home/pi/pimatic-app/node_modules/pimatic-homeduino/arduino/Homeduino_nano328.hex';

var avrgirl = new Avrgirl({
  board: board,
  port: port,
  debug: true
});
console.info('Flash normal')
avrgirl.flash(file, function (error) {
  if (error) {
    console.error(error);
  } else {
    console.info('done.');
  }

  Promise.promisifyAll(Avrgirl.prototype)

  var avrgirl = new Avrgirl({
    board: board,
    port: port,
    debug: true
  });
  console.info('Flash async')
  avrgirl.flashAsync(file).then( function (error) {
    if (error) {
      console.error(error);
    } else {
      console.info('done.');
    }
  });
});

I included the bluebird library, because we used it as promises in pimatic. Following test did i run: 1 Test

stress --cpu 1 --timeout 120s

Result: 5 out of 5 Both uploads completed.

2 Test

stress --cpu 1 --io 1 --vm 1 --vm-bytes 128M --timeout 120s

Result: 5 out of 5 Both uploads completed.

3 Test

stress --cpu 1 --io 1 --vm 1 --vm-bytes 128M --hdd 1 --timeout 120s

Result: 2 out of 5 Both uploads completed.

3 out of 5 The first upload runs. The second crashed.

Unhandled rejection Error: Sending 640080461020408001020408102001020408102004040404040404040202020202020303030303030000000023002600290000000000250028002b0000000000240027002a00b603900611241fbecfefd8e0debfcdbf11e0a0e0b1e0ece1fde202c005900d92a43fb107d9f717e0a4efb1e001c01d92a331b107e1f710e0c6ecd0e004c020: receiveData timeout after 400ms
    at /home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/sendCommand.js:36:17
    at finished (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:38:5)
    at null._onTimeout (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:43:7)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)

Unhandled rejection Error: Sending 64008046df91cf910c943107cf92df92ef92ff920f931f93cf93df93cdb7deb764970fb6f894debf0fbecdbf80910202882371f10e94ce0a882309f48dc00e94c70a8c010e941f0a809fb001819f700d909f700d11244ae050e080e193e00e94f2076ce371e080e193e00e9431078091f4018f5f8093f401803108f46dc01092f4016ae020: receiveData timeout after 400ms
    at /home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/sendCommand.js:36:17
    at finished (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:38:5)
    at null._onTimeout (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:43:7)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)

Unhandled rejection Error: Sending 640080461020408001020408102001020408102004040404040404040202020202020303030303030000000023002600290000000000250028002b0000000000240027002a00b603900611241fbecfefd8e0debfcdbf11e0a0e0b1e0ece1fde202c005900d92a43fb107d9f717e0a4efb1e001c01d92a331b107e1f710e0c6ecd0e004c020: receiveData timeout after 400ms
    at /home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/sendCommand.js:36:17
    at finished (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:38:5)
    at null._onTimeout (/home/pi/pimatic-app/node_modules/pimatic-arduino-updater/node_modules/avrgirl-arduino/node_modules/stk500/lib/receiveData.js:43:7)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)

4 Test Now i testet only the Promisifed version of avrgirl-arduino

stress --cpu 1 --io 1 --vm 1 --vm-bytes 128M --hdd 1 --timeout 120s

Result: 5 out of 5 Uploads completed

5 Test I startet Pimatic and used the async upload function to flash the arduino. Result: 5 out of 5 Uploads completed

So in think it isn´t really a problem of your arduino flasher. But now i have no idea what can happen the problem. @sweetpi

[noopkat]

@Icesory thanks for giving that a thorough test with lots of scenarios :grin: I have a Pi B and a Pi 2, so I'll also give it a go this weekend.

I have never 'promisified' avrgirl-arduino before, so I'm really happy to see that it wraps correctly and works!

One small thing I thought was odd though, was in your crash log, the node package in the stack trace is stk500. However, if you're flashing an Arduino Nano, then it should be running the avr109 package instead. So I am confused as to why it's selecting the incorrect communication protocol for the nano microchip?

[Icesory]

That is indeed interesting. I use only arduino clones. And for all tests I used an Arduino Nano(Atmega328P) with an FT232RL usart to USB bridge. I think the stk500 is the right protocol but I am not so familiar with alle the different bootloaders.

[noopkat]

Ah! I missed that detail earlier. yes, stk500 is the correct protocol, you are right. I was thinking of the Arduino Micro :grinning:

[Icesory]

I read some stuff in your blog. And saw this section:

I wrote the reset functionality mostly without a hitch, but hit a snag with node-serialport. In some cases (sometimes operating system related), calling serialPort.close() doesn't truly close the connection. This means that it's possible for the board to never reset correctly. No reset = no bootloader mode, and you're going to have a sad time trying to program the chip.

In pimatic the other plugins open the their SerialPorts to communicate with the arduinos. When their discover that the firmware isn't up to date a upload request is generated. In this request the plugin is forced to close his comport and after this avrgirl-arduino uploads an new firmware to the avr chip. So in some cases it is possible that the other plugin doesn't close the comport probably? How can I discover this and how can this be prevented?

[noopkat]

ah, I see! This is a reasonable theory.

The thing that may disprove it is that when you look at the first byte that was sent (or attempted) just before the crash happened, you'll see it's 64, or 0x64. This byte, being at the beginning of the message being sent to the board and having a value of 64 is the opcode for 'program page'.

Therefore, the reset and the serialport reconnection + sending preparation opcodes seemed to have happened just fine. I can see this in the other logs too.

Still a mystery, perhaps?

[Icesory]

You are right. The errors in my first post do not related to an open serialport. But i had such errors too :-(

Is it possible, that your code throws a other strings as "flash complete(red)" when a error occurs? Eventually something meaningful like "flash abort: Can´t write page NUMBER"?

Ps: Sorry for my bad English. I am from Germany and still learning.

[noopkat]

@Icesory hey, just checking in. I'm working on offering better and more clear errors and logging, and will keep you posted on the progress of this 😁 . I'm closing this issue for now, feel free to reopen if you have further questions!