samples: net: echo_client: sample runs failed with prj_qemu_x86_tls.conf configuration file

[xianrenqiu]

Summary

In zephyr/samples/net/echo_client sample, when using the prj_qemu_x86.conf configuration file, the sample runs successfully, but using the prj_qemu_x86_tls.conf configuration file, the sample runs failed. Error code is EBUSY(-16, TLS handshake not yet done ?).

Setup

1. branch info
zephyr branch: zephyr-v1.11.0
net-tools branch: master (commit 17e31b)

2. terminal #1 linux <--> qemu
$ cd net-tools
$ ./loop-socat.sh &
$ sudo ./loop-slip-tap.sh
# tap0 info
tap0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.0.2.2  netmask 255.255.255.0  broadcast 0.0.0.0
        inet6 fe80::a870:87ff:fec6:6114  prefixlen 64  scopeid 0x20<link>
        inet6 2001:db8::2  prefixlen 64  scopeid 0x0<global>
        ether aa:70:87:c6:61:14  txqueuelen 1000
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

Failed (prj_qemu_x86_tls.conf)

# terminal #2 run stunnel
$ cd net-tools
$ ./stunnel.sh
# output info
2018.05.11 09:15:39 LOG5[ui]: stunnel 5.44 on x86_64-pc-linux-gnu platform
2018.05.11 09:15:39 LOG5[ui]: stunnel 5.44 on x86_64-pc-linux-gnu platform
2018.05.11 09:15:39 LOG5[ui]: Compiled/running with OpenSSL 1.1.0g  2 Nov 2017
2018.05.11 09:15:39 LOG5[ui]: Compiled/running with OpenSSL 1.1.0g  2 Nov 2017
2018.05.11 09:15:39 LOG5[ui]: Threading:PTHREAD Sockets:POLL,IPv6,SYSTEMD TLS:ENGINE,FIPS,OCSP,PSK,SNI Auth:LIBWRAP
2018.05.11 09:15:39 LOG5[ui]: Threading:PTHREAD Sockets:POLL,IPv6,SYSTEMD TLS:ENGINE,FIPS,OCSP,PSK,SNI Auth:LIBWRAP
2018.05.11 09:15:39 LOG5[ui]: Reading configuration from file /root/share/repo/net-tools/stunnel.conf
2018.05.11 09:15:39 LOG5[ui]: Reading configuration from file /root/share/repo/net-tools/stunnel.conf
2018.05.11 09:15:39 LOG5[ui]: UTF-8 byte order mark not detected
2018.05.11 09:15:39 LOG5[ui]: UTF-8 byte order mark not detected
2018.05.11 09:15:39 LOG5[ui]: FIPS mode disabled
2018.05.11 09:15:39 LOG5[ui]: FIPS mode disabled
2018.05.11 09:15:39 LOG4[ui]: Insecure file permissions on echo-apps-key.pem
2018.05.11 09:15:39 LOG4[ui]: Insecure file permissions on echo-apps-key.pem
2018.05.11 09:15:39 LOG4[ui]: Insecure file permissions on echo-apps-key.pem
2018.05.11 09:15:39 LOG4[ui]: Insecure file permissions on echo-apps-key.pem
2018.05.11 09:15:39 LOG5[ui]: Configuration successful
2018.05.11 09:15:39 LOG5[ui]: Configuration successful

# terminal #3 echo_server
$ ./echo-server -p 4244 -i tap0
# output info
IPv4: binding to 192.0.2.2
IPv6: binding to 2001:db8::2
Sockets: UPD IPv4 3 IPv6 4, mcast IPv4 5 IPv6 6, TCP IPv4 7 IPv6 8
Socket 3 binding to 192.0.2.2
Socket 4 binding to 2001:db8::2
Socket 5 binding to 239.192.0.2
Socket 6 binding to ff84::2
Socket 7 binding to 192.0.2.2
Socket 8 binding to 2001:db8::2

# terminal #4 echo_client
$ cd <zephyr>/samples/net/echo_client
$ mkdir build && cd build
$ cmake -DBOARD=qemu_x86 -DCONF_FILE=prj_qemu_x86_tls.conf ..
$ make run
# output info
qemu-system-i386: warning: Unknown firmware file in legacy mode: genroms/multiboot.bin

