stm32: serial: Data is not read properly at a certain baud rate

[KwonTae-young]

Describe the bug
UART data is not read properly at a certain baud rate.

To Reproduce
Board: stm32f4_disco
Barcode module: EM1399

I was conducting a test with EM1399 to read the barcode.
EM1399 is connected to UART1.

west init zephyrproject -m https://github.com/KwonTae-young/zephyr/ --mr code
cd zephyrproject/zephyr
source zephyr-env.sh
mkdir samples/barcode/build
cd samples/barcode/build/
cmake -DBOARD=stm32f4_disco ..
make -j8 flash

Expected behavior
I expected the scanned barcode information to be output.

Impact
At certain baud rate, barcode data is not read properly through UART.

Screenshots or console output
I have tested on a total of two boards.(stm32f4_disco, nrf52840_pca10056)
stm32f4_disco does not read the data properly.
nrf52840_pca10056 reads the data correctly.

1. UART setup of EM1399

	EM1399
baud rate	9600
stop bit	1
data bit	8
parity	none
flow control	none

2. stm32f4_disco
   

• pin connection

EM1399	stm32f4_disco
VDD(2)	3V
GND(3)	GND
TX(5)	PB7(UART1_RX)
nTrig(12)	custom button

• console

***** Booting Zephyr OS zephyr-v1.13.0-5106-g5d6c36b85f *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=9600
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 31 (1 bytes)
uart_isr: 36 (1 bytes)
uart_isr: 0a (1 bytes)

3. nrf52840_pca10056
   

• pin connection

EM1399	nrf52840_pca10056
VDD(2)	3V
GND(3)	GND
TX(5)	P0.27(UART1_RX)
nTrig(12)	custom button

• console

***** Booting Zephyr OS zephyr-v1.13.0-5105-g7352d2b0c1 *****
Sample app running on: nrf52840_pca10056
uart_init() done
uart_config.baudrate=9600
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 31 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 36 (1 bytes)
uart_isr: 0d (1 bytes)

Environment (please complete the following information):

• OS: Linux(Ubuntu 18.04)
• Toolchain: Zephyr SDK 0.9.5
• Commit SHA or Version used: 7352d2b.

Additional context
nrf52840_pca10056 is normal and only stm32f4_disco is read strangely.
So I think it is a bug.
The barcode data tested is shown below.

• Test program
  It was created by modifying samples/nfc/nfc_hello.

