Return to Question

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

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

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.

Update 3:

i've modified bootloader (optiboot) to wait 4 seconds (instead of 1 second by default) and added blinking when character 0x41 () 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).