1 /*---------------------------------------------------------------------\
3 | |__ / \ / / . \ . \ |
8 \---------------------------------------------------------------------*/
9 /** \file zypp/base/LogControl.cc
18 #include <zypp-core/base/Logger.h>
19 #include <zypp-core/base/LogControl.h>
20 #include <zypp-core/base/ProfilingFormater.h>
21 #include <zypp-core/base/String.h>
22 #include <zypp-core/Date.h>
23 #include <zypp-core/TriBool.h>
24 #include <zypp-core/AutoDispose.h>
26 #include <zypp-core/zyppng/io/Socket>
27 #include <zypp-core/zyppng/io/SockAddr>
28 #include <zypp-core/zyppng/base/EventLoop>
29 #include <zypp-core/zyppng/base/EventDispatcher>
30 #include <zypp-core/zyppng/base/Timer>
31 #include <zypp-core/zyppng/base/private/linuxhelpers_p.h>
32 #include <zypp-core/zyppng/thread/Wakeup>
33 #include <zypp-core/zyppng/base/private/threaddata_p.h>
34 #include <zypp-core/zyppng/base/SocketNotifier>
43 #include <sys/types.h>
52 std::once_flag flagReadEnvAutomatically;
56 constexpr std::string_view ZYPP_MAIN_THREAD_NAME( "Zypp-main" );
58 template<class> inline constexpr bool always_false_v = false;
61 * \internal Provides a very simply lock that is using atomics so it can be
62 * safely used in signal handlers
68 while ( _atomicLock.test_and_set())
69 // reschedule the current thread while we wait, maybe when its our next turn the lock is free again
70 std::this_thread::yield();
78 // we use a lock free atomic flag here so this lock can be safely obtained in a signal handler as well
79 std::atomic_flag _atomicLock = ATOMIC_FLAG_INIT;
91 static LogThread &instance () {
96 void setLineWriter ( boost::shared_ptr<log::LineWriter> writer ) {
97 std::lock_guard lk( _lineWriterLock );
101 boost::shared_ptr<log::LineWriter> getLineWriter () {
102 std::lock_guard lk( _lineWriterLock );
103 auto lw = _lineWriter;
108 _stopSignal.notify();
109 if ( _thread.get_id() != std::this_thread::get_id() )
113 std::thread::id threadId () {
114 return _thread.get_id();
117 static std::string sockPath () {
118 static std::string path = zypp::str::Format("zypp-logsocket-%1%") % getpid();
126 // Name the thread that started the logger assuming it's main thread.
127 zyppng::ThreadData::current().setName(ZYPP_MAIN_THREAD_NAME);
128 _thread = std::thread( [this] () {
135 // force the kernel to pick another thread to handle those signals
136 zyppng::blockSignalsForCurrentThread( { SIGTERM, SIGINT, SIGPIPE, } );
138 zyppng::ThreadData::current().setName("Zypp-Log");
140 auto ev = zyppng::EventLoop::create();
141 auto server = zyppng::Socket::create( AF_UNIX, SOCK_STREAM, 0 );
142 auto stopNotifyWatch = _stopSignal.makeNotifier( );
144 std::vector<zyppng::Socket::Ptr> clients;
146 // bind to a abstract unix domain socket address, which means we do not need to care about cleaning it up
147 server->bind( std::make_shared<zyppng::UnixSockAddr>( sockPath(), true ) );
150 // wait for incoming connections from other threads
151 server->connectFunc( &zyppng::Socket::sigIncomingConnection, [&](){
153 auto cl = server->accept();
155 clients.push_back( cl );
157 // wait until data is available, we operate line by line so we only
158 // log a string once we encounter \n
159 cl->connectFunc( &zyppng::Socket::sigReadyRead, [ this, sock = cl.get() ](){
160 auto writer = getLineWriter();
161 if ( !writer ) return;
162 while ( sock->canReadLine() ) {
163 auto br = sock->readLine();
164 writer->writeOut( std::string( br.data(), br.size() - 1 ) );
168 // once a client disconnects we remove it from the std::vector so that the socket is not leaked
169 cl->connectFunc( &zyppng::Socket::sigDisconnected, [&clients, sock = std::weak_ptr(cl)](){
170 auto lock = sock.lock();
174 auto idx = std::find_if( clients.begin(), clients.end(), [lock]( const auto &s ){ return lock.get() == s.get(); } );
175 clients.erase( idx );
180 stopNotifyWatch->connectFunc( &zyppng::SocketNotifier::sigActivated, [&ev]( const auto &, auto ) {
186 // make sure we have written everything
187 auto writer = getLineWriter();
189 for ( auto &sock : clients ){
190 while ( sock->canReadLine() ) {
191 auto br = sock->readLine();
192 writer->writeOut( std::string( br.data(), br.size() - 1 ) );
200 zyppng::Wakeup _stopSignal;
202 // since the public API uses boost::shared_ptr we can not use the atomic
203 // functionalities provided in std.
204 // this lock type can be used safely in signals
205 SpinLock _lineWriterLock;
206 // boost shared_ptr has a lock free implementation of reference counting so it can be used from signal handlers as well
207 boost::shared_ptr<log::LineWriter> _lineWriter{ nullptr };
214 // make sure the thread is running
215 LogThread::instance();
223 * Tries to connect to the log threads socket, returns true on success or
224 * if the socket is already connected
226 bool ensureConnection () {
230 _sockFD = ::socket( AF_UNIX, SOCK_STREAM, 0 );
234 zyppng::UnixSockAddr addr( LogThread::sockPath(), true );
235 return zyppng::trySocketConnection( _sockFD, addr, 100 );
239 * Sends a message to the log thread.
241 void pushMessage ( std::string &&msg ) {
242 if ( inPushMessage ) {
246 // make sure we do not end up in a busy loop
247 zypp::AutoDispose<bool *> res( &inPushMessage, [](auto val){
250 inPushMessage = true;
252 // if we are in the same thread as the Log worker we can directly push our messages out, no need to use the socket
253 if ( std::this_thread::get_id() == LogThread::instance().threadId() ) {
254 auto writer = LogThread::instance().getLineWriter();
256 writer->writeOut( msg );
260 if(!ensureConnection())
263 if ( msg.back() != '\n' )
267 while ( written < msg.size() ) {
268 const auto res = zyppng::eintrSafeCall( ::send, _sockFD, msg.data() + written, msg.size() - written, MSG_NOSIGNAL );
270 //assume broken socket
281 bool inPushMessage = false;
287 // Fg::Black: 30 Bg: 40 Attr::Normal: 22;27
288 // Fg::Red: 31 ... Attr::Bright: 1
289 // Fg::Green: 32 Attr::Reverse: 7
296 static constexpr std::string_view OO { "\033[0m" };
297 static constexpr std::string_view WH { "\033[37;40m" };
298 static constexpr std::string_view CY { "\033[36;40m" };
299 static constexpr std::string_view YE { "\033[33;1;40m" };
300 static constexpr std::string_view GR { "\033[32;40m" };
301 static constexpr std::string_view RE { "\033[31;1;40m" };
302 static constexpr std::string_view MA { "\033[35;40m" };
304 unsigned TraceLeave::_depth = 1;
306 std::string tracestr( char tag_r, unsigned depth_r, const char * file_r, const char * fnc_r, int line_r )
308 static str::Format fmt { "*** %s %s(%s):%d" };
309 fmt % std::string(depth_r,tag_r) % file_r % fnc_r % line_r;
313 TraceLeave::TraceLeave( const char * file_r, const char * fnc_r, int line_r )
314 : _file( std::move(file_r) )
315 , _fnc( std::move(fnc_r) )
318 const std::string & m { tracestr( '>',_depth++, _file,_fnc,_line ) };
320 Osd(L_USR("TRACE"),1) << m << endl;
323 TraceLeave::~TraceLeave()
325 const std::string & m { tracestr( '<',--_depth, _file,_fnc,_line ) };
327 Osd(L_USR("TRACE"),1) << m << endl;
330 Osd::Osd( std::ostream & str, int i )
331 : _strout { std::cerr }
333 { _strout << (i?WH:YE); }
338 Osd & Osd::operator<<( std::ostream& (*iomanip)( std::ostream& ) )
345 #endif // ZYPP_NDEBUG
347 ///////////////////////////////////////////////////////////////////
349 { /////////////////////////////////////////////////////////////////
351 StdoutLineWriter::StdoutLineWriter()
352 : StreamLineWriter( std::cout )
355 StderrLineWriter::StderrLineWriter()
356 : StreamLineWriter( std::cerr )
359 FileLineWriter::FileLineWriter( const Pathname & file_r, mode_t mode_r )
361 if ( file_r == Pathname("-") )
369 // not filesystem::assert_file as filesystem:: functions log,
370 // and this FileWriter is not yet in place.
371 int fd = ::open( file_r.c_str(), O_CREAT|O_EXCL, mode_r );
375 // set unbuffered write
376 std::ofstream * fstr = 0;
377 _outs.reset( (fstr = new std::ofstream( file_r.asString().c_str(), std::ios_base::app )) );
378 fstr->rdbuf()->pubsetbuf(0,0);
383 /////////////////////////////////////////////////////////////////
385 ///////////////////////////////////////////////////////////////////
387 ///////////////////////////////////////////////////////////////////
389 { /////////////////////////////////////////////////////////////////
390 ///////////////////////////////////////////////////////////////////
392 { /////////////////////////////////////////////////////////////////
394 inline void putStream( const std::string & group_r, LogLevel level_r,
395 const char * file_r, const char * func_r, int line_r,
396 const std::string & buffer_r );
398 ///////////////////////////////////////////////////////////////////
400 // CLASS NAME : Loglinebuf
402 class Loglinebuf : public std::streambuf {
406 Loglinebuf( const std::string & group_r, LogLevel level_r )
416 if ( !_buffer.empty() )
421 void tagSet( const char * fil_r, const char * fnc_r, int lne_r )
430 virtual std::streamsize xsputn( const char * s, std::streamsize n )
431 { return writeout( s, n ); }
433 virtual int overflow( int ch = EOF )
443 virtual int writeout( const char* s, std::streamsize n )
445 //logger::putStream( _group, _level, _file, _func, _line, _buffer );
450 for ( int i = 0; i < n; ++i, ++c )
453 _buffer += std::string( s, c-s );
454 logger::putStream( _group, _level, _file, _func, _line, _buffer );
455 _buffer = std::string();
461 _buffer += std::string( s, c-s );
476 ///////////////////////////////////////////////////////////////////
478 ///////////////////////////////////////////////////////////////////
480 // CLASS NAME : Loglinestream
482 class Loglinestream {
486 Loglinestream( const std::string & group_r, LogLevel level_r )
487 : _mybuf( group_r, level_r )
488 , _mystream( &_mybuf )
492 { _mystream.flush(); }
496 std::ostream & getStream( const char * fil_r, const char * fnc_r, int lne_r )
498 _mybuf.tagSet( fil_r, fnc_r, lne_r );
504 std::ostream _mystream;
506 ///////////////////////////////////////////////////////////////////
508 struct LogControlImpl;
511 * Ugly hack to prevent the use of LogControlImpl when libzypp is shutting down.
512 * Due to the c++ std thread_local static instances are cleaned up before the first global static
513 * destructor is called. So all classes that use logging after that point in time would crash the
514 * application because its accessing a variable that has already been destroyed.
516 int &logControlValidFlag() {
517 // We are using a POD flag that does not have a destructor,
518 // to flag if the thread_local destructors were already executed.
519 // Since TLS data is stored in a segment that is available until the thread ceases to exist it should still be readable
520 // after thread_local c++ destructors were already executed. Or so I hope.
521 static thread_local int logControlValid = 0;
522 return logControlValid;
525 ///////////////////////////////////////////////////////////////////
527 // CLASS NAME : LogControlImpl
529 /** LogControl implementation (thread_local Singleton).
531 * \note There is a slight difference in using the _lineFormater and _lineWriter!
532 * \li \c _lineFormater must not be NULL (create default LogControl::LineFormater)
533 * \li \c _lineWriter is NULL if no logging is performed, this way we can pass
534 * _no_stream as logstream to the application, and avoid unnecessary formating
535 * of logliles, which would then be discarded when passed to some dummy
538 struct LogControlImpl
541 bool isExcessive() const
542 { return _excessive; }
544 void excessive( bool onOff_r )
545 { _excessive = onOff_r; }
548 /** Hint for Formater whether to hide the thread name. */
549 bool hideThreadName() const
551 if ( indeterminate(_hideThreadName) )
552 _hideThreadName = ( zyppng::ThreadData::current().name() == ZYPP_MAIN_THREAD_NAME );
553 return bool(_hideThreadName);
555 /** \overload Setter */
556 void hideThreadName( bool onOff_r )
557 { _hideThreadName = onOff_r; }
558 /** \overload Static getter */
559 static bool instanceHideThreadName()
561 auto impl = LogControlImpl::instance();
562 return impl ? impl->hideThreadName() : false;
564 /** \overload Static setter */
565 static void instanceHideThreadName( bool onOff_r )
567 auto impl = LogControlImpl::instance();
568 if ( impl ) impl->hideThreadName( onOff_r );
572 /** NULL _lineWriter indicates no loggin. */
573 void setLineWriter( const shared_ptr<LogControl::LineWriter> & writer_r )
574 { LogThread::instance().setLineWriter( writer_r ); }
576 shared_ptr<LogControl::LineWriter> getLineWriter() const
577 { return LogThread::instance().getLineWriter(); }
579 /** Assert \a _lineFormater is not NULL. */
580 void setLineFormater( const shared_ptr<LogControl::LineFormater> & format_r )
583 _lineFormater = format_r;
585 _lineFormater.reset( new LogControl::LineFormater );
588 void logfile( const Pathname & logfile_r, mode_t mode_r = 0640 )
590 if ( logfile_r.empty() )
591 setLineWriter( shared_ptr<LogControl::LineWriter>() );
592 else if ( logfile_r == Pathname( "-" ) )
593 setLineWriter( shared_ptr<LogControl::LineWriter>(new log::StderrLineWriter) );
595 setLineWriter( shared_ptr<LogControl::LineWriter>(new log::FileLineWriter(logfile_r, mode_r)) );
599 LogClient _logClient;
600 std::ostream _no_stream;
602 mutable TriBool _hideThreadName = indeterminate; ///< Hint for Formater whether to hide the thread name.
604 shared_ptr<LogControl::LineFormater> _lineFormater;
607 /** Provide the log stream to write (logger interface) */
608 std::ostream & getStream( const std::string & group_r,
614 if ( ! getLineWriter() )
616 if ( level_r == E_XXX && !_excessive )
619 if ( !_streamtable[group_r][level_r] )
621 _streamtable[group_r][level_r].reset( new Loglinestream( group_r, level_r ) );
623 std::ostream & ret( _streamtable[group_r][level_r]->getStream( file_r, func_r, line_r ) );
627 ret << "---<RESET LOGSTREAM FROM FAILED STATE]" << endl;
632 /** Format and write out a logline from Loglinebuf. */
633 void putStream( const std::string & group_r,
638 const std::string & message_r )
640 _logClient.pushMessage( _lineFormater->format( group_r, level_r,
641 file_r, func_r, line_r,
646 typedef shared_ptr<Loglinestream> StreamPtr;
647 typedef std::map<LogLevel,StreamPtr> StreamSet;
648 typedef std::map<std::string,StreamSet> StreamTable;
649 /** one streambuffer per group and level */
650 StreamTable _streamtable;
651 zyppng::Socket::Ptr _sock;
655 void readEnvVars () {
656 if ( getenv("ZYPP_LOGFILE") )
657 logfile( getenv("ZYPP_LOGFILE") );
659 if ( getenv("ZYPP_PROFILING") )
661 shared_ptr<LogControl::LineFormater> formater(new ProfilingFormater);
662 setLineFormater(formater);
666 * No logging per default, unless enabled via $ZYPP_LOGFILE.
670 , _excessive( getenv("ZYPP_FULLLOG") )
671 , _lineFormater( new LogControl::LineFormater )
673 logControlValidFlag() = 1;
674 std::call_once( flagReadEnvAutomatically, &LogControlImpl::readEnvVars, this);
676 // make sure the LogControl is invalidated when we fork
677 pthread_atfork( nullptr, nullptr, &LogControl::notifyFork );
684 logControlValidFlag() = 0;
687 /** The LogControlImpl singleton
688 * \note As most dtors log, it is inportant that the
689 * LogControlImpl instance is the last static variable
690 * destructed. At least destucted after all statics
691 * which log from their dtor.
693 static LogControlImpl *instance();
695 ///////////////////////////////////////////////////////////////////
697 // 'THE' LogControlImpl singleton
698 inline LogControlImpl *LogControlImpl::instance()
700 thread_local static LogControlImpl _instance;
701 if ( logControlValidFlag() > 0 )
706 ///////////////////////////////////////////////////////////////////
708 /** \relates LogControlImpl Stream output */
709 inline std::ostream & operator<<( std::ostream & str, const LogControlImpl & )
711 return str << "LogControlImpl";
714 ///////////////////////////////////////////////////////////////////
716 // Access from logger::
718 ///////////////////////////////////////////////////////////////////
720 std::ostream & getStream( const char * group_r,
726 static std::ostream nstream(NULL);
727 auto control = LogControlImpl::instance();
728 if ( !control || !group_r || strlen(group_r ) == 0 ) {
734 return control->getStream( group_r,
741 /** That's what Loglinebuf calls. */
742 inline void putStream( const std::string & group_r, LogLevel level_r,
743 const char * file_r, const char * func_r, int line_r,
744 const std::string & buffer_r )
746 auto control = LogControlImpl::instance();
750 control->putStream( group_r, level_r,
751 file_r, func_r, line_r,
757 auto impl = LogControlImpl::instance();
760 return impl->isExcessive();
763 /////////////////////////////////////////////////////////////////
764 } // namespace logger
765 ///////////////////////////////////////////////////////////////////
767 using logger::LogControlImpl;
769 ///////////////////////////////////////////////////////////////////
771 ///////////////////////////////////////////////////////////////////
772 std::string LogControl::LineFormater::format( const std::string & group_r,
773 logger::LogLevel level_r,
777 const std::string & message_r )
779 static char hostname[1024];
780 static char nohostname[] = "unknown";
781 std::string now( Date::now().form( "%Y-%m-%d %H:%M:%S" ) );
783 if ( LogControlImpl::instanceHideThreadName() )
784 ret = str::form( "%s <%d> %s(%d) [%s] %s(%s):%d %s",
785 now.c_str(), level_r,
786 ( gethostname( hostname, 1024 ) ? nohostname : hostname ),
789 file_r, func_r, line_r,
792 ret = str::form( "%s <%d> %s(%d) [%s] %s(%s):%d {T:%s} %s",
793 now.c_str(), level_r,
794 ( gethostname( hostname, 1024 ) ? nohostname : hostname ),
797 file_r, func_r, line_r,
798 zyppng::ThreadData::current().name().c_str(),
803 ///////////////////////////////////////////////////////////////////
805 // CLASS NAME : LogControl
806 // Forward to LogControlImpl singleton.
808 ///////////////////////////////////////////////////////////////////
811 void LogControl::logfile( const Pathname & logfile_r )
813 auto impl = LogControlImpl::instance();
817 impl->logfile( logfile_r );
820 void LogControl::logfile( const Pathname & logfile_r, mode_t mode_r )
822 auto impl = LogControlImpl::instance();
826 impl->logfile( logfile_r, mode_r );
829 shared_ptr<LogControl::LineWriter> LogControl::getLineWriter() const
831 auto impl = LogControlImpl::instance();
835 return impl->getLineWriter();
838 void LogControl::setLineWriter( const shared_ptr<LineWriter> & writer_r )
840 auto impl = LogControlImpl::instance();
843 impl->setLineWriter( writer_r );
846 void LogControl::setLineFormater( const shared_ptr<LineFormater> & formater_r )
848 auto impl = LogControlImpl::instance();
851 impl->setLineFormater( formater_r );
854 void LogControl::logNothing()
856 auto impl = LogControlImpl::instance();
859 impl->setLineWriter( shared_ptr<LineWriter>() );
862 void LogControl::logToStdErr()
864 auto impl = LogControlImpl::instance();
867 impl->setLineWriter( shared_ptr<LineWriter>( new log::StderrLineWriter ) );
870 void base::LogControl::emergencyShutdown()
872 LogThread::instance().stop();
875 void LogControl::notifyFork()
877 logger::logControlValidFlag () = 0;
880 ///////////////////////////////////////////////////////////////////
882 // LogControl::TmpExcessive
884 ///////////////////////////////////////////////////////////////////
885 LogControl::TmpExcessive::TmpExcessive()
887 auto impl = LogControlImpl::instance();
890 impl->excessive( true );
892 LogControl::TmpExcessive::~TmpExcessive()
894 auto impl = LogControlImpl::instance();
897 impl->excessive( false );
900 /******************************************************************
902 ** FUNCTION NAME : operator<<
903 ** FUNCTION TYPE : std::ostream &
905 std::ostream & operator<<( std::ostream & str, const LogControl & )
907 auto impl = LogControlImpl::instance();
913 /////////////////////////////////////////////////////////////////
915 ///////////////////////////////////////////////////////////////////
916 /////////////////////////////////////////////////////////////////
918 ///////////////////////////////////////////////////////////////////