Issue with connect() Returning Success Without Establishing TCP Connection #78736

ofirshe · 2024-09-19T22:14:56Z

ofirshe
Sep 19, 2024

Hey,

I'm running a TCP client application on an NXP RT1060EVK, and I’ve encountered a strange issue.

The socket() function successfully returns a valid file descriptor, and the connect() function returns 0, indicating that a TCP connection was established. However, no SYN packet is actually being sent, meaning no connection is truly being established. Additionally, when I disconnect the Ethernet cable, connect() still returns 0, which is odd because no connection should be possible with the cable disconnected. The only function that fails is send(), which returns an error with errno -ENOTCONN, as expected when no connection is established.

Here are my relevant configuration settings:

CONFIG_BUILD_OUTPUT_S19=y
CONFIG_I2C=y
CONFIG_MAIN_STACK_SIZE=131072
CONFIG_ONOFF=y
CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_RING_BUFFER=y
CONFIG_EVENTFD=y
CONFIG_JSON_LIBRARY=y
CONFIG_INIT_STACKS=y
CONFIG_LOG=y
# Use immediate mode so all messages are being
# printed. Under deferred mode, there may be
# dropped messages as there are quite a number of
# messages to be printed.
CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_PICOLIBC_IO_FLOAT=y
CONFIG_EVENTFD_MAX=32
CONFIG_POSIX_MAX_FDS=64
CONFIG_SPI=y
CONFIG_FLASH=y
CONFIG_FLASH_MAP=y
CONFIG_NETWORKING=y
CONFIG_NET_UDP=y
CONFIG_NET_TCP=y
CONFIG_NET_IPV4=y
CONFIG_INIT_STACKS=y
CONFIG_NET_LOG=y
CONFIG_NET_CONFIG_SETTINGS=y
CONFIG_NET_CONFIG_NEED_IPV4=y
CONFIG_NET_CONFIG_MY_IPV4_ADDR="172.18.133.10"
CONFIG_NET_CONFIG_MY_IPV4_NETMASK="255.255.240.0"
CONFIG_NET_CONFIG_MY_IPV4_GW="172.18.143.254"
CONFIG_NET_L2_ETHERNET=y
CONFIG_NET_CONFIG_INIT_TIMEOUT=0
CONFIG_NET_CONTEXT_RCVTIMEO=y
CONFIG_NET_SOCKETS=y
CONFIG_POSIX_API=y
CONFIG_NET_TX_STACK_SIZE=4096
CONFIG_NET_RX_STACK_SIZE=4096
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
CONFIG_NET_PKT_RX_COUNT=64
CONFIG_NET_PKT_TX_COUNT=64
CONFIG_NET_BUF_RX_COUNT=64
CONFIG_NET_BUF_TX_COUNT=64
CONFIG_NET_MAX_CONN=64
CONFIG_NET_MAX_CONTEXTS=64

Here is a snippet of the code:

#define SERVER_IP 0xAC140503 /* IPv4 172.20.5.3 address */
#define SERVER_PORT 5666
...

// Create a socket
int sockfd = socket(AF_INET, SOCK_STREAM, 0);
if (sockfd < 0)
{
    LOG_ERR("socket failed; errno = %d", errno);
    return -1;
}

// Initialize the server address
struct sockaddr_in server_addr;
memset(&server_addr, 0, sizeof(server_addr));

server_addr.sin_family = AF_INET;
server_addr.sin_port = htons(SERVER_PORT);
server_addr.sin_addr.s_addr = htonl(SERVER_IP);

// Initiate the connection
int res = connect(sockfd, (struct sockaddr *)&server_addr, sizeof(server_addr));
if (res < 0 && errno != EINPROGRESS) 
{
    LOG_ERR("connect failed; errno = %d", errno);
    close(sockfd);
    return -1;
}

rc = send(sockfd, (const void *)command, command_size_bytes, 0);
if (rc < 0)
{
    LOG_ERR("Failed to send a command to remote server; errno=%d\n", errno);
}

Any insights into why does connect() behave this way, even when the Ethernet cable is disconnected ?

Thanks for help.

Answered by jukkar

Sep 24, 2024

Fix proposal at #78922

View full answer

jukkar · 2024-09-20T07:29:56Z

jukkar
Sep 20, 2024
Collaborator

