1

I'm working on wireless upload to Arduino and i've succeed for Mega2560. But when trying to upload to Uno it does not wait for upload commands. I'm doing reset using GPIO and HM-10 BLE module wired with capacitor and resistor and wired to MCU's reset pin just it's done for USB. I think it remembers somehow how it was reset - by pressing hardware RESET button, by USB DTR/RTS or other way. The problem is that when resetting for USB it waits for upload commands after reset and for BLE it does not.

I've viewed optiboot bootloader code but i'm not sure i understand it correctly. Any clue on how to do it?

Update1:

2015-09-05 15:51:36.682 xctest[60180:7754033] [TRACE  ] [OUT]: Send: A [0x41] T [0x54] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] 1 [0x31] 
2015-09-05 15:51:36.682 xctest[60180:7754033] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 8
2015-09-05 15:51:36.735 xctest[60180:7754033] [DEBUG  ] [OUT]: Sending 8 bytes
2015-09-05 15:51:36.736 xctest[60180:7754033] [TRACE  ] [OUT]: Send: A [0x41] T [0x54] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] 0 [0x30] 
2015-09-05 15:51:36.736 xctest[60180:7754033] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 8
2015-09-05 15:51:36.788 xctest[60180:7754033] [DEBUG  ] [   ]: Draining for 300 ms ...
2015-09-05 15:51:36.788 xctest[60180:7754033] [TRACE  ] [IN ]: Start reading
2015-09-05 15:51:37.053 xctest[60180:7754082] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 1 [0x31] 
2015-09-05 15:51:37.053 xctest[60180:7754082] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 0 [0x30] 
2015-09-05 15:51:37.093 xctest[60180:7754033] [TRACE  ] [IN ]: Finish reading
2015-09-05 15:51:37.093 xctest[60180:7754033] [TRACE  ] [IN ]: Ble clear buffer
2015-09-05 15:51:37.093 xctest[60180:7754033] [DEBUG  ] [IN ]: Drained 18 bytes
2015-09-05 15:51:37.094 xctest[60180:7754033] [DEBUG  ] [OUT]: Sending 2 bytes
2015-09-05 15:51:37.094 xctest[60180:7754033] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-09-05 15:51:37.094 xctest[60180:7754033] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 2
2015-09-05 15:51:37.095 xctest[60180:7754033] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-05 15:51:37.096 xctest[60180:7754033] [TRACE  ] [IN ]: Start reading
2015-09-05 15:51:37.450 xctest[60180:7754084] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-05 15:51:37.450 xctest[60180:7754084] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-05 15:51:37.450 xctest[60180:7754084] [TRACE  ] [IN ]: Rx value received 2 bytes: . [0x14] . [0x10] 
2015-09-05 15:51:37.452 xctest[60180:7754033] [TRACE  ] [IN ]: Finish reading
2015-09-05 15:51:37.452 xctest[60180:7754033] [TRACE  ] [IN ]: Receive: . [0x14] 
2015-09-05 15:51:37.452 xctest[60180:7754033] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-05 15:51:37.453 xctest[60180:7754033] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-05 15:51:37.453 xctest[60180:7754033] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-05 15:51:37.454 xctest[60180:7754033] [TRACE  ] [IN ]: Having current receive buffer: . [0x10] 
2015-09-05 15:51:37.454 xctest[60180:7754033] [TRACE  ] [IN ]: Start reading
2015-09-05 15:51:37.454 xctest[60180:7754033] [TRACE  ] [IN ]: Finish reading
2015-09-05 15:51:37.455 xctest[60180:7754033] [TRACE  ] [IN ]: Receive: . [0x10] 
2015-09-05 15:51:37.455 xctest[60180:7754033] [DEBUG  ] [IN ]: Read 1 bytes, actually received 1 bytes
2015-09-05 15:51:37.455 xctest[60180:7754033] [TRACE  ] [IN ]: Ble clear buffer
2015-09-05 15:51:37.455 xctest[60180:7754033] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-05 15:51:37.456 xctest[60180:7754033] [TRACE  ] [OUT]: Send: A [0x41] . [0x81]   [0x20] 
2015-09-05 15:51:37.456 xctest[60180:7754033] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-05 15:51:37.457 xctest[60180:7754033] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-05 15:51:37.457 xctest[60180:7754033] [TRACE  ] [IN ]: Start reading
2015-09-05 15:51:37.701 xctest[60180:7754084] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-05 15:51:37.701 xctest[60180:7754084] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-05 15:51:38.451 xctest[60180:7754082] [TRACE  ] [IN ]: Rx value received 5 bytes: h [0x68] e [0x65] l [0x6C] l [0x6C] o [0x6F] 
2015-09-05 15:51:38.452 xctest[60180:7754033] [TRACE  ] [IN ]: Finish reading

Update 2 (this is uploading to Uno over USB log):

