search

apache / logging-log4cxx

Apache Log4cxx is a C++ port of Apache Log4j
http://logging.apache.org/log4cxx
Apache License 2.0
278 stars 122 forks source link

XMLSocketAppender file descriptors remain open upon unsuccessful connect #429

Closed danielpetri closed 5 days ago

danielpetri commented 1 week ago

Description

Log4cxx 1.1.0 (default available on Ubuntu 24.04) does not close file descriptors when the log server, e.g., chainsaw is not running. Counting number of sockets remain open.

Code example:

#include <memory>
#include <log4cxx/patternlayout.h>
#include <log4cxx/net/xmlsocketappender.h>
#include <thread>

int main( int argc, char *argv[] )
{
    auto logger = log4cxx::Logger::getRootLogger( );
    auto appender = std::make_shared<log4cxx::net::XMLSocketAppender>( "localhost", 1234 );
    auto layout =
        std::make_shared<log4cxx::PatternLayout>( LOG4CXX_STR( "[%-4p] (%F:%L) %d{mm:ss,SSS} %X{application} %m%n" ) );
    appender->setLayout( layout );
    log4cxx::helpers::Pool pool;
    appender->activateOptions( pool );
    logger->addAppender( appender );
    logger->setLevel( log4cxx::Level::getInfo( ) );

    while ( true )
    {
        LOG4CXX_ERROR( logger, "Something went wrong" );
        LOG4CXX_INFO( logger, "Very important information" );
        std::this_thread::sleep_for( std::chrono::seconds( 1 ) );
    }

    return 0;
}

Listing and counting the open file descriptors periodically results in an increasing number:

# ls -l /proc/$(pidof log4cxxdemo)/fd | wc -l
123
# sleep 600
# ls -l /proc/$(pidof log4cxxdemo)/fd | wc -l
141

The socket should be closed after connection failures.

Configuration

Version: [Log4cxx 1.1.0]

Operating system: [Linux, Ubuntu 24.04]

Logs

Program output

log4cxx: Could not connect to [localhost:1234]. We will try again in 30000 ms
log4cxx: IO Exception : status code = 111(Connection refused)

Reproduction

Compile the code above and link with log4cxx library, then execute.

rm5248 commented 1 week ago

It seems that current master also has a bug introduced with https://github.com/apache/logging-log4cxx/commit/1a8875ad839a37d2fcf31876c0bbfe61181c9f21, which causes the monitor thread to exit immediately(so it does not reconnect if it can't connect the first time). @stephen-webb has more insight into why the stopMonitor() is being called in the private constructor.

Commenting that out though, I can't reproduce this bug. Are you sure it's due to network sockets? Can you show the output of the ls -l /proc/$(pidof log4cxxdemo)/fd command?

danielpetri commented 1 week ago

Yes, sure. This is the query right after I started log4cxxdemo:

# ls -l /proc/$(pidof log4cxxdemo)/fd
összesen 0
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 0 -> /dev/pts/1
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 1 -> /dev/pts/1
l-wx------ 1 dpetri dpetri 64 nov   17 16:44 10 -> 'pipe:[21457178]'
l-wx------ 1 dpetri dpetri 64 nov   17 16:44 12 -> 'pipe:[21457179]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 2 -> /dev/pts/1
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 3 -> 'socket:[21551985]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 4 -> 'socket:[21551986]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 5 -> 'socket:[21546750]'

Some minutes later:

> ls -l /proc/$(pidof log4cxxdemo)/fd
összesen 0
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 0 -> /dev/pts/1
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 1 -> /dev/pts/1
l-wx------ 1 dpetri dpetri 64 nov   17 16:44 10 -> 'pipe:[21457178]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:47 11 -> 'socket:[21558009]'
l-wx------ 1 dpetri dpetri 64 nov   17 16:44 12 -> 'pipe:[21457179]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:47 13 -> 'socket:[21563601]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:48 14 -> 'socket:[21795300]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 2 -> /dev/pts/1
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 3 -> 'socket:[21551985]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 4 -> 'socket:[21551986]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:44 5 -> 'socket:[21546750]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:46 6 -> 'socket:[21557277]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:46 7 -> 'socket:[21557344]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:46 8 -> 'socket:[21557479]'
lrwx------ 1 dpetri dpetri 64 nov   17 16:46 9 -> 'socket:[21557778]'

