bootloader timeout

Hello to everybody.

The question is "What time after resetting Arduino Uno r3 bootloader waits for upload commands?"

I'm working on uploading from Android devices using libusb (modifing avrdude) and i'm in stuck - bootloader does not wait but starts the sketch right after reset.

Test sketch (uploaded to the board):

int led = 13;
void setup() {
  pinMode(led, OUTPUT);
  digitalWrite(led, HIGH);
  delay(3000);
  digitalWrite(led, LOW);
  Serial.begin(115200);
}

void loop() {
  // send back token byte
  while (Serial.available()) {
    int b = Serial.read();
    if (b == 0x30) {
      digitalWrite(led, HIGH);
    }
    Serial.write(0x45);
  }

}

So you can see that if byte 0x30 received it sets LED to HIGH and replies 0x45 byte to every incoming byte. The problem is that bootloader should wait for about half second for sync/upload commands or start uploaded sketch.

usbdev_drain sends sync command ('0') and bootloader should answer [0x14, 0x10] according to the sources: https://github.com/arduino/Arduino/blob/master/hardware/arduino/bootloaders/atmega/ATmegaBOOT_168.c

BUT it does not wait and starts the sketch right after reset (avrdude libusb log):

08-02 17:19:51.172: WARN/System.err(13204): *** set rts/dtr = 0
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.035953 debug [libusb_get_next_timeout] next timeout in 0.099970s
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.036167 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.036502 debug [handle_events] poll() 2 fds with timeout in 100ms
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.037448 debug [handle_events] poll() returned 1
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.037662 debug [reap_for_handle] urb type=2 status=0 transferred=0
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.038150 debug [handle_control_completion] handling completion status 0
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.038364 debug [usbi_handle_transfer_completion] transfer 0x288410 has callback 0x57d38
08-02 17:19:51.172: WARN/System.err(13204): libusb: 0.038883 debug [ctrl_transfer_cb] actual_length=0
08-02 17:19:51.222: WARN/System.err(13204): *** set rts/dtr = 1
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.090462 debug [libusb_get_next_timeout] next timeout in 0.100000s
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.090981 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.091439 debug [handle_events] poll() 2 fds with timeout in 100ms
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.091836 debug [handle_events] poll() returned 1
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.092355 debug [reap_for_handle] urb type=2 status=0 transferred=0
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.092568 debug [handle_control_completion] handling completion status 0
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.093026 debug [usbi_handle_transfer_completion] transfer 0x288410 has callback 0x57d38
08-02 17:19:51.222: WARN/System.err(13204): libusb: 0.093240 debug [ctrl_transfer_cb] actual_length=0
08-02 17:19:51.272: WARN/System.err(13204): set baud in dtr_rts
08-02 17:19:51.272: WARN/System.err(13204): setting baud rate: 115200 ...
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.144575 debug [libusb_get_next_timeout] no URB with timeout or all handled by OS; no timeout!
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.145033 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.145246 debug [handle_events] poll() 2 fds with timeout in 60000ms
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.145460 debug [handle_events] poll() returned 1
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.145674 debug [reap_for_handle] urb type=2 status=0 transferred=7
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.146223 debug [handle_control_completion] handling completion status 0
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.146406 debug [usbi_handle_transfer_completion] transfer 0x288410 has callback 0x57d38
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.146620 debug [ctrl_transfer_cb] actual_length=7
08-02 17:19:51.282: WARN/System.err(13204): usbdev_drain...
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.147017 debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
08-02 17:19:51.282: WARN/System.err(13204): ioctl in submit_bulk_transfer() for fd = 4
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.148512 debug [libusb_get_next_timeout] next timeout in 0.098474s
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.148848 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.149397 debug [handle_events] poll() 2 fds with timeout in 99ms
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.149824 debug [handle_events] poll() returned 1
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.150099 debug [reap_for_handle] urb type=3 status=-121 transferred=1
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.150252 debug [handle_bulk_completion] handling completion status -121 of bulk urb 1/1
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.150252 debug [handle_bulk_completion] last URB in transfer --> complete!
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.150282 debug [usbi_handle_transfer_completion] transfer 0x288410 has callback 0x57ce8
08-02 17:19:51.282: WARN/System.err(13204): libusb: 0.150282 debug [bulk_transfer_cb] actual_length=1
08-02 17:19:51.282: WARN/System.err(13204): @@@ received for flushing: 45