2015-06-29 16:34:10.829 xctest[36585:3703900] [TRACE  ] [   ]: DTR/RTS supported by Serial, resetting
2015-06-29 16:34:11.140 xctest[36585:3703900] [DEBUG  ] [IN ]: Draining ...
2015-06-29 16:34:11.392 xctest[36585:3703900] [DEBUG  ] [IN ]: Drain done
2015-06-29 16:34:11.392 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 2 bytes
2015-06-29 16:34:11.392 xctest[36585:3703900] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-06-29 16:34:11.393 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.531 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] 
2015-06-29 16:34:11.531 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.532 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x10] 
2015-06-29 16:34:11.532 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 3 bytes
2015-06-29 16:34:11.532 xctest[36585:3703900] [TRACE  ] [OUT]: Send: A [0x41] . [0x81]   [0x20] 
2015-06-29 16:34:11.533 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.535 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] 
2015-06-29 16:34:11.536 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.536 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x04] 
2015-06-29 16:34:11.536 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.536 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x10] 
2015-06-29 16:34:11.537 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 3 bytes
2015-06-29 16:34:11.537 xctest[36585:3703900] [TRACE  ] [OUT]: Send: A [0x41] . [0x82]   [0x20] 
2015-06-29 16:34:11.537 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.540 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] 
2015-06-29 16:34:11.540 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.540 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x04] 
2015-06-29 16:34:11.540 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.541 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x10] 
2015-06-29 16:34:11.541 xctest[36585:3703900] [DEBUG  ] [   ]: STK500:initialize: n_extparms = 4
2015-06-29 16:34:11.541 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 22 bytes
2015-06-29 16:34:11.542 xctest[36585:3703900] [TRACE  ] [OUT]: Send: B [0x42] . [0x86] . [0x00] . [0x01] . [0x00] . [0x01] . [0x01] . [0x01] . [0x03] . [0xFF] . [0xFF] . [0xFF] . [0xFF] . [0x00] . [0x80] . [0x04] . [0x00] . [0x00] . [0x00] . [0x80] . [0x00]   [0x20] 
2015-06-29 16:34:11.542 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.548 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] 
2015-06-29 16:34:11.548 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.548 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x10] 
2015-06-29 16:34:11.548 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 7 bytes
2015-06-29 16:34:11.549 xctest[36585:3703900] [TRACE  ] [OUT]: Send: E [0x45] . [0x05] . [0x04] . [0xD7] . [0xC2] . [0x00]   [0x20] 
2015-06-29 16:34:11.549 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.552 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] 
2015-06-29 16:34:11.552 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.552 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x10] 
2015-06-29 16:34:11.553 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 2 bytes
2015-06-29 16:34:11.553 xctest[36585:3703900] [TRACE  ] [OUT]: Send: P [0x50]   [0x20] 
2015-06-29 16:34:11.553 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.556 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] 
2015-06-29 16:34:11.556 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 1 bytes
2015-06-29 16:34:11.556 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x10] 
2015-06-29 16:34:11.569 xctest[36585:3703900] Reading |                                                    | 0% 0ms
2015-06-29 16:34:11.570 xctest[36585:3703900] [DEBUG  ] [OUT]: Sending 2 bytes
2015-06-29 16:34:11.571 xctest[36585:3703900] [TRACE  ] [OUT]: Send: u [0x75]   [0x20] 
2015-06-29 16:34:11.571 xctest[36585:3703900] [DEBUG  ] [IN ]: Receiving 5 bytes
2015-06-29 16:34:11.572 xctest[36585:3703900] [TRACE  ] [IN ]: Received: . [0x14] . [0x1E] . [0x95] . [0x0F] . [0x10] 
2015-06-29 16:34:11.572 xctest[36585:3703900] Reading | ################################################## | 100% 2ms

Update 3:

i've modified bootloader (optiboot) to wait 4 seconds (instead of 1 second by default) and added blinking when character 0x41 (STK_GET_PARAMETER) arrives. Also i've uploaded 'echo' sketch to return what back everything that is sent to the board.

bootloader modifications (part):

// Set up watchdog to trigger after 4s
  watchdogConfig(WATCHDOG_4S); // 4ntoine: was WATCHDOG_1s

  /* Set LED pin as output */
  LED_DDR |= _BV(LED);

#ifdef SOFT_UART
  /* Set TX pin as output */
  UART_DDR |= _BV(UART_TX_BIT);
#endif

// #if LED_START_FLASHES > 0
  /* Flash onboard LED to signal entering of bootloader */
  // flash_led(2); // 4ntoine