Maybe the issue has already been solved on the current master, I only worked with 1.1.0 which is the most recent version available on Ubuntu 24.04.

swebb2066 commented 6 days ago

why the stopMonitor() is being called in the private constructor.

It was meant to be in the destructor. My brain must have been mash that day.

swebb2066 commented 6 days ago

Maybe the issue has already been solved on the current master

I can reproduce the problem when using the release version 1.1 code, but not when using the #431 code

danielpetri commented 6 days ago

@swebb2066 thank you for the investigation. Should I close this ticket? What is the way of pushing Ubuntu to update to a later, stable release?

swebb2066 commented 6 days ago

Should I close this ticket?

Leave it for the moment. I have not yet identified why the sockets are being closed in the #431 code. It seems to me that apr_socket_close is still not being called.

What is the way of pushing Ubuntu to update to a later, stable release?

I do not know.

rm5248 commented 6 days ago

What is the way of pushing Ubuntu to update to a later, stable release?

Report a bug on launchpad.

danielpetri commented 6 days ago

Can you please confirm (accept) this bug for 1.1.0 so I can refer to it in the Ubuntu bug report? Which version shoud I suggest instead of 1.1.0?

swebb2066 commented 6 days ago

It seems the bug was somewhat accidently fixed by destroying the APR memory pool used to create the socket. In the current version the socket is closed by APR as a part of a memory pool cleanup. The stack from the current version at the call to connect and the subsequent call to close is as follows:

Breakpoint 1, __libc_connect (fd=3, addr=..., len=16) at ../sysdeps/unix/sysv/linux/connect.c:24
24      ../sysdeps/unix/sysv/linux/connect.c: No such file or directory.
(gdb) bt
#0  __libc_connect (fd=3, addr=..., len=16) at ../sysdeps/unix/sysv/linux/connect.c:24
#1  0x00005555556ed509 in apr_socket_connect ()
#2  0x00005555556d255b in log4cxx::helpers::APRSocket::APRSocket (this=0x555555818fe0, address=std::shared_ptr<log4cxx::helpers::InetAddress> (use count 2, weak count 0) = {...}, port=1234)
    at /home/stephen/source/logging-log4cxx/src/main/cpp/aprsocket.cpp:73
#3  0x00005555556d1ae1 in std::make_unique<log4cxx::helpers::APRSocket, std::shared_ptr<log4cxx::helpers::InetAddress>&, int&> () at /usr/include/c++/11/bits/unique_ptr.h:962
#4  0x00005555556d1627 in log4cxx::helpers::Socket::create (address=std::shared_ptr<log4cxx::helpers::InetAddress> (use count 2, weak count 0) = {...}, port=1234) at /home/stephen/source/logging-log4cxx/src/main/cpp/socket.cpp:49
#5  0x000055555569329a in log4cxx::net::SocketAppenderSkeleton::connect (this=0x555555818f80, p=...) at /home/stephen/source/logging-log4cxx/src/main/cpp/socketappenderskeleton.cpp:96
#6  0x0000555555692fae in log4cxx::net::SocketAppenderSkeleton::activateOptions (this=0x555555818f80, p=...) at /home/stephen/source/logging-log4cxx/src/main/cpp/socketappenderskeleton.cpp:66
#7  0x00005555555d2d20 in log4cxx::net::XMLSocketAppender::XMLSocketAppender (this=0x555555818f80, host="localhost", port1=1234, __in_chrg=<optimised out>, __vtt_parm=<optimised out>)
    at /home/stephen/source/logging-log4cxx/src/main/cpp/xmlsocketappender.cpp:82
#8  0x000055555558c7ad in std::construct_at<log4cxx::net::XMLSocketAppender, char const (&) [10], int> (__location=0x555555818f80) at /usr/include/c++/11/bits/stl_construct.h:97
#9  0x000055555558c879 in std::allocator_traits<std::allocator<log4cxx::net::XMLSocketAppender> >::construct<log4cxx::net::XMLSocketAppender, char const (&) [10], int> (__a=..., __p=0x555555818f80)
    at /usr/include/c++/11/bits/alloc_traits.h:518