You could try to enable relevant network debug logs to get more information.

CONFIG_NET_LOG=y
CONFIG_NET_TCP_LOG_LEVEL_DBG=y
CONFIG_NET_CONTEXT_LOG_LEVEL_DBG=y
CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y

1 reply

ofirshe Sep 22, 2024
Author

Hey @jukkar,

I’m attaching the debug logs below:

[00:00:02.799,980] <inf> phy_mc_ksz8081: PHY 0 is up
[00:00:02.799,980] <inf> phy_mc_ksz8081: PHY (0) Link speed 100 Mb, full duplex

[00:00:02.799,980] <dbg> net_tcp: net_tcp_init: (0x80007408): Workq started. Thread ID: 0x80007190
*** Booting Zephyr OS build v3.7.0-2542-g7dde60404492 ***
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_ref: (0x80007408): conn: 0x80039fa8, ref_count: 1
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_alloc: (0x80007408): conn: 0x80039fa8
[00:00:02.799,980] <dbg> net_sock: zsock_socket_internal: (0x80007408): socket: ctx=0x80004448, fd=3
[00:00:02.799,980] <dbg> net_tcp: net_tcp_recv: (0x80007408): context: 0x80004448, cb: 0x6000a019, user_data: 0
[00:00:02.799,980] <dbg> net_ctx: net_context_bind: (0x80007408): Context 0x80004448 binding to TCP 0.0.0.0:47144 iface 1 (0x80001208)
[00:00:02.799,980] <dbg> net_tcp: net_tcp_connect: (0x80007408): context: 0x80004448, local: 0.0.0.0, remote: 172.20.5.3
[00:00:02.799,980] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x80039fa8 src: 0.0.0.0, dst: 172.20.5.3
[00:00:02.799,980] <dbg> net_tcp: tcp_in: (0x80007408):  [LISTEN Seq=1998307048 Ack=0]
[00:00:02.799,980] <dbg> net_ctx: net_context_create_ipv4_new: (0x80007408): DROP: src addr is unspecified
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_close_debug: (0x80007408): conn: 0x80039fa8 closed by TCP stack (tcp_in():3626)
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_close_debug: (0x80007408): LISTEN->CLOSED
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_unref: (0x80007408): conn: 0x80039fa8, ref_count=1
[00:00:02.799,980] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x80039fa8, ret=0
[00:00:02.799,980] <dbg> net_tcp: net_tcp_recv: (0x80007408): context: 0x80004448, cb: 0x6000a019, user_data: 0
[00:00:02.799,980] <err> main: client_send_command: Failed to send a command to the server; errno=128

[00:00:02.799,980] <dbg> net_tcp: net_tcp_recv: (0x80007408): context: 0x80004448, cb: 0, user_data: 0
[00:00:02.799,980] <dbg> net_ctx: net_context_unref: (0x80007408): Context 0x80004448 released

I put a breakpoint on the connect() function, which then calls net_tcp_connect(). I noticed that the line (void)tcp_in(conn, NULL); gets executed. Since we’re trying to establish a connection, the line
ret = tcp_out_ext(conn, SYN, NULL /* no data */, conn->seq); is executed, which should initiate the three-way handshake by sending a SYN packet to the destination.