// #endif

  /* Forever loop */
  for (;;) {
    /* get character from UART */
    ch = getch();

    if(ch == STK_GET_PARAMETER) {
      flash_led(2); // 4ntoine

      unsigned char which = getch();
      verifySpace();

      if (which == 0x82) {
         /*
           * Send optiboot version as "minor SW version"
           */
         putch(OPTIBOOT_MINVER);
      } else if (which == 0x81) {
           putch(OPTIBOOT_MAJVER);
      } else {
    /*
     * GET PARAMETER returns a generic 0x03 reply for
         * other parameters - enough to keep Avrdude happy
     */
    putch(0x03);
      }
    }

uploaded arduino sketch:

int LED = 13;

void setup() {
  // avoid misleading blinking
  pinMode(LED, OUTPUT);
  digitalWrite(LED, LOW);

  // to let us know when sketch starts
  Serial.begin(115200);
  Serial.write("hello");
}

void loop() {
  while (Serial.available()) {
    int incomingByte = Serial.read();
    Serial.write(incomingByte);
  }

}

log:

2015-09-13 20:52:57.011 xctest[55099:2968978] [INFO   ] [   ]: Found peripheral: <CBPeripheral: 0x100400af0 identifier = D92ECAAB-51A5-44D5-8C6C-536CD797867E, Name = "BleIos", state = disconnected>
2015-09-13 20:52:57.011 xctest[55099:2968978] [DEBUG  ] [   ]: Stop scanning
2015-09-13 20:52:57.012 xctest[55099:2968978] [INFO   ] [   ]: Connecting to <CBPeripheral: 0x100400af0 identifier = D92ECAAB-51A5-44D5-8C6C-536CD797867E, Name = "BleIos", state = disconnected>
2015-09-13 20:52:57.236 xctest[55099:2968989] [DEBUG  ] [   ]: Connected to peripheral <CBPeripheral: 0x100400af0 identifier = D92ECAAB-51A5-44D5-8C6C-536CD797867E, Name = "BleIos", state = connected>
2015-09-13 20:52:57.238 xctest[55099:2968989] [TRACE  ] [   ]: Discovered services for peripheral <CBPeripheral: 0x100400af0 identifier = D92ECAAB-51A5-44D5-8C6C-536CD797867E, Name = "BleIos", state = connected>
2015-09-13 20:52:57.238 xctest[55099:2968989] [DEBUG  ] [   ]: Discovered service <CBService: 0x10010d950>
2015-09-13 20:52:57.381 xctest[55099:2968989] [TRACE  ] [   ]: Discovered characteristics for service <CBService: 0x10010d950>
2015-09-13 20:52:57.381 xctest[55099:2968989] [TRACE  ] [   ]: Discovered characteristic <CBCharacteristic: 0x100304d10>
2015-09-13 20:52:57.382 xctest[55099:2968989] [DEBUG  ] [   ]: Tx characteristic supports WriteWithResponse: NO
2015-09-13 20:52:57.382 xctest[55099:2968989] [TRACE  ] [   ]: Subscribing to Rx value
2015-09-13 20:52:57.392 xctest[55099:2968940] [INFO   ] [   ]: Connected successfully
2015-09-13 20:52:57.392 xctest[55099:2968940] [TRACE  ] [   ]: DTR/RTS supported by Serial, resetting
2015-09-13 20:52:57.392 xctest[55099:2968940] [TRACE  ] [   ]: Waiting until subscribed to Rx value ...
2015-09-13 20:52:58.387 xctest[55099:2968989] [DEBUG  ] [IN ]: Updated notifications state for RX characteristic: isNotifying=YES
2015-09-13 20:52:58.408 xctest[55099:2968940] [DEBUG  ] [OUT]: Sending 8 bytes
2015-09-13 20:52:58.408 xctest[55099:2968940] [TRACE  ] [OUT]: Send: A [0x41] T [0x54] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] 1 [0x31] 
2015-09-13 20:52:58.408 xctest[55099:2968940] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 8
2015-09-13 20:52:58.463 xctest[55099:2968940] [DEBUG  ] [OUT]: Sending 8 bytes
2015-09-13 20:52:58.463 xctest[55099:2968940] [TRACE  ] [OUT]: Send: A [0x41] T [0x54] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] 0 [0x30] 
2015-09-13 20:52:58.463 xctest[55099:2968940] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 8
2015-09-13 20:52:58.518 xctest[55099:2968940] [DEBUG  ] [   ]: Draining for 300 ms ...
2015-09-13 20:52:58.518 xctest[55099:2968940] [TRACE  ] [IN ]: Start reading
2015-09-13 20:52:58.784 xctest[55099:2968989] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 1 [0x31] 
2015-09-13 20:52:58.785 xctest[55099:2968989] [WARNING] [IN ]: Removing 'OK+PIO2:1' (9 bytes) from incoming buffer (9 bytes)
2015-09-13 20:52:58.785 xctest[55099:2968989] [WARNING] [IN ]: Got 0 bytes in incoming buffer
2015-09-13 20:52:58.786 xctest[55099:2968989] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 0 [0x30] 
2015-09-13 20:52:58.786 xctest[55099:2968989] [WARNING] [IN ]: Removing 'OK+PIO2:0' (9 bytes) from incoming buffer (9 bytes)
2015-09-13 20:52:58.787 xctest[55099:2968989] [WARNING] [IN ]: Got 0 bytes in incoming buffer
2015-09-13 20:52:58.820 xctest[55099:2968940] [TRACE  ] [IN ]: Finish reading
2015-09-13 20:52:58.820 xctest[55099:2968940] [TRACE  ] [IN ]: Ble clear buffer
2015-09-13 20:52:58.821 xctest[55099:2968940] [DEBUG  ] [IN ]: Drained 0 bytes
2015-09-13 20:52:58.821 xctest[55099:2968940] [DEBUG  ] [OUT]: Sending 2 bytes
2015-09-13 20:52:58.821 xctest[55099:2968940] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-09-13 20:52:58.821 xctest[55099:2968940] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 2
2015-09-13 20:52:58.822 xctest[55099:2968940] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-13 20:52:58.822 xctest[55099:2968940] [TRACE  ] [IN ]: Start reading
2015-09-13 20:52:59.193 xctest[55099:2968978] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-13 20:52:59.193 xctest[55099:2968978] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-13 20:52:59.193 xctest[55099:2968978] [TRACE  ] [IN ]: Rx value received 2 bytes: . [0x14] . [0x10] 
2015-09-13 20:52:59.194 xctest[55099:2968978] [WARNING] [IN ]: Got 2 bytes in incoming buffer
2015-09-13 20:52:59.194 xctest[55099:2968940] [TRACE  ] [IN ]: Finish reading
2015-09-13 20:52:59.195 xctest[55099:2968940] [TRACE  ] [IN ]: Receive: . [0x14] 
2015-09-13 20:52:59.195 xctest[55099:2968940] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-13 20:52:59.195 xctest[55099:2968940] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-13 20:52:59.196 xctest[55099:2968940] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-13 20:52:59.196 xctest[55099:2968940] [TRACE  ] [IN ]: Having current receive buffer: . [0x10] 
2015-09-13 20:52:59.196 xctest[55099:2968940] [TRACE  ] [IN ]: Start reading
2015-09-13 20:52:59.196 xctest[55099:2968940] [TRACE  ] [IN ]: Finish reading
2015-09-13 20:52:59.197 xctest[55099:2968940] [TRACE  ] [IN ]: Receive: . [0x10] 
2015-09-13 20:52:59.197 xctest[55099:2968940] [DEBUG  ] [IN ]: Read 1 bytes, actually received 1 bytes
2015-09-13 20:52:59.197 xctest[55099:2968940] [TRACE  ] [IN ]: Ble clear buffer
2015-09-13 20:52:59.198 xctest[55099:2968940] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-13 20:52:59.198 xctest[55099:2968940] [TRACE  ] [OUT]: Send: A [0x41] . [0x81]   [0x20] 
2015-09-13 20:52:59.198 xctest[55099:2968940] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-13 20:52:59.199 xctest[55099:2968940] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-13 20:52:59.199 xctest[55099:2968940] [TRACE  ] [IN ]: Start reading
2015-09-13 20:52:59.268 xctest[55099:2968978] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-13 20:52:59.268 xctest[55099:2968978] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-13 20:53:02.955 xctest[55099:2968940] [ERROR  ] [OUT]: BLE read timeout: 3.000965 (timeout = 3.000000)
2015-09-13 20:53:02.955 xctest[55099:2968940] [TRACE  ] [IN ]: Finish reading
2015-09-13 20:53:02.955 xctest[55099:2968940] [TRACE  ] [IN ]: Ble clear buffer
2015-09-13 20:53:02.955 xctest[55099:2968940] [ERROR  ] [IN ]: STK500:receive: programmer is not responding
2015-09-13 20:53:02.956 xctest[55099:2968940] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-13 20:53:02.956 xctest[55099:2968940] [TRACE  ] [OUT]: Send: A [0x41] . [0x82]   [0x20] 
2015-09-13 20:53:02.956 xctest[55099:2968940] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-13 20:53:02.956 xctest[55099:2968940] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-13 20:53:02.957 xctest[55099:2968940] [TRACE  ] [IN ]: Start reading
2015-09-13 20:53:03.018 xctest[55099:2968978] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-13 20:53:03.018 xctest[55099:2968978] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-13 20:53:03.280 xctest[55099:2968989] [TRACE  ] [IN ]: Rx value received 5 bytes: h [0x68] e [0x65] l [0x6C] l [0x6C] o [0x6F] 
2015-09-13 20:53:03.280 xctest[55099:2968989] [WARNING] [IN ]: Got 5 bytes in incoming buffer
2015-09-13 20:53:03.281 xctest[55099:2968940] [TRACE  ] [IN ]: Finish reading