#10 0x000055555558c2af in std::_Sp_counted_ptr_inplace<log4cxx::net::XMLSocketAppender, std::allocator<log4cxx::net::XMLSocketAppender>, (__gnu_cxx::_Lock_policy)2>::_Sp_counted_ptr_inplace<char const (&) [10], int> (
    this=0x555555818f70, __a=...) at /usr/include/c++/11/bits/shared_ptr_base.h:519
#11 0x000055555558bd93 in std::__shared_count<(__gnu_cxx::_Lock_policy)2>::__shared_count<log4cxx::net::XMLSocketAppender, std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (this=0x7fffffffe208,
    __p=@0x7fffffffe200: 0x0, __a=...) at /usr/include/c++/11/bits/shared_ptr_base.h:650
#12 0x000055555558bb28 in std::__shared_ptr<log4cxx::net::XMLSocketAppender, (__gnu_cxx::_Lock_policy)2>::__shared_ptr<std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (this=0x7fffffffe200, __tag=...)
    at /usr/include/c++/11/bits/shared_ptr_base.h:1342
#13 0x000055555558b7fd in std::shared_ptr<log4cxx::net::XMLSocketAppender>::shared_ptr<std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (this=0x7fffffffe200, __tag=...)
    at /usr/include/c++/11/bits/shared_ptr.h:409
#14 0x000055555558b2eb in std::allocate_shared<log4cxx::net::XMLSocketAppender, std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (__a=...) at /usr/include/c++/11/bits/shared_ptr.h:863
#15 0x000055555558a8e1 in std::make_shared<log4cxx::net::XMLSocketAppender, char const (&) [10], int> () at /usr/include/c++/11/bits/shared_ptr.h:879
#16 0x0000555555589e8a in main (argc=1, argv=0x7fffffffe3a8) at /home/stephen/source/logging-log4cxx/src/examples/cpp/testSocketAppender.cpp:9
(gdb) c
Continuing.

Breakpoint 2, __GI___close (fd=3) at ../sysdeps/unix/sysv/linux/close.c:26
26      ../sysdeps/unix/sysv/linux/close.c: No such file or directory.
(gdb) bt
#0  __GI___close (fd=3) at ../sysdeps/unix/sysv/linux/close.c:26
#1  0x00005555556eca29 in socket_cleanup ()
#2  0x00005555556e946f in run_cleanups ()
#3  0x00005555556e82a6 in apr_pool_destroy ()
#4  0x00005555555bf5c7 in log4cxx::helpers::Pool::~Pool (this=0x55555581b6e0, __in_chrg=<optimised out>) at /home/stephen/source/logging-log4cxx/src/main/cpp/pool.cpp:46
#5  0x00005555556d315c in log4cxx::helpers::APRSocket::APRSocketPriv::~APRSocketPriv (this=0x55555581b6c0, __in_chrg=<optimised out>) at /home/stephen/source/logging-log4cxx/src/main/cpp/aprsocket.cpp:31
#6  0x00005555556d3188 in log4cxx::helpers::APRSocket::APRSocketPriv::~APRSocketPriv (this=0x55555581b6c0, __in_chrg=<optimised out>) at /home/stephen/source/logging-log4cxx/src/main/cpp/aprsocket.cpp:31
#7  0x00005555556d1cc2 in std::default_delete<log4cxx::helpers::Socket::SocketPrivate>::operator() (this=0x555555818fe8, __ptr=0x55555581b6c0) at /usr/include/c++/11/bits/unique_ptr.h:85
#8  0x00005555556d1a5e in std::unique_ptr<log4cxx::helpers::Socket::SocketPrivate, std::default_delete<log4cxx::helpers::Socket::SocketPrivate> >::~unique_ptr (this=0x555555818fe8, __in_chrg=<optimised out>)
    at /usr/include/c++/11/bits/unique_ptr.h:361
#9  0x00005555556d1546 in log4cxx::helpers::Socket::~Socket (this=0x555555818fe0, __in_chrg=<optimised out>) at /home/stephen/source/logging-log4cxx/src/main/cpp/socket.cpp:36
#10 0x00005555556d2665 in log4cxx::helpers::APRSocket::APRSocket (this=0x555555818fe0, address=std::shared_ptr<log4cxx::helpers::InetAddress> (use count 2, weak count 0) = {...}, port=1234)
    at /home/stephen/source/logging-log4cxx/src/main/cpp/aprsocket.cpp:79