***** BOOTING ZEPHYR OS v1.11.0 - BUILD: May 11 2018 01:16:18 *****
Zephyr Shell, Zephyr version: 1.11.0
Type 'help' for a list of available commands
shell> [echo-client] [INF] init_app: Run echo client
[echo-client] [ERR] send_tcp_data: Cannot send IPv4 data to peer (-16)
[echo-client] [DBG] tcp_received: (0x00401408): IPv6: Sent 536 bytes, received 536 bytes
[echo-client] [DBG] compare_tcp_data: (0x00401408): Compared 536 bytes, all ok

# after runs echo_client,  terminal #2 output: 
2018.05.11 09:16:29 LOG5[0]: Service [echo-server-ipv6] accepted connection from 2001:db8::1:47420
2018.05.11 09:16:29 LOG5[0]: Service [echo-server-ipv6] accepted connection from 2001:db8::1:47420
2018.05.11 09:16:29 LOG5[0]: s_connect: connected 2001:db8::2:4244
2018.05.11 09:16:29 LOG5[0]: s_connect: connected 2001:db8::2:4244
2018.05.11 09:16:29 LOG5[0]: Service [echo-server-ipv6] connected remote server from 2001:db8::2:60492
2018.05.11 09:16:29 LOG5[0]: Service [echo-server-ipv6] connected remote server from 2001:db8::2:60492
2018.05.11 09:16:29 LOG5[1]: Service [echo-server-ipv4] accepted connection from 192.0.2.1:60583
2018.05.11 09:16:29 LOG5[1]: Service [echo-server-ipv4] accepted connection from 192.0.2.1:60583
2018.05.11 09:16:29 LOG5[1]: s_connect: connected 192.0.2.2:4244
2018.05.11 09:16:29 LOG5[1]: s_connect: connected 192.0.2.2:4244
2018.05.11 09:16:29 LOG5[1]: Service [echo-server-ipv4] connected remote server from 192.0.2.2:38478
2018.05.11 09:16:29 LOG5[1]: Service [echo-server-ipv4] connected remote server from 192.0.2.2:38478

[pfalcon]

If you run echo_client with TLS support, you should also run echo_server with TLS support. Is that what you did?

[xianrenqiu]

@pfalcon Sorry, I forgot to write some process in front of it, and have been updated on them. echo_server with TLS support refer to net-tools ，Is there a problem in the process？

[xianrenqiu]

@pfalcon I have failed many times in the zephyr-v1.11.0 branch, and the latest submission(commit 03f9f6) can run successfully, but If it runs for a long time , there will be an CPU Page Fault error，The following is the log：

qemu-system-i386: warning: Unknown firmware file in legacy mode: genroms/multiboot.bin

***** Booting Zephyr OS v1.11.0-1168-g03f9f6649 *****
Zephyr Shell, Zephyr version: 1.11.99
Type 'help' for a list of available commands
shell> [echo-client] [INF] init_app: Run echo client
[echo-client] [DBG] tcp_received: (0x00401408): IPv6: Sent 227 bytes, received 227 bytes
[echo-client] [DBG] compare_tcp_data: (0x00401408): Compared 227 bytes, all ok
[echo-client] [DBG] tcp_received: (0x00400d08): IPv4: Sent 236 bytes, received 236 bytes
[echo-client] [DBG] compare_tcp_data: (0x00400d08): Compared 236 bytes, all ok
... ... ... 
[echo-client] [DBG] tcp_received: (0x00400d08): IPv4: Sent 536 bytes, received 536 bytes
[echo-client] [DBG] compare_tcp_data: (0x00400d08): Compared 536 bytes, all ok
***** CPU Page Fault (error code 0x00000000)
Supervisor thread read address 0x00000068
PDE: 0x025 Present, Read-only, User, Execute Enabled
PTE: 0x00 Non-present, Read-only, Supervisor, Execute Enabled
Current thread ID = 0x0040d270
eax: 0x00000000, ebx: 0x00414a70, ecx: 0x00413a80, edx: 0x0040d880
esi: 0x00000000, edi: 0x00000001, ebp: 0x00422f84, esp: 0x00422f54
eflags: 0x00000206 cs: 0x0008
call trace:
eip: 0x00020b59
     0x0001ab59 (0x6)
     0x00016af4 (0x414a70)
     0x00016b44 (0x422fd0)
     0x000268ed (0x414a74)
     0x00026120 (0x40d260)
Fatal fault in thread 0x0040d270! Aborting.

[jukkar]

I do not see any handshake failures but sometimes I have seen similar thread crash. I will investigate the crash further.

[linkmeyer]

@jukkar , what's the status on this?

[rveerama1]

I am working on this. I didn't find a fix yet.