i can see blinking so the character arrives so the characters arrive correctly to the board. also i've tested wiring (sketch returns exactly the same as it was sent and it sends 'hello' after start). So i'm pretty sure: 1. characters arrive correctly to the bootloader 2. wiring is correct (as i can see back what i've sent - i'm using LightBlue mac app to open HM-10 as BLE device, subscribe to the characteristics and send characters and i can see it's changing to what i've sent). 3. bootloader waits for 4 seconds (i can see it in Arduino IDE terminal).

Update 4 :

my understanding now is that optiboot sets wrong baud rate for 115200 passed in bootloader mode as it replies with 0x11 and transmits characters correctly in sketch mode:

2015-09-17 09:39:25.628 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 1 [0x31] 
2015-09-17 09:39:25.628 xctest[60179:4253160] [WARNING] [IN ]: Got 9 bytes in incoming buffer
2015-09-17 09:39:25.629 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 0 [0x30] 
2015-09-17 09:39:25.629 xctest[60179:4253160] [WARNING] [IN ]: Got 9 bytes in incoming buffer
2015-09-17 09:39:25.630 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-17 09:39:25.630 xctest[60179:4253160] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-17 09:39:27.351 xctest[60179:4253117] [TRACE  ] [IN ]: Finish reading
2015-09-17 09:39:27.351 xctest[60179:4253117] [TRACE  ] [IN ]: Ble clear buffer
2015-09-17 09:39:27.351 xctest[60179:4253117] [DEBUG  ] [IN ]: Drained 18 bytes
2015-09-17 09:39:27.352 xctest[60179:4253117] [DEBUG  ] [   ]: Draining incoming buffer (0 bytes)
2015-09-17 09:39:27.352 xctest[60179:4253117] [DEBUG  ] [OUT]: Sending 2 bytes
2015-09-17 09:39:27.352 xctest[60179:4253117] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-09-17 09:39:27.353 xctest[60179:4253117] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 2
2015-09-17 09:39:27.353 xctest[60179:4253117] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-17 09:39:27.353 xctest[60179:4253117] [TRACE  ] [IN ]: Start reading
2015-09-17 09:39:27.424 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-17 09:39:27.424 xctest[60179:4253160] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-17 09:39:27.424 xctest[60179:4253149] [TRACE  ] [IN ]: Rx value received 2 bytes: . [0x11] . [0xFC] 
2015-09-17 09:39:27.425 xctest[60179:4253149] [WARNING] [IN ]: Got 2 bytes in incoming buffer
2015-09-17 09:39:27.425 xctest[60179:4253117] [TRACE  ] [IN ]: Finish reading
2015-09-17 09:39:27.425 xctest[60179:4253117] [TRACE  ] [IN ]: Receive: . [0x11] 
2015-09-17 09:39:27.425 xctest[60179:4253117] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-17 09:39:27.426 xctest[60179:4253117] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-17 09:39:27.426 xctest[60179:4253117] [ERROR  ] [   ]: STK500:synchronize: attempt 1 of 3: no sync: received [0x11]
2015-09-17 09:39:27.426 xctest[60179:4253117] [DEBUG  ] [   ]: Draining incoming buffer (1 bytes)
2015-09-17 09:39:27.426 xctest[60179:4253117] [DEBUG  ] [OUT]: Sending 2 bytes
2015-09-17 09:39:27.427 xctest[60179:4253117] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-09-17 09:39:27.427 xctest[60179:4253117] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 2
2015-09-17 09:39:27.427 xctest[60179:4253117] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-17 09:39:27.427 xctest[60179:4253117] [TRACE  ] [IN ]: Start reading
2015-09-17 09:39:27.499 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-17 09:39:27.499 xctest[60179:4253160] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-17 09:39:27.500 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 2 bytes: . [0x14] . [0x10] 
2015-09-17 09:39:27.500 xctest[60179:4253160] [WARNING] [IN ]: Got 2 bytes in incoming buffer
2015-09-17 09:39:27.500 xctest[60179:4253117] [TRACE  ] [IN ]: Finish reading
2015-09-17 09:39:27.501 xctest[60179:4253117] [TRACE  ] [IN ]: Receive: . [0x14] 
2015-09-17 09:39:27.501 xctest[60179:4253117] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-17 09:39:27.501 xctest[60179:4253117] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-17 09:39:27.501 xctest[60179:4253117] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-17 09:39:27.501 xctest[60179:4253117] [TRACE  ] [IN ]: Having current receive buffer: . [0x10] 
2015-09-17 09:39:27.502 xctest[60179:4253117] [TRACE  ] [IN ]: Start reading
2015-09-17 09:39:27.502 xctest[60179:4253117] [TRACE  ] [IN ]: Finish reading
2015-09-17 09:39:27.502 xctest[60179:4253117] [TRACE  ] [IN ]: Receive: . [0x10] 
2015-09-17 09:39:27.508 xctest[60179:4253117] [DEBUG  ] [IN ]: Read 1 bytes, actually received 1 bytes
2015-09-17 09:39:27.509 xctest[60179:4253117] [TRACE  ] [IN ]: Ble clear buffer
2015-09-17 09:39:27.509 xctest[60179:4253117] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-17 09:39:27.509 xctest[60179:4253117] [TRACE  ] [OUT]: Send: A [0x41] . [0x81]   [0x20] 
2015-09-17 09:39:27.509 xctest[60179:4253117] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-17 09:39:27.510 xctest[60179:4253117] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-17 09:39:27.510 xctest[60179:4253117] [TRACE  ] [IN ]: Start reading
2015-09-17 09:39:27.574 xctest[60179:4253149] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-17 09:39:27.574 xctest[60179:4253149] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-17 09:39:31.325 xctest[60179:4253117] [ERROR  ] [OUT]: BLE read timeout: 3.000965 (timeout = 3.000000)
2015-09-17 09:39:31.326 xctest[60179:4253117] [TRACE  ] [IN ]: Finish reading
2015-09-17 09:39:31.326 xctest[60179:4253117] [TRACE  ] [IN ]: Ble clear buffer
2015-09-17 09:39:31.326 xctest[60179:4253117] [ERROR  ] [IN ]: STK500:receive: programmer is not responding
2015-09-17 09:39:31.327 xctest[60179:4253117] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-17 09:39:31.327 xctest[60179:4253117] [TRACE  ] [OUT]: Send: A [0x41] . [0x82]   [0x20] 
2015-09-17 09:39:31.327 xctest[60179:4253117] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-17 09:39:31.328 xctest[60179:4253117] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-17 09:39:31.328 xctest[60179:4253117] [TRACE  ] [IN ]: Start reading
2015-09-17 09:39:31.399 xctest[60179:4253160] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-17 09:39:31.400 xctest[60179:4253160] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-17 09:39:35.173 xctest[60179:4253117] [ERROR  ] [OUT]: BLE read timeout: 3.000965 (timeout = 3.000000)
2015-09-17 09:39:35.173 xctest[60179:4253117] [TRACE  ] [IN ]: Finish reading
2015-09-17 09:39:35.174 xctest[60179:4253117] [TRACE  ] [IN ]: Ble clear buffer
2015-09-17 09:39:35.174 xctest[60179:4253117] [ERROR  ] [IN ]: STK500:receive: programmer is not responding
2015-09-17 09:39:35.174 xctest[60179:4253117] [DEBUG  ] [   ]: STK500:initialize: n_extparms = 3
2015-09-17 09:39:35.175 xctest[60179:4253117] [DEBUG  ] [OUT]: Sending 22 bytes
2015-09-17 09:39:35.175 xctest[60179:4253117] [TRACE  ] [OUT]: Send: B [0x42] . [0x86] . [0x00] . [0x01] . [0x00] . [0x01] . [0x01] . [0x01] . [0x03] . [0xFF] . [0xFF] . [0xFF] . [0xFF] . [0x00] . [0x80] . [0x04] . [0x00] . [0x00] . [0x00] . [0x80] . [0x00]   [0x20] 
2015-09-17 09:39:35.175 xctest[60179:4253117] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 20
2015-09-17 09:39:35.176 xctest[60179:4253117] [TRACE  ] [OUT]: BLE sending bytes range from 20 length 2
2015-09-17 09:39:35.177 xctest[60179:4253117] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-17 09:39:35.177 xctest[60179:4253117] [TRACE  ] [IN ]: Start reading
2015-09-17 09:39:35.224 xctest[60179:4253149] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-17 09:39:35.224 xctest[60179:4253149] [TRACE  ] [IN ]: Ignoring single 0x00 char 