#11 0x00005555556d1ae1 in std::make_unique<log4cxx::helpers::APRSocket, std::shared_ptr<log4cxx::helpers::InetAddress>&, int&> () at /usr/include/c++/11/bits/unique_ptr.h:962
#12 0x00005555556d1627 in log4cxx::helpers::Socket::create (address=std::shared_ptr<log4cxx::helpers::InetAddress> (use count 2, weak count 0) = {...}, port=1234) at /home/stephen/source/logging-log4cxx/src/main/cpp/socket.cpp:49
#13 0x000055555569329a in log4cxx::net::SocketAppenderSkeleton::connect (this=0x555555818f80, p=...) at /home/stephen/source/logging-log4cxx/src/main/cpp/socketappenderskeleton.cpp:96
#14 0x0000555555692fae in log4cxx::net::SocketAppenderSkeleton::activateOptions (this=0x555555818f80, p=...) at /home/stephen/source/logging-log4cxx/src/main/cpp/socketappenderskeleton.cpp:66
#15 0x00005555555d2d20 in log4cxx::net::XMLSocketAppender::XMLSocketAppender (this=0x555555818f80, host="localhost", port1=1234, __in_chrg=<optimised out>, __vtt_parm=<optimised out>)
    at /home/stephen/source/logging-log4cxx/src/main/cpp/xmlsocketappender.cpp:82
#16 0x000055555558c7ad in std::construct_at<log4cxx::net::XMLSocketAppender, char const (&) [10], int> (__location=0x555555818f80) at /usr/include/c++/11/bits/stl_construct.h:97
#17 0x000055555558c879 in std::allocator_traits<std::allocator<log4cxx::net::XMLSocketAppender> >::construct<log4cxx::net::XMLSocketAppender, char const (&) [10], int> (__a=..., __p=0x555555818f80)
    at /usr/include/c++/11/bits/alloc_traits.h:518
#18 0x000055555558c2af in std::_Sp_counted_ptr_inplace<log4cxx::net::XMLSocketAppender, std::allocator<log4cxx::net::XMLSocketAppender>, (__gnu_cxx::_Lock_policy)2>::_Sp_counted_ptr_inplace<char const (&) [10], int> (
    this=0x555555818f70, __a=...) at /usr/include/c++/11/bits/shared_ptr_base.h:519
#19 0x000055555558bd93 in std::__shared_count<(__gnu_cxx::_Lock_policy)2>::__shared_count<log4cxx::net::XMLSocketAppender, std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (this=0x7fffffffe208,
    __p=@0x7fffffffe200: 0x0, __a=...) at /usr/include/c++/11/bits/shared_ptr_base.h:650
#20 0x000055555558bb28 in std::__shared_ptr<log4cxx::net::XMLSocketAppender, (__gnu_cxx::_Lock_policy)2>::__shared_ptr<std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (this=0x7fffffffe200, __tag=...)
    at /usr/include/c++/11/bits/shared_ptr_base.h:1342
#21 0x000055555558b7fd in std::shared_ptr<log4cxx::net::XMLSocketAppender>::shared_ptr<std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (this=0x7fffffffe200, __tag=...)
    at /usr/include/c++/11/bits/shared_ptr.h:409
#22 0x000055555558b2eb in std::allocate_shared<log4cxx::net::XMLSocketAppender, std::allocator<log4cxx::net::XMLSocketAppender>, char const (&) [10], int> (__a=...) at /usr/include/c++/11/bits/shared_ptr.h:863
#23 0x000055555558a8e1 in std::make_shared<log4cxx::net::XMLSocketAppender, char const (&) [10], int> () at /usr/include/c++/11/bits/shared_ptr.h:879
#24 0x0000555555589e8a in main (argc=1, argv=0x7fffffffe3a8) at /home/stephen/source/logging-log4cxx/src/examples/cpp/testSocketAppender.cpp:9
(gdb)
swebb2066 commented 6 days ago

The commit that fixed the issue is 43e01bf51 which means it is fixed in release 1.2.0

danielpetri commented 5 days ago

Thanks, @swebb2066! I reported the bug in Ubuntu: https://bugs.launchpad.net/ubuntu/+source/log4cxx/+bug/2088751.