/*
 * Copyright (c) 2015 Intel Corporation
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include <zephyr.h>
#include <stdio.h>
#include <zephyr/types.h>
#include <string.h>
#include <uart.h>
#include <misc/byteorder.h>

#define BUF_MAXSIZE	256
#define SLEEP_TIME	500

static struct device *uart_dev;
static u8_t rx_buf[BUF_MAXSIZE];

static void msg_dump(const char *s, u8_t *data, unsigned len)
{
	unsigned i;

	printf("%s: ", s);
	for (i = 0U; i < len; i++) {
		printf("%02x ", data[i]);
	}
	printf("(%u bytes)\n", len);
}

static void uart_isr(struct device *x)
{
	int len = uart_fifo_read(uart_dev, rx_buf, BUF_MAXSIZE);

	ARG_UNUSED(x);
	msg_dump(__func__, rx_buf, len);
}

static void uart_init(void)
{
	uart_dev = device_get_binding("UART_1");

	uart_irq_callback_set(uart_dev, uart_isr);
	uart_irq_rx_enable(uart_dev);

	printf("%s() done\n", __func__);
}

void main(void)
{
	struct uart_config uart_cfg;
	int ret;

	printf("Sample app running on: %s\n", CONFIG_BOARD);

	uart_init();

	ret = uart_config_get(uart_dev, &uart_cfg);
	if (ret == 0) {
		printf("uart_config.baudrate=%d\n", uart_cfg.baudrate);
		printf("uart_config.parity=%d\n", uart_cfg.parity);
		printf("uart_config.stop_bits=%d\n", uart_cfg.stop_bits);
		printf("uart_config.data_bits=%d\n", uart_cfg.data_bits);
		printf("uart_config.flow_ctrl=%d\n", uart_cfg.flow_ctrl);
	} else {
		printf("uart_config_get() error\n");
	}

	while (1) {
		k_sleep(SLEEP_TIME);
	}
}

• baud rate
  I tested it by changing the baud rate.
  The baud rate of EM1399 and stm32f4_disco are set equal.
  The test results show that the data was read correctly only on 2400 and 4800.
  Below is the log by the baud rate I tested in stm32f4_disco.

1. baud rate: 1200

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=1200
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)
uart_isr: 00 (1 bytes)

2. baud date: 2400

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=2400
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 31 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 36 (1 bytes)
uart_isr: 0d (1 bytes)
uart_isr: 0a (1 bytes)

3. baud rate: 4800

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=4800
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 31 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 36 (1 bytes)
uart_isr: 0d (1 bytes)
uart_isr: 0a (1 bytes)

4. baud rate: 9600

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=9600
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 31 (1 bytes)
uart_isr: 36 (1 bytes)
uart_isr: 0a (1 bytes)

5. baud rate: 14400

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=14400
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 39 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 34 (1 bytes)
uart_isr: 36 (1 bytes)

6. baud rate: 19200

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=19200
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 36 (1 bytes)

7. baud rate: 38400

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=38400
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 37 (1 bytes)

8. baud rate: 57600

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=57600
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 34 (1 bytes)

9. baud rate: 115200

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=115200
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)

I'm sorry I do not have enough English.
Thank you.

[erwango]

Can you try the following, in boards/arm/stm32f4_disco/pinmux.c:

#ifdef CONFIG_UART_1
	{STM32_PIN_PB6, STM32F4_PINMUX_FUNC_PB6_USART1_TX},
-	{STM32_PIN_PB7, STM32F4_PINMUX_FUNC_PB7_USART1_RX},
+	{STM32_PIN_PB7, STM32F4_PINMUX_FUNC_PB7_USART1_RX | STM32_OSPEEDR_VERY_HIGH_SPEED},
#endif	/* CONFIG_UART_1 */

[KwonTae-young]

Hi. @erwango
I applied and tested it.
But the result was the same.

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: stm32f4_disco
uart_init() done
uart_config.baudrate=9600
uart_config.parity=0
uart_config.stop_bits=1
uart_config.data_bits=3
uart_config.flow_ctrl=0
uart_isr: 38 (1 bytes)
uart_isr: 38 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 30 (1 bytes)
uart_isr: 32 (1 bytes)
uart_isr: 37 (1 bytes)
uart_isr: 31 (1 bytes)
uart_isr: 36 (1 bytes)
uart_isr: 0a (1 bytes)

[KwonTae-young]

Additional testing

I have tested some more about stm32f4_disco and nrf52840_pca10056.
This test was done using samples/nfc/nfc-hello.
The baudrate was tested to 9600.

loopback test

• nrf52840_pca10056(loopback)
  
  Connect P0.26(Tx) and P0.27(Rx) to each other.
  Below is the log of nrf52840_pca10056.

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: arm
uart1_init() done
uart1_isr: 00 (1 bytes)
uart1_isr: 00 (1 bytes)
uart1_isr: 00 (1 bytes)
uart1_isr: 04 (1 bytes)
uart1_isr: 20 (1 bytes)
uart1_isr: 00 (1 bytes)
uart1_isr: 01 (1 bytes)
uart1_isr: 00 (1 bytes)

• stm32f4_disco(loopback)
  
  Connect PB6(Tx) and PB7(Rx) to each other.
  Below is the log of stm32f4_disco.

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: arm
uart1_init() done
uart1_isr: 00 (1 bytes)

stm32f4_disco+ nrf52840_pca10056 test

• stm32f4_disco(Rx) + nrf52840_pca10056(Tx)
  
  Connect PB7(Rx) and P0.26(Tx) to each other.
  Below is the log of stm32f4_disco.

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: arm
uart1_init() done
uart1_isr: 00 (1 bytes)
uart1_isr: 00 (1 bytes)
uart1_isr: 00 (1 bytes)
uart1_isr: 04 (1 bytes)
uart1_isr: 00 (1 bytes)
uart1_isr: 00 (1 bytes)