Should it work if i wire pins 0 and 1 at Uno to RX/TX (it does work for Mega2560)? Here is soft uart code from optiboot:

#ifndef SOFT_UART
#ifdef __AVR_ATmega8__
  UCSRA = _BV(U2X); //Double speed mode USART
  UCSRB = _BV(RXEN) | _BV(TXEN);  // enable Rx & Tx
  UCSRC = _BV(URSEL) | _BV(UCSZ1) | _BV(UCSZ0);  // config USART; 8N1
  UBRRL = (uint8_t)( (F_CPU + BAUD_RATE * 4L) / (BAUD_RATE * 8L) - 1 );
#else
  UCSR0A = _BV(U2X0); //Double speed mode USART0
  UCSR0B = _BV(RXEN0) | _BV(TXEN0);
  UCSR0C = _BV(UCSZ00) | _BV(UCSZ01);
  UBRR0L = (uint8_t)( (F_CPU + BAUD_RATE * 4L) / (BAUD_RATE * 8L) - 1 );
#endif
#endif

#ifdef SOFT_UART
  /* Set TX pin as output */
  UART_DDR |= _BV(UART_TX_BIT);
#endif

Should RX be set as input separately too (like Tx as output)? Why it tries to set 'Double speed'?

2 Answers 2

1

