Hi:
I think I've isolated the problem and it appears to be in
uv_poll_stop().
In particlular if uv_accept() is called immediately after
uv_poll_stop(), and it reallocates the
same socket descriptor just freed by uv_poll_stop(), then
uv_poll_init() fails with the error
EEXIST or EBADF. This must have something to do with uv_loop_t
handle passed to uv_poll_init(),
called Poll_Loop in my code.
I had to instrument my code to keep track of Libuv API calls to
see this.
The following explanatory items follows.
A - The sequence of calls that produces the problem.
B - Commented syslog() diagnostics.
C - The relevant code segments.
D - The gdb stack backtrace.
Best Regards,
Paul R.
A) The sequence of relevant calls is as follows and the problem
only occur with this exact
sequence of events.
****************************************************************************************
1) uv_poll_stop(): The uv_pool_t handle is bound to socket
descriptor N.
This should free socket descriptor N.
2) uv_accept(): Bound to socket desciptor N as set by uv_fileno().
Socket descriptor N should be newly allocated.
3) uv_poll_init(): Returns EBADF with socket descriptor N and
Poll_Loop.watchers[N] is NULL.
Something is wrong !
B) The commented syslog() diagnostic sequence from the
instrumented code.
**************************************************************************
* Stop Polling - Connection 1 Fd 21. This frees the FD.
Apr 30 15:46:08 mobius pexd[30963]: POLL_CALL[i 1 fd 21] -
IO_TASK - uv_poll_stop() - T_POLL_DISMANTLE_REQ
* Stop Polling - Connection 0 Fd 20. This frees the FD
Apr 30 15:46:08 mobius pexd[30963]: POLL_CALL[i 0 fd 20] -
IO_TASK - uv_poll_stop() - T_POLL_DISMANTLE_REQ
* New Connection - Connection 1 Fd 20. This is fine since
uv_poll_stop() was called for Fd 20 which
freed it and it is newly allcated with uv_accept() and
obtained with uv_fileno().
Apr 30 15:46:08 mobius pexd[30963]: POLL_CALL[i 1 fd 20] -
IO_TASK - uv_accept() + uv_fileno()
* However we crash because uv_poll_init() returned EBADF !
Apr 30 15:46:08 mobius pexd[30963]: POLL_CALL[i 1 fd 20] -
IO_TASK - uv_poll_init() - T_POLL_CONFIG_REQ
Apr 30 15:46:08 mobius pexd[30963]: IO_TASK: POLL_PROXY -
Polling Initialization Error -9, EBADF
C) The edited associated code segments are as follows.
********************************************************
1) Prelude to uv_poll_stop() in poll_proxy() in the IO_Task()
thread. (network_io.c)
------------------------------------------------------------------------------------
case T_POLL_DISMANTLE_REQ:
ppdata = (uv_handle_t **) &msg->buffer[0];
poll_handle = (uv_poll_t *) *ppdata;
syslog(LOG_INFO, "POLL_CALL[i %d fd %d] - IO_TASK -
uv_poll_stop() - T_POLL_DISMANTLE_REQ\n", cdesc->index, cdesc->fd);
if( (r = uv_poll_stop(poll_handle)) )
{
fatal_error(LOG_CRIT, "IO_TASK: POLL_PROXY -
Poll Stop Error %d, %s",
r, uv_err_name(r) );
}
//
// The callback routine notifies the
Protocol_Task() when everything is done.
//
poll_handle->data = (void *) cdesc;
uv_close((uv_handle_t *) poll_handle,
async_close_callback);
2) Connection acceptance in make_incoming_connection() in the
main() thread. (main.c)
---------------------------------------------------------------------------------------
conn_handle = (uv_tcp_t *) VALLOC(sizeof(uv_tcp_t));
uv_tcp_init(&Connect_Loop, conn_handle);
if((r = uv_accept(listen_handle, (uv_stream_t *)
conn_handle)) == 0)
{
//
// A new connection occured.
//
uv_os_fd_t fd;
ENTER_MUTEX(&Protocol_D_Mutex);
nsock = N_Sockets++;
EXIT_MUTEX(&Protocol_D_Mutex);
//
// Fetch the socket descriptor from the connection handle.
//
uv_fileno((const uv_handle_t*) conn_handle, &fd);
//
// Allocate the connection descriptor.
//
cdesc = ALLOC_CONN_DESC(fd);
if( !cdesc )
{
syslog(LOG_DEBUG, "MAIN_TASK: CONNECTION REJECTION -
No Connection Descriptors, N = %d", nsock);
ENTER_MUTEX(&Protocol_D_Mutex);
N_Sockets--;
close(fd);
EXIT_MUTEX(&Protocol_D_Mutex);
uv_close((uv_handle_t *) conn_handle,
forced_close_callback);
return;
}
syslog(LOG_INFO, "POLL_CALL[i %d fd %d] - IO_TASK - uv_accept()
+ uv_fileno()\n", cdesc->index, cdesc->fd);
//
// Save the connection handle and start polling.
//
cdesc->conn_handle = (uv_tcp_t *) conn_handle;
syslog(LOG_INFO, "MAIN_TASK: NEW CONNECTION ESTABLISHED
- CONN %d FD %d", cdesc->index, cdesc->fd);
//
// Set up epoll() plumbing by sending a message to
IO_Task();
//
bzero((void *) &poll_data, sizeof(ASYNC_DATA));
poll_data.type = T_POLL_CONFIG_REQ;
poll_data.async_handle = &IO_Task_Async_Handle;
poll_data.async_q = &IO_Task_Input_Q;
poll_data.object_handle = NULL;
//
// The T_POLL_CONFIG_RSP message will be sent to the
Protocol_Task() which
// is in S_IDLE state.
//
send_async_msg(cdesc, &poll_data);
}
3) Prelude to uv_poll_init() in poll_proxy() in the IO_Task()
thread. (network_io.c)
------------------------------------------------------------------------------------
case T_POLL_CONFIG_REQ:
//
// Main process request to start Libuv/epoll()
operation.
//
poll_handle = (uv_poll_t *)
VALLOC(sizeof(uv_poll_t));
syslog(LOG_INFO, "POLL_CALL[i %d fd %d] - IO_TASK -
uv_poll_init() - T_POLL_CONFIG_REQ\n", cdesc->index, cdesc->fd);
if( (r = uv_poll_init(&Poll_Loop, poll_handle,
cdesc->fd)) != 0)
{
fatal_error(LOG_CRIT, "IO_TASK: POLL_PROXY
- Polling Initialization Error %d, %s",
r, uv_err_name(r));
}
D) Stack backtrace.
(gdb) bt
#0 0x00007f62c47b0267 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:55
#1 0x00007f62c47b1eca in __GI_abort () at abort.c:89
#2 0x000000000040d411 in fatal_error (log_prio=2,
fmt=0x424e28 "IO_TASK: POLL_PROXY - Polling Initialization
Error %d, %s") at misc.c:135
#3 0x0000000000405b6d in poll_proxy (handle=0x641f80
<IO_Task_Async_Handle>) at network_io.c:291
#4 0x00000000004114cb in uv__async_io (loop=0xc26800
<Poll_Loop>, w=<optimized out>, events=<optimized out>)
at src/unix/async.c:163
#5 0x000000000041d255 in uv__io_poll (loop=loop@entry=0xc26800
<Poll_Loop>, timeout=<optimized out>)
at src/unix/linux-core.c:462
#6 0x0000000000411c48 in uv_run (loop=0xc26800 <Poll_Loop>,
mode=UV_RUN_DEFAULT) at src/unix/core.c:385
#7 0x0000000000405835 in IO_Task (arg=0x0) at network_io.c:100
#8 0x00007f62c4b4c6aa in start_thread (arg=0x7f62bbfff700) at
pthread_create.c:333
#9 0x00007f62c4881eed in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:109
At this point cdesc->fd is 20 and Poll_Loop.watchers[20] is NULL.
On 04/30/2021 11:48 AM, Paul Romero wrote:
Hi:
My guess is that there is a subtle, probably timing related,
problem in uv_poll_stop()
simply because I can't think of any other relevant Libuv
routines that are explicitly
called after uv_poll_start() succeeds. What do you think ? Of
course, there could
be a problem in the way connections are rejected. All that code
is in the make_incoming_connection()
callback routine in main.c
Best Regards,
Paul R.
On 04/29/2021 03:14 PM, Paul Romero wrote:
Hi:
I reattached the following files with some confusing debugging
stuff removed and
a dump using them follows.
* main.c
* network_io.c
* rx_fsm.c
* async.c
Again this is the relevant code segment.
case T_POLL_CONFIG_REQ:
//
// Main process request to start Libuv/epoll() operation.
//
poll_handle = (uv_poll_t *) VALLOC(sizeof(uv_poll_t));
if( (r = uv_poll_init(&Poll_Loop, poll_handle,
cdesc->fd)) != 0)
{
fatal_error(LOG_CRIT, "IO_TASK: POLL_PROXY -
Polling Initialization Error %d, %s",
r, uv_err_name(r));
}
This is the crash diagnostic.
IO_TASK: POLL_PROXY - Polling Initialization Error -17, EEXIST
Aborted (core dumped)
And the is the gdb backtrace and is typical of the problem.
Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `./pexd'.
Program terminated with signal SIGABRT, Aborted.
#0 0x00007ff1da90b267 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:55
55 ../sysdeps/unix/sysv/linux/raise.c: No such file or
directory.
(gdb) bt
#0 0x00007ff1da90b267 in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:55
#1 0x00007ff1da90ceca in __GI_abort () at abort.c:89
#2 0x000000000040d379 in fatal_error (log_prio=2,
fmt=0x424ce0 "IO_TASK: POLL_PROXY - Polling
Initialization Error %d, %s") at misc.c:135
#3 0x0000000000405b21 in poll_proxy (handle=0x641f80
<IO_Task_Async_Handle>) at network_io.c:287
#4 0x000000000041142b in uv__async_io (loop=0xc26800
<Poll_Loop>, w=<optimized out>, events=<optimized out>)
at src/unix/async.c:163
#5 0x000000000041d1b5 in uv__io_poll
(loop=loop@entry=0xc26800 <Poll_Loop>, timeout=<optimized out>)
at src/unix/linux-core.c:462
#6 0x0000000000411ba8 in uv_run (loop=0xc26800 <Poll_Loop>,
mode=UV_RUN_DEFAULT) at src/unix/core.c:385
#7 0x000000000040580f in IO_Task (arg=0x0) at network_io.c:100
#8 0x00007ff1daca76aa in start_thread (arg=0x7ff1d5a7c700) at
pthread_create.c:333
#9 0x00007ff1da9dceed in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:109
At this point cdesc->fd is 22 and Poll_Loop.watchers[22] =
0x17ef458, a valid address ?
On 04/29/2021 09:09 AM, Paul Romero wrote:
Hi:
The most common symptom of the problem is that uv_poll_init()
fails which means the problem must
be related to the uv_poll_t Poll_Loop. The relevant code
segment is as follows.
poll_handle = (uv_poll_t *) VALLOC(sizeof(uv_poll_t));
if( (r = uv_poll_init(&Poll_Loop, poll_handle, cdesc->fd))
!= 0)
{
fatal_error(LOG_CRIT, "IO_TASK: POLL_PROXY -
Polling Initialization Error %d, %s",
r, uv_err_name(r));
}
The following files illustrate the problem and are attached
to this message. Please advise me
how to attach files to the list directly.
* trace_badf.txt: A stack trace when the error code is EBADF.
* trace_eexist.txt: A stack trace when the error code is EEXIST.
* network_io.c: The IO_Task() thread code. The problem occurs
in the poll_proxy() routine.
* main.c: The main() process/thread code where most
initialization occurs.
* transmit.c: The Transmit_Task() thread.
* rx_fsm.c: The heart of the protocol task code.
You are right that only the IO_Task() performs polling
related operations.
However, please note that the Transmit_Task() thread uses the
underlying TCP socket descriptor
to send data to the network with Linux send(). (See the
TX_DATA() routine.) Also,
USE_SSL and USE_SCRAM are not defined.
I will send more information if am able to produce the
problem at another point.
Also, I have seen the issue you mentioned before and suspect
it may be relevant.
Please let me know if you need anything else.
Best Regards,
Paul R.
Best Regards,
Paul R.
On 04/28/2021 08:52 PM, Jameson Nash wrote:
I'm assuming from your description that you've ensured all
libuv calls happen from exactly one thread (except
uv_async_send). It sounds like you're describing the issue
that
https://github.com/libuv/libuv/commit/c9406ba0e3d67907c1973a71968b89a6bd83c63c
was intended to fix, which was included in v1.41.0
Note that the Poll_Loop.watchers[N] is not always required
to be NULL, so perhaps you've found a case where it is still
incorrectly expecting that? You might want to file an issue
with code to reproduce the problem, or at least an `rr`
trace dump of the code that hits problem (note that `rr`
could potentially upload all of your hard drive, so be
careful what you are submitting).
On Wed, Apr 28, 2021 at 11:13 PM pa...@rcom-software.com
<mailto:pa...@rcom-software.com> <pa...@rcom-software.com
<mailto:pa...@rcom-software.com>> wrote:
Hi Folks:
I am experiencing an intermittent problem with
uv_poll_init() after the successful establishment and
release
of multiple concurrent TCP connections. I am not sure if
this problem is due to a bug, which may
be corrected in another Libuv release, or if I am doing
something wrong when releasing the poll handle.
Do you have insight about the cause ? The details I
consider most important follow.
The uv_poll_t callback function reads incoming TCP data
as follows.
iff(events & UV_READABLE)
{
CONN_DESC *cdesc = (CONN_DESC *) poll_handle->data;
n = recv(cdesc->fd, cdesc->rx_buf, RX_BUF_SIZE,
MSG_DONTWAIT);
NOTE: I am using Libuv version 1.41.0 running on Ubuntu
Linux version 15.04.
The problem is that uv_poll_init() fails, normally with
the EEXIST or EBADF error code, and
my investigation indicates the uv_loop_t
Poll_Loop.watchers[N] field is not NULL when it should be,
where N is TCP socket descriptor. It occurs immediately
after the uv_poll_t poll_handle is allocated.
(There is exactly one TCP socket descriptor per poll
handle.) The call to uv_poll_init() is as follows
and the socket descriptor is obtained with uv_fileno().
if( (r = uv_poll_init(&Poll_Loop, poll_handle,
cdesc->fd)) != 0)
{
fatal_error(LOG_CRIT, "IO_TASK: POLL_PROXY -
Polling Initialization Error %d, %s",
r, uv_err_name(r));
}
It occurs in the IO_Task() thread when there multiple
TCP socket descriptors are in use. The IO_task
releases the poll_handle with the following code
sequence when it is notified that polling should stop
via a Libuv async. message from the Protocol_Task() thread.
if( (r = uv_poll_stop(poll_handle)) )
{
fatal_error(LOG_CRIT, "IO_TASK: POLL_PROXY -
Poll Stop Error %d, %s",
r, uv_err_name(r) );
}
poll_handle->data = (void *) cdesc;
uv_close((uv_handle_t *) poll_handle,
async_close_callback);
The actual release occurs in async_close_callback() as
follows and the Protocol_Task() releases the
TCP socket decriptor with a normal Linux close() after
it receives the T_DISMANTLE response message.
VFREE((UCHAR *) handle);
//
// Send a notification message to the Protocol_Task.
//
msg = MSG_ALLOC(0, FALSE);
msg->class = C_NOTIFY;
msg->type = T_DISMANTLE_RSP;
msg->info = 0;
SendProtoMsg(cdesc, msg);
I think the underlying cause is that if there is new TCP
connection that uses a the same TCP socket descriptor
as one released with uv_poll_stop() and uv_close(), the
call to uv_poll_init() occurs before the socket closure
has propogated into the uv_loop_t Poll_Handle.
Best Regards,
Paul Romero
--
You received this message because you are subscribed to
the Google Groups "libuv" group.
To unsubscribe from this group and stop receiving emails
from it, send an email to
libuv+unsubscr...@googlegroups.com
<mailto:libuv+unsubscr...@googlegroups.com>.
To view this discussion on the web visit
https://groups.google.com/d/msgid/libuv/c3290a76-ab6b-42ad-8540-33021c6188b9n%40googlegroups.com.
--
You received this message because you are subscribed to a
topic in the Google Groups "libuv" group.
To unsubscribe from this topic, visit
https://groups.google.com/d/topic/libuv/_4ClQoaVPCg/unsubscribe.
To unsubscribe from this group and all its topics, send an
email to libuv+unsubscr...@googlegroups.com
<mailto:libuv+unsubscr...@googlegroups.com>.
To view this discussion on the web visit
https://groups.google.com/d/msgid/libuv/CADnnjUXSsF7QwRnVqFojAm1W_o35CHKyMCPM%2BVw0FM0FjqN1XQ%40mail.gmail.com.
--
Paul Romero
-----------
RCOM Communications Software
EMAIL:pa...@rcom-software.com <mailto:pa...@rcom-software.com>
PHONE: (510)482-2769
--
Paul Romero
-----------
RCOM Communications Software
EMAIL:pa...@rcom-software.com <mailto:pa...@rcom-software.com>
PHONE: (510)482-2769
--
Paul Romero
-----------
RCOM Communications Software
EMAIL:pa...@rcom-software.com <mailto:pa...@rcom-software.com>
PHONE: (510)482-2769
--
You received this message because you are subscribed to a topic
in the Google Groups "libuv" group.
To unsubscribe from this topic, visit
https://groups.google.com/d/topic/libuv/_4ClQoaVPCg/unsubscribe.
To unsubscribe from this group and all its topics, send an
email to libuv+unsubscr...@googlegroups.com
<mailto:libuv+unsubscr...@googlegroups.com>.
To view this discussion on the web visit
https://groups.google.com/d/msgid/libuv/608C50E8.7070202%40rcom-software.com.
--
Paul Romero
-----------
RCOM Communications Software
EMAIL:pa...@rcom-software.com <mailto:pa...@rcom-software.com>
PHONE: (510)482-2769
