How to reset Arduino Uno over BLE just like over USB?

Question

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'?

Answer 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.

• 4ntoine: 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: 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
• stefandz: 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.
• 4ntoine: what command should be invoked within 1 second to let bootloader know it should not start the app and uploading is going to happen?
• stefandz: 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.

Answer 2

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.