The reset procedure for the Arduino Uno works this way:

  1. If supported, toggle USB DTR/RTS or if not, open the Serial port at 1200 baud & close it
  2. The Atmega8u2 or Atmega16u2 (which is acting as the USB-UART bridge) detects one of these two events, and pulls PD7 (which is capacitively coupled to the pulled-up reset pin on the main Atmega328 IC) low, causing a low pulse on the reset pin, putting the Uno into bootloader mode.

Although microcontrollers do generally have a register which records the reset event reason (for example brownout detect, watchdog timer overflow, power-on reset or external reset) to allow for differentiation in startup routines, this isn't at play here because the Atmega328 can't know whether it was the Atmega8/16u2 which pulled the line low, or if you did it, or if it was a very focused beam of ionising radiation from outer space.

With this in mind, there are two possible reasons for the problem you are having:

  1. The reset isn't actually happening. You can write your own code that has a particular startup routine to detect this, along with watching the reset pin with a scope to observe the pulse.

  2. The onboard bootloader timeout is kicking in before you are passing data to it. From looking at the optiboot code (and the makefiles in the Arduino Github repo) it seems that you have a timeout of 1 second from reset to pass your first valid character to the bootloader. This is longer for other boards (8 seconds for the Arduino Leonardo, for example). Are you certain that you are getting data there that fast?