• stm32f4_disco(Tx) + nrf52840_pca10056(Rx)
  
  Connect PB6(Tx) and P0.27(Rx) to each other.
  Below is the log of nrf52840_pca10056.

***** Booting Zephyr OS zephyr-v1.13.0-5106-g34550e11e9 *****
Sample app running on: arm
uart1_init() done
uart1_isr: 00 (1 bytes)

I was not using Tx because it was a barcode scanner.
But from the above results, Tx also seems strange.
I added STM32_OSPEEDR_VERY_HIGH_SPEED but the result was the same.

[erwango]

@KwonTae-young , can you provide test sample you're using for loopback test so I can test on my side?

EDIT: Btw, I've run basic uart tests (uart_basic_api, console, ...) at 115200 on stm32f4_disco and haven't seen issues so far.
EDIT2: A branch that includes all board related modifications would be ideal

[KwonTae-young]

@erwango, I used samples/nfc/nfc-hello.
Pressing the reset button will output the defined reset command.
https://github.com/zephyrproject-rtos/zephyr/blob/master/samples/nfc/nfc_hello/src/main.c#L65-L69

/*
 * Peer will receive: 0x00 0x00 0x00 0x04 0x20 0x00 0x01 0x00
 *	                nci_reset size   +    nci_reset cmd
 */
uart_fifo_fill(uart1_dev, tx_buf, sizeof(u32_t) + sizeof(nci_reset));

I created a loopback branch that I tested.
loopback branch: https://github.com/KwonTae-young/zephyr/tree/loopback

west init zephyrproject_loopback -m https://github.com/KwonTae-young/zephyr/ --mr loopback
cd zephyrproject_loopback/zephyr
source zephyr-env.sh
mkdir samples/nfc/nfc_hello/build
cd samples/nfc/nfc_hello/build/
cmake -DBOARD=stm32f4_disco ..
make -j8 flash

Below is a test video.

1. stm32f4_disco
   https://youtu.be/J9NJ-enYM5I

2. nrf52840_pca10056
   https://youtu.be/9FMTosBAdEE

[erwango]

There is at least an issue in fifo_fill.
I've proposed a fix: #13952, so the loopback mode is now working.

Then, about your use case, can you have a try to disable printf in uart1_isr and see what happens?

[erwango]

@KwonTae-young , actually, it appears that uart_fifo_fill call in nfc_hello does not respect the API and behavior is undefined, cf:

zephyr/include/uart.h

Lines 697 to 698 in 687e02d

	* @brief Fill FIFO with data.
	*

[pfalcon]

uart_fifo_read, uart_fifo_fill, etc. are internal APIs, deprecated for use by application. That's because it's very hard to use them correctly by an application.

Please use higher-level API, I suggest https://github.com/zephyrproject-rtos/zephyr/blob/master/include/tty.h

[KwonTae-young]

@erwango, @pfalcon
I am on vacation until March 3rd.
I will test the following on Monday next week.

1. Apply driver/serial: stm32: fifo_fill should wait for TXE #13952 to read looback and barcode data.
2. Use 'https://github.com/zephyrproject-rtos/zephyr/blob/master/include/tty.h' to read the barcode data.

I thought samples/nfc/nfc_hello was a simple example using uart.
I currently can not find an example using https://github.com/zephyrproject-rtos/zephyr/blob/master/include/tty.h.
So I will refer to https://github.com/zephyrproject-rtos/zephyr/blob/master/subsys/console/getchar.c.

[KwonTae-young]

@erwango
I applied #13952.
And I modified samples/nfc/nfc-hello as follows.

diff --git a/samples/nfc/nfc_hello/src/main.c b/samples/nfc/nfc_hello/src/main.c
index 0f2f6fa358..926c9bb45c 100644
--- a/samples/nfc/nfc_hello/src/main.c
+++ b/samples/nfc/nfc_hello/src/main.c
@@ -19,6 +19,9 @@ static u8_t rx_buf[BUF_MAXSIZE];
 static u8_t tx_buf[BUF_MAXSIZE];
 static u8_t nci_reset[] = {0x20, 0x00, 0x01, 0x00};
 
