nerves uart terminating with port_timed_out when used from iex

[pallix]

When reading a port in a read loop with nerves uart and testing the program from iex, nerves uart crashes when typing twice <tab>:

λ iex -S mix
Erlang/OTP 20 [erts-9.1] [source] [64-bit] [smp:2:2] [ds:2:2:10] [async-threads:10] [kernel-poll:false]

Interactive Elixir (1.6.0) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> NervesUartBug.bug()
%Task{
  owner: #PID<0.152.0>,
  pid: #PID<0.155.0>,
  ref: #Reference<0.3372432089.4237557761.212204>
}

### HERE type <tab> <tab> quickly

iex(2)> 
15:37:03.575 [error] GenServer #PID<0.154.0> terminating
** (stop) :port_timed_out
    (nerves_uart) lib/nerves_uart.ex:501: Nerves.UART.call_port/4
    (nerves_uart) lib/nerves_uart.ex:356: Nerves.UART.handle_call/3
    (stdlib) gen_server.erl:636: :gen_server.try_handle_call/4
    (stdlib) gen_server.erl:665: :gen_server.handle_msg/6
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.155.0>): {:read, 50}
State: %Nerves.UART.State{controlling_process: #PID<0.152.0>, framing: Nerves.UART.Framing.None, framing_state: nil, is_active: false, name: "tnt0", port: #Port<0.4984>, queued_messages: [], rx_framing_timeout: 0, rx_framing_tref: nil}
Client #PID<0.155.0> is alive
    (stdlib) gen.erl:169: :gen.do_call/4
    (elixir) lib/gen_server.ex:828: GenServer.call/3
    (nerves_uart_bug) lib/nerves_uart_bug.ex:22: NervesUartBug.read_serial_line/1
    (elixir) lib/task/supervised.ex:88: Task.Supervised.do_apply/2
    (elixir) lib/task/supervised.ex:38: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3

I have a demo code showing the problem: https://github.com/pallix/nerves_uart_bug

[fhunleth]

Thanks for the detailed bug report.

Do you know whether this is related to the 50 millisecond timeout? Also, could you turn on debug prints in the C code to see if there's a clue there?

[pallix]

You are welcome.

I don't get much in the log. The content after the crash:

λ cat nerves_uart-19920.log 
Starting...

[pallix]

I tried, 30, 60, and 600 for the timeout value and still get the crash.

[fhunleth]

I'm trying to reproduce, but can't. I'm typing tab, tab as quickly as I can after running NervesUartBug.bug:

$ iex -S mix
Erlang/OTP 20 [erts-9.1] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:10] [hipe] [kernel-poll:false]

Interactive Elixir (1.6.0) - press Ctrl+C to exit (type h() ENTER for help)
Loaded ~/.iex.exs
iex(1)> NervesUartBug.bug()
%Task{
  owner: #PID<0.154.0>,
  pid: #PID<0.157.0>,
  ref: #Reference<0.4196568369.3516137479.205605>
}
iex(2)> 
!/1                           !=/2                          
!==/2                         %/2                         
...

Here's some info about my system:

$ cat /etc/os-release 
NAME="Ubuntu"
VERSION="16.04.3 LTS (Xenial Xerus)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 16.04.3 LTS"
VERSION_ID="16.04"
HOME_URL="http://www.ubuntu.com/"
SUPPORT_URL="http://help.ubuntu.com/"
BUG_REPORT_URL="http://bugs.launchpad.net/ubuntu/"
VERSION_CODENAME=xenial
UBUNTU_CODENAME=xenial
$ head /proc/cpuinfo 
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 58
model name	: Intel(R) Core(TM) i7-3740QM CPU @ 2.70GHz
stepping	: 9
microcode	: 0x1c
cpu MHz		: 1200.023
cache size	: 6144 KB
physical id	: 0

Also, I'm running Erlang 20.2.

Could you let me know what you're running? Also do you have any more clues? This is really weird.

[pallix]

Are you using https://github.com/freemed/tty0tty.git ?

$ cat /etc/os-release 
PRETTY_NAME="Debian GNU/Linux 9 (stretch)"
NAME="Debian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
$ head /proc/cpuinfo 
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 142
model name	: Intel(R) Core(TM) i5-7200U CPU @ 2.50GHz
stepping	: 9
microcode	: 0x62
cpu MHz		: 2712.022
cache size	: 3072 KB
physical id	: 0

I am using Erlang 20.1.1.

It is not really necessary to type quickly tabs.