If the issue is a timing one (and you can't improve your timing), you could always consider flashing your own compiled version of Optiboot based on the Arduino makefile options for the atmega328 target but with an additional -DTIMEOUT_MS=XXXX in the CFLAGS definition, where XXXX is the timeout in ms chosen from the supported list of 500, 1000, 2000, 4000, 8000.

18
  • thank for the explanation. i'm not sure about 1200 baud rate magic. in arduino ide source code it just sets DTR/RTS to 1 and 0 in 50 ms and that's enough to reset the board. it's almost the same way i'm making Uno to reset (but i use HM-10 PIO as DTR with the same reset schematics). I'm 100% sure it actually reset and i can see 'hello' which runs in setup() in uploaded arduino sketch. what about timeout this can be the reason (i've updated the question with log). But this is the way i upload successfully to Mega2560. So you think arduino does not remember/know how reset was initiated?
    – 4ntoine
    Sep 8, 2015 at 11:35
  • i've updated the task with uploading over USB log. You can see after Send: A [0x41] . [0x81] [0x20] interaction continues in contrast to uploading over BLE
    – 4ntoine
    Sep 8, 2015 at 11:50
  • 1
    Hmmm, interesting. The 1200 baud rate definitely works (just checked) but there seem to be two separate mechanisms it can use. In any case it is of no use to you here. The Mega2560 uses a different bootloader, but it also seems to have a 1 second timeout. The Atmega328 does remember how it was reset, but only between options such as brownout detect, watchdog timeout, new power on and external reset - it can't tell the difference between different resets using the external pin.
    – stefandz
    Sep 8, 2015 at 11:54
  • what command should be invoked within 1 second to let bootloader know it should not start the app and uploading is going to happen?
    – 4ntoine
    Sep 8, 2015 at 17:39
  • 1
    The command to be sent is any command valid within the optiboot bootloader protocol. And if you take a look at the Atmega328 datasheet you'll see that Figure 10-1 shows the reset logic and the source of the 4 reset source bits in the MCU status register. That is to say that the Atmega328 sets that bit because it detected a reset event at the RESET pin.
    – stefandz
    Sep 8, 2015 at 22:15
1

Eventually i've found the reason. And it was bug in HM-10 firmware. In mode 0 it does not accept control commands and in modes 1 and 2 it accepts AT commands to control PIO and commands are look like 'AT+...', f.e. 'PIO set value 1 to pin 1' command is 'AT+PIO11' and change mode to 0 look like 'AT+MODE0'. I need mode 1 to set PIO to 1 and 0 to reset arduino board. The problem is that some of upload commands look like 'A [0x41] . [0x81] [0x20]' (starts from 'A' too) and it makes HM-10 think it's control command which also starts from 'A'. If i add changing mode to 0 after pin control commands (in order to make HM-10 stop accepting control commands) it starts uploading:

2015-09-18 10:27:32.144 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 1 [0x31] 
2015-09-18 10:27:32.145 xctest[94852:4603627] [WARNING] [IN ]: Got 9 bytes in incoming buffer
2015-09-18 10:27:32.145 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 9 bytes: O [0x4F] K [0x4B] + [0x2B] P [0x50] I [0x49] O [0x4F] 2 [0x32] : [0x3A] 0 [0x30] 
2015-09-18 10:27:32.146 xctest[94852:4603627] [WARNING] [IN ]: Got 9 bytes in incoming buffer
2015-09-18 10:27:32.146 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 8 bytes: O [0x4F] K [0x4B] + [0x2B] S [0x53] e [0x65] t [0x74] : [0x3A] 0 [0x30] 
2015-09-18 10:27:32.147 xctest[94852:4603627] [WARNING] [IN ]: Got 8 bytes in incoming buffer
2015-09-18 10:27:32.147 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-18 10:27:32.147 xctest[94852:4603627] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-18 10:27:32.207 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.208 xctest[94852:4603578] [TRACE  ] [IN ]: Ble clear buffer
2015-09-18 10:27:32.208 xctest[94852:4603578] [DEBUG  ] [IN ]: Drained 26 bytes
2015-09-18 10:27:32.208 xctest[94852:4603578] [DEBUG  ] [   ]: Draining incoming buffer (0 bytes)
2015-09-18 10:27:32.208 xctest[94852:4603578] [DEBUG  ] [OUT]: Sending 2 bytes
2015-09-18 10:27:32.208 xctest[94852:4603578] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-09-18 10:27:32.209 xctest[94852:4603578] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 2
2015-09-18 10:27:32.209 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.209 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.561 xctest[94852:4603630] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-18 10:27:32.561 xctest[94852:4603630] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-18 10:27:32.561 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 2 bytes: . [0x11] . [0xFC] 
2015-09-18 10:27:32.561 xctest[94852:4603627] [WARNING] [IN ]: Got 2 bytes in incoming buffer
2015-09-18 10:27:32.563 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.563 xctest[94852:4603578] [TRACE  ] [IN ]: Receive: . [0x11] 
2015-09-18 10:27:32.563 xctest[94852:4603578] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-18 10:27:32.563 xctest[94852:4603578] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-18 10:27:32.563 xctest[94852:4603578] [ERROR  ] [   ]: STK500:synchronize: attempt 1 of 3: no sync: received [0x11]
2015-09-18 10:27:32.564 xctest[94852:4603578] [DEBUG  ] [   ]: Draining incoming buffer (1 bytes)
2015-09-18 10:27:32.564 xctest[94852:4603578] [DEBUG  ] [OUT]: Sending 2 bytes
2015-09-18 10:27:32.564 xctest[94852:4603578] [TRACE  ] [OUT]: Send: 0 [0x30]   [0x20] 
2015-09-18 10:27:32.564 xctest[94852:4603578] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 2
2015-09-18 10:27:32.565 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.565 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.636 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-18 10:27:32.636 xctest[94852:4603627] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-18 10:27:32.636 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 2 bytes: . [0x14] . [0x10] 
2015-09-18 10:27:32.636 xctest[94852:4603627] [WARNING] [IN ]: Got 2 bytes in incoming buffer
2015-09-18 10:27:32.638 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.638 xctest[94852:4603578] [TRACE  ] [IN ]: Receive: . [0x14] 
2015-09-18 10:27:32.638 xctest[94852:4603578] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-18 10:27:32.638 xctest[94852:4603578] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-18 10:27:32.639 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.639 xctest[94852:4603578] [TRACE  ] [IN ]: Having current receive buffer: . [0x10] 
2015-09-18 10:27:32.639 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.639 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.640 xctest[94852:4603578] [TRACE  ] [IN ]: Receive: . [0x10] 
2015-09-18 10:27:32.644 xctest[94852:4603578] [DEBUG  ] [IN ]: Read 1 bytes, actually received 1 bytes
2015-09-18 10:27:32.644 xctest[94852:4603578] [TRACE  ] [IN ]: Ble clear buffer
2015-09-18 10:27:32.645 xctest[94852:4603578] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-18 10:27:32.645 xctest[94852:4603578] [TRACE  ] [OUT]: Send: A [0x41] . [0x81]   [0x20] 
2015-09-18 10:27:32.645 xctest[94852:4603578] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-18 10:27:32.645 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.646 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.711 xctest[94852:4603630] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-18 10:27:32.711 xctest[94852:4603630] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-18 10:27:32.711 xctest[94852:4603630] [TRACE  ] [IN ]: Rx value received 3 bytes: . [0x14] . [0x04] . [0x10] 
2015-09-18 10:27:32.711 xctest[94852:4603630] [WARNING] [IN ]: Got 3 bytes in incoming buffer
2015-09-18 10:27:32.712 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.713 xctest[94852:4603578] [TRACE  ] [IN ]: Receive: . [0x14] 
2015-09-18 10:27:32.713 xctest[94852:4603578] [DEBUG  ] [IN ]: Read 1 bytes, actually received 3 bytes
2015-09-18 10:27:32.713 xctest[94852:4603578] [TRACE  ] [IN ]: 2 bytes in incoming buffer remaining for next receive
2015-09-18 10:27:32.713 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.713 xctest[94852:4603578] [TRACE  ] [IN ]: Having current receive buffer: . [0x04] . [0x10] 
2015-09-18 10:27:32.714 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.714 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.728 xctest[94852:4603578] [TRACE  ] [IN ]: Receive: . [0x04] 
2015-09-18 10:27:32.728 xctest[94852:4603578] [DEBUG  ] [IN ]: Read 1 bytes, actually received 2 bytes
2015-09-18 10:27:32.729 xctest[94852:4603578] [TRACE  ] [IN ]: 1 bytes in incoming buffer remaining for next receive
2015-09-18 10:27:32.729 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.729 xctest[94852:4603578] [TRACE  ] [IN ]: Having current receive buffer: . [0x10] 
2015-09-18 10:27:32.729 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.730 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.730 xctest[94852:4603578] [TRACE  ] [IN ]: Receive: . [0x10] 
2015-09-18 10:27:32.730 xctest[94852:4603578] [DEBUG  ] [IN ]: Read 1 bytes, actually received 1 bytes
2015-09-18 10:27:32.730 xctest[94852:4603578] [TRACE  ] [IN ]: Ble clear buffer
2015-09-18 10:27:32.731 xctest[94852:4603578] [DEBUG  ] [OUT]: Sending 3 bytes
2015-09-18 10:27:32.731 xctest[94852:4603578] [TRACE  ] [OUT]: Send: A [0x41] . [0x82]   [0x20] 
2015-09-18 10:27:32.731 xctest[94852:4603578] [TRACE  ] [OUT]: BLE sending bytes range from 0 length 3
2015-09-18 10:27:32.732 xctest[94852:4603578] [DEBUG  ] [IN ]: Reading 1 bytes ...
2015-09-18 10:27:32.732 xctest[94852:4603578] [TRACE  ] [IN ]: Start reading
2015-09-18 10:27:32.786 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 1 bytes: . [0x00] 
2015-09-18 10:27:32.786 xctest[94852:4603627] [TRACE  ] [IN ]: Ignoring single 0x00 char 
2015-09-18 10:27:32.787 xctest[94852:4603627] [TRACE  ] [IN ]: Rx value received 3 bytes: . [0x14] . [0x04] . [0x10] 
2015-09-18 10:27:32.787 xctest[94852:4603627] [WARNING] [IN ]: Got 3 bytes in incoming buffer
2015-09-18 10:27:32.788 xctest[94852:4603578] [TRACE  ] [IN ]: Finish reading
2015-09-18 10:27:32.788 xctest[94

I was working for Mega2560 since it uses different bootloader and upload commands do not start from 'A'. It's definitely HM-10 firmware bug as it can understand it's not control command since the second byte is not 'T'.

If i had oscilloscope i'd find the reason in 1 hour but for casual engineering i don't need it. I've reported a bug to HM-10 manufacturer but i'm not sure when they fix it. HM-10 firmware version is v532.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.