+static u8_t save_buf[BUF_MAXSIZE];
+static int count = 0;
+
 static void msg_dump(const char *s, u8_t *data, unsigned len)
 {
        unsigned i;
@@ -35,7 +38,17 @@ static void uart1_isr(struct device *x)
        int len = uart_fifo_read(uart1_dev, rx_buf, BUF_MAXSIZE);
 
        ARG_UNUSED(x);
-       msg_dump(__func__, rx_buf, len);
+
+       // length is always 1
+       memcpy(save_buf + count++, rx_buf, 1);
+
+       // The reset command has a length of 8
+       if (count == 8) {
+               printf("[loopback test] save_buf: ");
+               for (int i = 0; i < count ; i++) {
+                       printf("%02x ", save_buf[i]);
+               }
+       }
 }
 
 static void uart1_init(void)

Then the loopback test was good.
Works well on all baudrates.

***** Booting Zephyr OS zephyr-v1.13.0-5107-geded5c2720 *****
Sample app running on: arm
uart1_init() done
[loopback test] save_buf: 00 00 00 04 20 00 01 00

I tried to run a bardcode scanner in a similar way.

Barcode data is read normally.

***** Booting Zephyr OS zephyr-v1.13.0-5107-geded5c2720 *****
Sample app running on: arm
uart1_init() done
[loopback test] save_buf: 38 38 30 39 30 39 32 38 37 34 31 34 36 0d 0a

@pfalcon
I created the following program using the tty API.

#include <zephyr.h>
#include <stdio.h>
#include <uart.h>
#include <device.h>
#include <console.h>
#include <tty.h>

static struct device *uart_dev;
static struct tty_serial console_serial;

void main(void)
{
	printf("Sample app running on: %s\n", CONFIG_BOARD);

	uart_dev = device_get_binding("UART_1");
	tty_init(&console_serial, uart_dev);
}

However, an error occurs during compilation.
What is my mistake?
I used tty.h.
I have uploaded the tested source to the tty_api_test branch.

[  1%] Built target driver_validation_h_target
[  4%] Built target syscall_list_h_target
[  5%] Built target syscall_macros_h_target
[  6%] Built target kobj_types_h_target
[  7%] Built target offsets
[  8%] Built target offsets_h
[  9%] Built target linker_script_target
[ 19%] Built target lib__libc__minimal
[ 20%] Built target app
[ 22%] Built target arch__arm__core__cortex_m__mpu
[ 29%] Built target arch__arm__core__cortex_m
[ 42%] Built target arch__arm__core
[ 44%] Built target drivers__gpio
[ 63%] Built target kernel
[ 64%] Built target drivers__pwm
[ 67%] Built target boards__arm__stm32f4_disco
[ 91%] Built target zephyr
[ 93%] Built target drivers__serial
[ 94%] Linking C executable zephyr_prebuilt.elf
Memory region         Used Size  Region Size  %age Used
           FLASH:       16764 B         1 MB      1.60%
            SRAM:        4460 B       192 KB      2.27%
        IDT_LIST:         152 B         2 KB      7.42%
../app/libapp.a(main.c.obj): In function `main':
/work/zephyrproject_loopback/zephyr/samples/tty_api/src/main.c:22: undefined reference to `tty_init'
collect2: error: ld returned 1 exit status
zephyr/CMakeFiles/zephyr_prebuilt.dir/build.make:97: recipe for target 'zephyr/zephyr_prebuilt.elf' failed
make[2]: *** [zephyr/zephyr_prebuilt.elf] Error 1
CMakeFiles/Makefile2:458: recipe for target 'zephyr/CMakeFiles/zephyr_prebuilt.dir/all' failed
make[1]: *** [zephyr/CMakeFiles/zephyr_prebuilt.dir/all] Error 2
Makefile:83: recipe for target 'all' failed
make: *** [all] Error 2