here you can see, that avrdude resets the board using rts/dtr:

08-02 17:19:51.222: WARN/System.err(13204): *** set rts/dtr = 1

and then sends '0' and flushes incoming buffer (which is expected to be [0x14, 0x10]):

08-02 17:19:51.282: WARN/System.err(13204): usbdev_drain...

and incoming buffer contains token byte 0x45 from the sketch:

08-02 17:19:51.282: WARN/System.err(13204): @@@ received for flushing: 45

it means that bootloader started and started the sketch right after reset and it did not wait as time interval is only 60ms (08-02 17:19:51.282 - 08-02 17:19:51.222)

How did you upload the sketch if the bootloader isn't working?

First time i uploaded it from pc, after that i’m trying to upload from android device using modified avrdude for android.
The sketch was uploaded just to reply anything on android device to make sure it works and to display it’s state.

The bootloader timeout is somewhat longer than 1s (it has the three initial LED flashes, followed by running with a 1s timeout.)

Are you sure that the reset code is working? Do you see the pin13 flashes when it starts the upload? Could the 45 be left over in the USB buffers from when the sketch was running before the reset?

The bootloader timeout is somewhat longer than 1s (it has the three initial LED flashes, followed by running with a 1s timeout.)

Are you sure that the reset code is working?

I'm pretty sure, it works.

The first, the log seems to be okay:

*** set rts/dtr = 0
08-03 16:36:00.627: WARN/System.err(6074): libusb-compat debug: usb_control_msg: RQT=21 RQ=22 V=0 I=0 len=0 timeout=100
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.059576 debug [libusb_get_next_timeout] next timeout in 0.099970s
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.059637 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.059668 debug [handle_events] poll() 2 fds with timeout in 100ms
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.061468 debug [handle_events] poll() returned 1
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.061530 debug [reap_for_handle] urb type=2 status=0 transferred=0
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.061560 debug [handle_control_completion] handling completion status 0
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.061560 debug [usbi_handle_transfer_completion] transfer 0x286408 has callback 0x57d38
08-03 16:36:00.627: WARN/System.err(6074): libusb: 0.061591 debug [ctrl_transfer_cb] actual_length=0
08-03 16:36:00.677: WARN/System.err(6074): *** set rts/dtr = 1
08-03 16:36:00.677: WARN/System.err(6074): libusb-compat debug: usb_control_msg: RQT=21 RQ=22 V=1 I=0 len=0 timeout=100
08-03 16:36:00.677: WARN/System.err(6074): libusb: 0.113078 debug [libusb_get_next_timeout] next timeout in 0.099969s
08-03 16:36:00.677: WARN/System.err(6074): libusb: 0.113200 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-03 16:36:00.677: WARN/System.err(6074): libusb: 0.113262 debug [handle_events] poll() 2 fds with timeout in 100ms
08-03 16:36:00.677: WARN/System.err(6074): libusb: 0.113536 debug [handle_events] poll() returned 1
08-03 16:36:00.677: WARN/System.err(6074): libusb: 0.113628 debug [reap_for_handle] urb type=2 status=0 transferred=0
08-03 16:36:00.687: WARN/System.err(6074): libusb: 0.113689 debug [handle_control_completion] handling completion status 0
08-03 16:36:00.687: WARN/System.err(6074): libusb: 0.113780 debug [usbi_handle_transfer_completion] transfer 0x286408 has callback 0x57d38
08-03 16:36:00.687: WARN/System.err(6074): libusb: 0.113841 debug [ctrl_transfer_cb] actual_length=0

Do you see the pin13 flashes when it starts the upload?

The second, all 3 LED flash for some time, so it does reset actually. Though i'm not sure at which moment (is reset actually done in the moment of set_rts_dtr() invocation OR set_rts_dtr() invocation just adds transfer in the queue).

Could the 45 be left over in the USB buffers from when the sketch was running before the reset?