Inside tcp_out_ext(), we enter ip_header_add(), which calls net_context_create_ipv4_new() as we’re using IPv4. However, in that function, I noticed the following condition is being met as the all bits of the source address are zero:
if (net_ipv4_is_addr_unspecified(src)) {
This causes the debug log entry: NET_DBG("DROP: src addr is unspecified");, which we also see above.

The return value -EINVAL is propagated up to the close_status variable in the tcp_in() function, and the verdict is NET_DROP. When execution returns to the net_tcp_connect() function, conn->state == TCP_UNUSED and despite the error, the return value ret is still 0. It seems the line ret = -errno; doesn’t properly assign errno to -EINVAL (I assume that net_context_create_ipv4_new() only returns the value without assigning it to errno) , so the error isn't properly returned to the user space connect() function.

After resolving the issue with the all-zeros source address (now properly set to my configured CONFIG_NET_CONFIG_MY_IPV4_ADDR), the TCP stack successfully sends a SYN packet. However, since the remote server is down, it transitions to the ACK,RST state, causing the connection to close. Despite this, as shown in the log below, the return value from net_tcp_connect() is still 0, which is not the expected behavior.

[00:00:02.799,980] <inf> phy_mc_ksz8081: PHY 0 is up
[00:00:02.799,980] <inf> phy_mc_ksz8081: PHY (0) Link speed 100 Mb, full duplex

[00:00:02.799,980] <dbg> net_tcp: net_tcp_init: (0x80007408): Workq started. Thread ID: 0x80007190
*** Booting Zephyr OS build v3.7.0-2542-g7dde60404492 ***
[00:00:02.799,980] <inf> net_config: Initializing network
[00:00:02.799,980] <inf> net_config: IPv4 address: 172.18.133.10
[00:00:02.799,980] <err> eth_nxp_enet_mac: ENET_GetRxFrameSize return: 4001
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_ref: (0x80007408): conn: 0x80039fa8, ref_count: 1
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_alloc: (0x80007408): conn: 0x80039fa8
[00:00:02.799,980] <dbg> net_sock: zsock_socket_internal: (0x80007408): socket: ctx=0x80004448, fd=3
[00:00:02.799,980] <dbg> net_tcp: net_tcp_recv: (0x80007408): context: 0x80004448, cb: 0x6000a019, user_data: 0
[00:00:02.799,980] <dbg> net_ctx: net_context_bind: (0x80007408): Context 0x80004448 binding to TCP 0.0.0.0:47538 iface 1 (0x80001208                                                                                                        )
[00:00:02.799,980] <dbg> net_tcp: net_tcp_connect: (0x80007408): context: 0x80004448, local: 0.0.0.0, remote: 172.20.5.3
[00:00:02.799,980] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x80039fa8 src: 172.18.133.10, dst: 172.20.5.3
[00:00:02.799,980] <dbg> net_tcp: tcp_in: (0x80007408):  [LISTEN Seq=1757565892 Ack=0]
[00:00:02.799,980] <dbg> net_tcp: tcp_send_process_no_lock: (0x80007408): SYN Seq=1757565892 Len=0
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_ref: (0x80007408): conn: 0x80039fa8, ref_count: 2
[00:00:02.799,980] <dbg> net_tcp: tcp_in: (0x80007408): LISTEN->SYN_SENT
[00:00:02.799,980] <dbg> net_tcp: tcp_in: (0x80007060): ACK,RST Seq=0 Ack=1757565893 Len=0 [SYN_SENT Seq=1757565893 Ack=0]
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_close_debug: (0x80007060): conn: 0x80039fa8 closed by TCP stack (tcp_in():3626)
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_close_debug: (0x80007060): SYN_SENT->CLOSED
[00:00:02.799,980] <dbg> net_tcp: tcp_conn_unref: (0x80007060): conn: 0x80039fa8, ref_count=2
[00:00:02.799,980] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x80039fa8, ret=0

This issue appears to affect multiple parts of the function. While I haven't thoroughly examined all of them yet, it seems there are additional instances where the net_tcp_connect() function may fail. It's important to ensure that the return value is properly propagated to the ret variable in net_tcp_connect(), unlike the two cases I've highlighted earlier.

Best Regards,
Ofir.

jukkar · 2024-09-23T08:25:17Z

jukkar
Sep 23, 2024
Collaborator

I could not replicate the issue you are describing with latest upstream. The TCP connect status is properly propagated to the application.

[00:00:00.000,000] <dbg> net_tcp: net_tcp_init: (0x807a780): Workq started. Thread ID: 0x807a540
*** Booting Zephyr OS build v3.7.0-3233-g4cc3134aa1c1 ***
[00:00:00.000,000] <inf> net_config: Initializing network
[00:00:00.000,000] <inf> net_config: IPv4 address: 192.0.2.1
[00:00:00.000,000] <dbg> net_tcp: tcp_conn_ref: (0x807a780): conn: 0x8087320, ref_count: 1
[00:00:00.000,000] <dbg> net_tcp: tcp_conn_alloc: (0x807a780): conn: 0x8087320
[00:00:00.000,000] <dbg> net_tcp: net_tcp_recv: (0x807a780): context: 0x80757c0, cb: 0x804c083, user_data: 0
[00:00:00.000,000] <dbg> net_tcp: net_tcp_connect: (0x807a780): context: 0x80757c0, local: 0.0.0.0, remote: 192.0.2.2
[00:00:00.000,000] <dbg> net_tcp: net_tcp_connect: (0x807a780): conn: 0x8087320 src: 192.0.2.1, dst: 192.0.2.2
[00:00:00.000,000] <dbg> net_tcp: tcp_in: (0x807a780):  [LISTEN Seq=1604170158 Ack=0]
[00:00:00.000,000] <dbg> net_tcp: tcp_send_process_no_lock: (0x807a780): SYN Seq=1604170158 Len=0 
[00:00:00.000,000] <dbg> net_tcp: tcp_conn_ref: (0x807a780): conn: 0x8087320, ref_count: 2
[00:00:00.000,000] <dbg> net_tcp: tcp_in: (0x807a780): LISTEN->SYN_SENT
[00:00:00.120,000] <dbg> net_tcp: tcp_in: (0x8078fe4): ACK,RST Seq=0 Ack=1604170159 Len=0 [SYN_SENT Seq=1604170159 Ack=0]
[00:00:00.120,000] <dbg> net_tcp: tcp_conn_close_debug: (0x8078fe4): conn: 0x8087320 closed by TCP stack (tcp_in():3626)
[00:00:00.120,000] <dbg> net_tcp: tcp_conn_close_debug: (0x8078fe4): SYN_SENT->CLOSED
[00:00:00.120,000] <dbg> net_tcp: tcp_conn_unref: (0x8078fe4): conn: 0x8087320, ref_count=2
[00:00:00.120,000] <dbg> net_tcp: net_tcp_connect: (0x807a780): conn: 0x8087320, ret=-116
[00:00:00.120,000] <err> tcp_conn_test: connect failed; errno = 116
[00:00:00.120,000] <dbg> net_tcp: net_tcp_recv: (0x807a780): context: 0x80757c0, cb: 0, user_data: 0
[00:00:00.120,000] <dbg> net_tcp: net_tcp_put: (0x807a780):  [CLOSED Seq=1604170159 Ack=0]
[00:00:00.120,000] <dbg> net_tcp: net_tcp_put: (0x807a780): context 0x80757c0 CONNECTING
[00:00:00.120,000] <dbg> net_tcp: tcp_conn_unref: (0x807a780): conn: 0x8087320, ref_count=1

5 replies

ofirshe Sep 24, 2024
Author

Hey @jukkar,

After aligning on the latest Zephyr version, the errno 116 issue has been resolved. However, the initial problem where the source address is unspecified still persists.

[00:00:03.511,000] <inf> phy_mc_ksz8081: PHY 0 is up
[00:00:03.516,000] <inf> phy_mc_ksz8081: PHY (0) Link speed 100 Mb, full duplex
[00:00:03.524,000] <dbg> net_tcp: net_tcp_init: (0x80007408): Workq started. Thread ID: 0x80007190
*** Booting Zephyr OS build v3.7.0-3276-gc15a223cfc4e ***
[00:00:03.539,000] <dbg> net_tcp: tcp_conn_ref: (0x80007408): conn: 0x8003bfa8, ref_count: 1
[00:00:03.548,000] <dbg> net_tcp: tcp_conn_alloc: (0x80007408): conn: 0x8003bfa8
[00:00:03.555,000] <dbg> net_sock: zsock_socket_internal: (0x80007408): socket: ctx=0x80004448, fd=3
[00:00:03.565,000] <dbg> net_tcp: net_tcp_recv: (0x80007408): context: 0x80004448, cb: 0x114a9, user_data: 0
[00:00:03.575,000] <dbg> net_ctx: net_context_bind: (0x80007408): Context 0x80004448 binding to TCP 0.0.0.0:64757 iface 1 (0x80001208)
[00:00:03.588,000] <dbg> net_tcp: net_tcp_connect: (0x80007408): context: 0x80004448, local: 0.0.0.0, remote: 172.20.5.6
[00:00:03.599,000] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x8003bfa8 src: 0.0.0.0, dst: 172.20.5.6
[00:00:03.610,000] <dbg> net_tcp: tcp_in: (0x80007408):  [LISTEN Seq=2996964778 Ack=0]
[00:00:03.618,000] <dbg> net_ctx: net_context_create_ipv4_new: (0x80007408): DROP: src addr is unspecified
[00:00:03.628,000] <dbg> net_tcp: tcp_conn_close_debug: (0x80007408): conn: 0x8003bfa8 closed by TCP stack (tcp_in():3626)
[00:00:03.639,000] <dbg> net_tcp: tcp_conn_close_debug: (0x80007408): LISTEN->CLOSED
[00:00:03.648,000] <dbg> net_tcp: tcp_conn_unref: (0x80007408): conn: 0x8003bfa8, ref_count=1
[00:00:03.657,000] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x8003bfa8, ret=0

You can replicate this issue by writing the application as a Zephyr module and assigning it an initialization priority lower than CONFIG_NET_CONFIG_INIT_PRIO. This results in the network interface not being initialized when attempting to connect to a remote host, which in turn leads to the src address being unspecified, as shown in the log.

jukkar Sep 24, 2024
Collaborator

You can replicate this issue by writing the application as a Zephyr module and assigning it an initialization priority lower than CONFIG_NET_CONFIG_INIT_PRIO. This results in the network interface not being initialized when attempting to connect to a remote host, which in turn leads to the src address being unspecified, as shown in the log.

This is expected, you cannot do any network activity before the network itself has been initialized.

ofirshe Sep 24, 2024
Author

@jukkar The issue I’m highlighting is that when the source address is unspecified, the errno is not properly propagated, causing the connect() function to return zero, even though the connection attempt fails. While I understand this may be a rare case, it’s still problematic. I spent a considerable amount of time debugging because connect() reported success, but the subsequent function (in my case, send()) failed with errno ENOTCONN. If connect() had returned a negative error code, it would have saved me a significant amount of debugging time.

[00:00:03.618,000] <dbg> net_ctx: net_context_create_ipv4_new: (0x80007408): DROP: src addr is unspecified
[00:00:03.628,000] <dbg> net_tcp: tcp_conn_close_debug: (0x80007408): conn: 0x8003bfa8 closed by TCP stack (tcp_in():3626)
[00:00:03.639,000] <dbg> net_tcp: tcp_conn_close_debug: (0x80007408): LISTEN->CLOSED
[00:00:03.648,000] <dbg> net_tcp: tcp_conn_unref: (0x80007408): conn: 0x8003bfa8, ref_count=1
[00:00:03.657,000] <dbg> net_tcp: net_tcp_connect: (0x80007408): conn: 0x8003bfa8, ret=0

jukkar Sep 24, 2024
Collaborator

Ok, so you see this error because the src address was not set. And the reason why it was not set because you were trying to use the net stack before it was initialized. Thanks for the extra info, I will investigate if this could be handled properly.

ofirshe Sep 24, 2024
Author

@jukkar I described the problem in my first message; it's likely in net_context_create_ipv4_new(), which only returns -EINVAL without assigning it to errno.

jukkar · 2024-09-24T08:29:22Z

jukkar
Sep 24, 2024
Collaborator

Fix proposal at #78922

1 reply

ofirshe Sep 26, 2024
Author

Thank you for the quick attention and resolution. I saw the changes have been merged—much appreciated!

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issue with connect() Returning Success Without Establishing TCP Connection #78736

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 3 comments 7 replies

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Issue with connect() Returning Success Without Establishing TCP Connection #78736

ofirshe Sep 19, 2024

Replies: 3 comments · 7 replies

jukkar Sep 20, 2024 Collaborator

ofirshe Sep 22, 2024 Author

jukkar Sep 23, 2024 Collaborator

ofirshe Sep 24, 2024 Author

jukkar Sep 24, 2024 Collaborator

ofirshe Sep 24, 2024 Author

jukkar Sep 24, 2024 Collaborator

ofirshe Sep 24, 2024 Author

jukkar Sep 24, 2024 Collaborator

ofirshe Sep 26, 2024 Author

ofirshe
Sep 19, 2024

Replies: 3 comments 7 replies

jukkar
Sep 20, 2024
Collaborator

ofirshe Sep 22, 2024
Author

jukkar
Sep 23, 2024
Collaborator

ofirshe Sep 24, 2024
Author

jukkar Sep 24, 2024
Collaborator

ofirshe Sep 24, 2024
Author

jukkar Sep 24, 2024
Collaborator

ofirshe Sep 24, 2024
Author

jukkar
Sep 24, 2024
Collaborator

ofirshe Sep 26, 2024
Author