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 <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+un...@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+un...@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
PHONE:(510)482-2769 <tel:%28510%29%20482-2769>
--
Paul Romero
-----------
RCOM Communications Software
EMAIL:pa...@rcom-software.com
PHONE:(510)482-2769 <tel:%28510%29%20482-2769>
--
Paul Romero
-----------
RCOM Communications Software
EMAIL:pa...@rcom-software.com
PHONE:(510)482-2769 <tel:%28510%29%20482-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+un...@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
PHONE:(510)482-2769 <tel:%28510%29%20482-2769>