This is very good idea as i can't understand, why it's replying with 0x45 but it's bootloader who is expected to work at that time (usb_drain sends 'sync' command to bootloader and flushes response):

08-03 16:36:00.737: WARN/System.err(6074): usbdev_drain...
08-03 16:36:00.737: WARN/System.err(6074): libusb-compat debug: usb_bulk_io: endpoint 83 size 64 timeout 100
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.166306 debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
08-03 16:36:00.737: WARN/System.err(6074): ioctl in submit_bulk_transfer() for fd = 4
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.166459 debug [libusb_get_next_timeout] next timeout in 0.099847s
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.166550 debug [libusb_handle_events_timeout_completed] doing our own event handling
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.166611 debug [handle_events] poll() 2 fds with timeout in 100ms
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.168137 debug [handle_events] poll() returned 1
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.168198 debug [reap_for_handle] urb type=3 status=-121 transferred=1
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.168290 debug [handle_bulk_completion] handling completion status -121 of bulk urb 1/1
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.168351 debug [handle_bulk_completion] last URB in transfer --> complete!
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.168442 debug [usbi_handle_transfer_completion] transfer 0x286408 has callback 0x57ce8
08-03 16:36:00.737: WARN/System.err(6074): libusb: 0.168748 debug [bulk_transfer_cb] actual_length=1
08-03 16:36:00.737: WARN/System.err(6074): @@@ received for flushing: 45

All this makes me think reset is done a bit later as response is received from sketch, but not from bootloader. So it can be another case instead or previous one (bootloader does not wait for delay and starts the sketch right after reset): the boards is reset after 'sync' command sent, thought 'sync' is sent after 'reset'..

I'm wondering if you still have the bootloader installed.

Can you show the fuse settings?

Bootloader is installed as i am able to flash the board from pc (just tried).

avrdude: Version 5.11, compiled on Sep  2 2011 at 18:52:52
         Copyright (c) 2000-2005 Brian Dean, http://www.bdmicro.com/
         Copyright (c) 2007-2009 Joerg Wunsch

         System wide configuration file is "/Applications/Arduino.app/Contents/Resources/Java/hardware/tools/avr/etc/avrdude.conf"
         User configuration file is "/Users/asmirnov/.avrduderc"
         User configuration file does not exist or is not a regular file, skipping

         Using Port                    : /dev/tty.usbmodem1411
         Using Programmer              : arduino
         Overriding Baud Rate          : 115200
avrdude: Send: 0 [30]   [20] 
avrdude: Send: 0 [30]   [20] 
avrdude: Send: 0 [30]   [20] 
avrdude: Recv: . [14] 
avrdude: Recv: . [10] 
         AVR Part                      : ATMEGA328P
         Chip Erase delay              : 9000 us
         PAGEL                         : PD7
         BS2                           : PC2
         RESET disposition             : dedicated
         RETRY pulse                   : SCK
         serial program mode           : yes
         parallel program mode         : yes
         Timeout                       : 200
         StabDelay                     : 100
         CmdexeDelay                   : 25
         SyncLoops                     : 32
         ByteDelay                     : 0
         PollIndex                     : 3
         PollValue                     : 0x53
         Memory Detail                 :

                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           eeprom        65    20     4    0 no       1024    4      0  3600  3600 0xff 0xff
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           flash         65     6   128    0 yes     32768  128    256  4500  4500 0xff 0xff
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           lfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           hfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           efuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           lock           0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           calibration    0     0     0    0 no          1    0      0     0     0 0x00 0x00
                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           signature      0     0     0    0 no          3    0      0     0     0 0x00 0x00

I've reviewed bootloader code (https://github.com/arduino/Arduino/blob/master/hardware/arduino/bootloaders/atmega/ATmegaBOOT_168.c) and i have an idea. What if some data (like 'set line state') is sent and errors count is more then MAX_ERROR_COUNT (5)? This can explain why it is not waiting and starts the sketch instantly:

if (++error_count == MAX_ERROR_COUNT)
    app_start();

Can anyone change bootloader code to check this or explain me how to do it myself? f.e. set pin 12 as OUTPUT and set HIGH if error count exceeds max just to check this idea?