3hren / blackhole Goto Github PK
View Code? Open in Web Editor NEWYet another logging library.
License: MIT License
Yet another logging library.
License: MIT License
Elliptics server node writes logs to /dev/null in our load test stand.
If log level is "debug", then 8k rps processed, but if log level is "error", then elliptics server node can process up to 100k rps.
Elliptics writes to logs from multiple threads. Blackhole has many lock waits. This lock offers critical section in which called write of a single message to log sink.
sudo strace -f -p
pidof dnet_ioserv
2> trace2
This log (trace2) contains many records like this:
[pid 15786] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
If log level is "error", then log has much less EAGAIN on mutex comparing to "debug" log level.
We frequently see this issue in elliptics:
# ls -l /proc/19808/fd/ | grep log l-wx------ 1 root root 64 Jul 28 01:49 3 -> /home/admin/elliptics/log/ioserv.log-2015.07.22-1437535502 (deleted)
ioserv.log - elliptics log file - was moved by logrotate 6 days ago, but blackhole didn't notice that and didn't reopen logfile.
Here is appropriate config section:
"logger": {
"frontends": [
{
"formatter": {
"type": "string",
"pattern": "%(timestamp)s %(request_id)s/%(lwp)s/%(pid)s %(severity)s: %(message)s %(...L)s"
},
"sink": {
"type": "files",
"path": "/home/admin/elliptics/log/ioserv.log",
"autoflush": true,
"rotation": {
"move": 0
}
}
}
],
"level": "info"
},
We use blackhole 0.2 if that matters. Rotation changed a little bit - there were introduced additional checks which might explain why 'size' rotation doesn't work in 0.2, but common 'move' logic is the same afaics.
It doesn't happen all the time, but yet quite frequently.
Hi
boost::variant
1.58 has introduced static asserts which fail compilation this way.
Here is code which calls blackhole::dynamic_t::to()
which in turn invokes boost::get<T>(&value)
typedef blackhole::dynamic_t dynamic_t;
...
const dynamic_t m_value;
m_value.to<const dynamic_t::array_t &>().size()
In file included from /usr/include/boost/intrusive/detail/generic_hook.hpp:29:0,
from /usr/include/boost/intrusive/list_hook.hpp:23,
from /usr/include/boost/intrusive/list.hpp:20,
from /home/zbr/rpmbuild/BUILD/elliptics-2.26.9.2/cache/cache.hpp:33,
from /home/zbr/rpmbuild/BUILD/elliptics-2.26.9.2/cache/cache.cpp:18:
/usr/include/boost/variant/get.hpp: In instantiation of 'typename boost::add_pointer<const U>::type boost::strict_get(const boost::variant<T0, TN ...>*) [with U = const std::vector<blackhole::dynamic_t>&; T0 = blackhole::dynamic_t::null_t; TN = {bool, long unsigned int, long int, double, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::vector<blackhole::dynamic_t, std::allocator<blackhole::dynamic_t> >, std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, blackhole::dynamic_t, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, blackhole::dynamic_t> > >}; typename boost::add_pointer<const U>::type = const std::vector<blackhole::dynamic_t>*]':
/usr/include/boost/variant/get.hpp:269:25: required from 'typename boost::add_pointer<const U>::type boost::get(const boost::variant<T0, TN ...>*) [with U = const std::vector<blackhole::dynamic_t>&; T0 = blackhole::dynamic_t::null_t; TN = {bool, long unsigned int, long int, double, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::vector<blackhole::dynamic_t, std::allocator<blackhole::dynamic_t> >, std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, blackhole::dynamic_t, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, blackhole::dynamic_t> > >}; typename boost::add_pointer<const U>::type = const std::vector<blackhole::dynamic_t>*]'
/usr/include/blackhole/dynamic.hpp:396:36: required from 'typename std::enable_if<(blackhole::dynamic_t::is_convertible<T>::value && (! blackhole::type_traits::is_integer<T>::value)), T>::type blackhole::dynamic_t::to() const [with T = const std::vector<blackhole::dynamic_t>&; typename std::enable_if<(blackhole::dynamic_t::is_convertible<T>::value && (! blackhole::type_traits::is_integer<T>::value)), T>::type = const std::vector<blackhole::dynamic_t>&]'
/home/zbr/rpmbuild/BUILD/elliptics-2.26.9.2/cache/../example/config.hpp:237:49: required from here
/usr/include/boost/variant/get.hpp:195:5: error: static assertion failed: boost::variant does not contain specified type U, call to boost::get<U>(const boost::variant<T...>*) will always return NULL
BOOST_STATIC_ASSERT_MSG(
^
Possible types:
::pthread_threadid_np(nullptr, &tid)
call. Otherwise 0
.pthread_self(3)
), which is the same as GDB or LLDB shows as a large hex number.<unnamed>
otherwise.By default there is :#x
spec, meaning the “alternate form” with 0x
prefix, because it's platform-independent.
Generally these placeholders will look like {thread:d}
, {thread:x}
, {thread:s}
or {thread:^20#x}
with spec for example.
The simplest example is to reinit file sink after file has been moved/deleted.
What methods shoud I use, is there any doc or example on that?
Logger objects are non-copyable and only movable by design. Therefore it will be useful to provide some shared pointer wrapped over it to manage its lifetime and share it between several parts of your program.
Sometimes it's useful to declare optional attribute fields in string pattern to be able to perform extended formatting depending on presence that attribute in set.
{
"pattern": "[%(timestamp)s]: 0%(/[request_id])?s: %(message)s"
}
BH_LOG(log, debug, "Le shit");
BH_LOG(log, debug, "Le shit")("request_id", 100500);
[2014-05-29 15:30:51]: 0: Le shit
[2014-05-29 15:30:51]: 0/100500: Le shit
Doesn't compile on Mac, because of googletest couldn't find something from tr1.
More verbose:
In file included from /Users/esafronov/sandbox/blackhole/foreign/gtest/src/gtest-all.cc:39:
In file included from /Users/esafronov/sandbox/blackhole/foreign/gtest/include/gtest/gtest.h:57:
In file included from /Users/esafronov/sandbox/blackhole/foreign/gtest/include/gtest/internal/gtest-internal.h:40:
/Users/esafronov/sandbox/blackhole/foreign/gtest/include/gtest/internal/gtest-port.h:484:13: fatal error: 'tr1/tuple' file not found
# include <tr1/tuple> // NOLINT
^
1 error generated.
It turned out that an easy combination with Blackhole v0.2 (Elliptics and friends) is impossible due to symbol conflicts.
As an easy solution is to introduce inline namespace v1
after each namespace blackhole
.
Useful for developing and debugging.
Adapt http://keepachangelog.com/ for Blackhole
One of the major shortcomings of Boost.Log is that it requires RTTI, even after adopting Boost.TypeIndex in 1.59.0. A quick grep in your repository shows that dynamic_cast
is only used in a unit test and typeid
is not used at all. However, it's hard to verify whether RTTI isn't pulled in from a different source, and whether disabling it would affect binary compatibility with the shared library part.
It would be great if the README spent a few words on documenting these things.
For the sake of ABI incompatibility for different versions.
In theory it allows to use several libraries that use different Blackhole versions in a single project.
For user defined attributes make configurable:
For example:
{
"type": "string",
"pattern": "%(message)s %(([...%k: %v])|, )s.",
}
And the next lines:
BH_LOG(log, debug, "Blah-blah")("host", "localhost", "port", 42000);
BH_LOG(log, debug, "Blah-blah");
Will result in:
Blah-blah ('host': 'localhost', 'port': 42000).
Blah-blah.
Compilation error with swarm package, please take a look at https://groups.google.com/forum/#!topic/reverbrain/N0_4Ns-9RoM
It would be great if you reply in maillist too
It must act like logger object itself.
For example:
logger_base_t log;
LOG(log, "le message")("id", 100500); // Attributes: {"id": 100500}
{
scoped_wrapper_t<logger_base_t> wrapper(log, log::attributes_t({{"answer", 42}}));
LOG(log, "le message")("id", 100500); // Attributes: {"id": 100500}
LOG(wrapper, "le message")("id", 100500); // Attributes: {"id": 100500, "answer": 42}
}
LOG(log, "le message")("id", 100500); // Attributes: {"id": 100500}
There are two main solutions how to provide an extension formatting library to the Blackhole users:
Let's see what pros and cons have these solutions.
If cppformat would have stateful API for writers, that allows to feed arguments one-by-one (instead of variadic pack), then I can possibly hide cppformat inside the Blackhole, providing wrappers. Think about it. but later.
Currently logger objects is not thread-safe.
Its thread-safety is achieved using synchronized wrapper which is just mutex for every method. It is a pain in the ass for some people (me included).
The only part of entire logging system that needs synchronization - are sinks. Some of them are thread-safe by design (e.g. file sink using non-buffered write via writev
syslog or Elasticsearch sink), some of them - aren't.
Think about design:
The problems:
scoped.hpp
file, which requires attribute.hpp
. It makes migration from 0.5 -> 1.0 version much painful.The solution: inverse the API.
Use https://codecov.io/ with its plugin this time
This includes:
Under heavy tests blackhole v0.2 raises weird exceptions, most of which lead to crash
Here is one of them, I noticed attributes = std::unordered_map with 140106538842976 elements
line, which looks wrong. Elliptics log string elliptics: self: addr: no address, resetting state: 0xa73e50
is quite ordinary, it is emitted when client disconnects.
I have coredump, if needed
(gdb) bt full
#0 0x00007f6e68df79c8 in raise () from /lib64/libc.so.6
No symbol table info available.
#1 0x00007f6e68df965a in abort () from /lib64/libc.so.6
No symbol table info available.
#2 0x00007f6e69731b4d in __gnu_cxx::__verbose_terminate_handler() () from /lib64/libstdc++.so.6
No symbol table info available.
#3 0x00007f6e6972f996 in ?? () from /lib64/libstdc++.so.6
No symbol table info available.
#4 0x00007f6e6972e989 in ?? () from /lib64/libstdc++.so.6
No symbol table info available.
#5 0x00007f6e6972f2e5 in __gxx_personality_v0 () from /lib64/libstdc++.so.6
No symbol table info available.
#6 0x00007f6e69192f13 in ?? () from /lib64/libgcc_s.so.1
No symbol table info available.
#7 0x00007f6e69193437 in _Unwind_Resume () from /lib64/libgcc_s.so.1
No symbol table info available.
#8 0x00007f6e6c6fdc54 in blackhole::logger_base_t::get_event_attributes (this=0x7f6d7c001a50) at /usr/include/blackhole/implementation/logger.ipp:165
tv = {tv_sec = 140112243037770, tv_usec = 1}
attributes = std::unordered_map with 140106538842976 elements
#9 0x00007f6e6c727b66 in boost::detail::variant::make_initializer_node::apply<boost::mpl::pair<boost::detail::variant::initializer_root, mpl_::int_<0> >, boost::mpl::l_iter<boost::mpl::list8<blackhole::dynamic_t::null_t, bool, unsigned long, long, double, std::string, std::vector<blackhole::dynamic_t, std::allocator<blackhole::dynamic_t> >, std::map<std::string, blackhole::dynamic_t, std::less<std::string>, std::allocator<std::pair<std::string const, blackhole::dynamic_t> > > > > >::initializer_node::initialize(void*, blackhole::dynamic_t::null_t&&) (dest=0xa385e8, operand=<unknown type in /home/zbr/awork/elliptics/build/library/libelliptics.so.2.26, CU 0xb7c69, DIE 0x12ac2f>) at /usr/include/boost/variant/detail/initializer.hpp:115
No locals.
#10 0x00007f6e6c71ae3e in boost::move<blackhole::dynamic_t::null_t&> (t=...) at /usr/include/boost/move/utility_core.hpp:183
No locals.
#11 0x00007f6e6c79976f in dnet_sink_t::emit (this=0xa5ef40, prio=cocaine::logging::error, app="storage/core", message="elliptics: self: addr: no address, resetting state: 0xa73e50 ") at /home/zbr/awork/elliptics/srw/srw.cpp:274
record = {attributes = std::unordered_map with 8 elements = {["source"] = {value = {which_ = 7, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "\270\026\000|m\177\000\000.nonbloc", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::local}, ["app"] = {value = {which_ = 7, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "\030\230\245\000\000\000\000\000\000\000\000\000m\177\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::local}, ["message"] = {value = {which_ = 7, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "(\026\000|m\177\000\000\270\210\r\000\000\000\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::event}, ["severity"] = {value = {which_ = 0, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "\004\000\000\000\000\000\000\000\245\207\r\000\000\000\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::event}, ["pid"] = {value = {which_ = 1, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "\001\062\000\000\000\000\000\000\000\000\000\000n\177\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::universe}, ["lwp"] = {value = {which_ = 5, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "Q3\000\000\000\000\000\000\371\206\r\000\000\000\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::thread}, ["timestamp"] = {value = {which_ = 8, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = "D0\356U\000\000\000\000\027\211\r\000\000\000\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::event}, ["request_id"] = {value = {which_ = 5, storage_ = {<boost::detail::aligned_storage::aligned_storage_imp<16ul, 8ul>> = {data_ = {buf = '\000' <repeats 12 times>, "n\177\000", align_ = {<No data fields>}}}, static size = <optimized out>, static alignment = <optimized out>}}, scope = blackhole::log::attribute::scope::event}}}
level = blackhole::defaults::severity::error
#12 0x00007f6e6bc9f80d in cocaine::logging::log_t::emit<std::string> (this=0xa60ea0, level=10882720, format=...) at /usr/src/debug/libcocaine-core2-0.11.3.1/include/cocaine/logging.hpp:69
No locals.
#13 0x00007f6e0832c078 in cocaine::storage::log_adapter_impl_t::handle (this=0xa63030, record=...) at /home/zbr/awork/elliptics/cocaine/plugins/storage.cpp:70
level = blackhole::defaults::severity::error
cocaine_level = cocaine::logging::error
#14 0x00007f6e6c6fdbe3 in blackhole::logger_base_t::push(blackhole::log::record_t&&) const (this=0xa62bc0, record=<unknown type in /home/zbr/awork/elliptics/build/library/libelliptics.so.2.26, CU 0xb7c69, DIE 0x17c014>) at /usr/include/blackhole/implementation/logger.ipp:161
lock = {m = 0xa62da0, is_locked = true}
#15 0x00007f6e6c727b66 in boost::detail::variant::make_initializer_node::apply<boost::mpl::pair<boost::detail::variant::initializer_root, mpl_::int_<0> >, boost::mpl::l_iter<boost::mpl::list8<blackhole::dynamic_t::null_t, bool, unsigned long, long, double, std::string, std::vector<blackhole::dynamic_t, std::allocator<blackhole::dynamic_t> >, std::map<std::string, blackhole::dynamic_t, std::less<std::string>, std::allocator<std::pair<std::string const, blackhole::dynamic_t> > > > > >::initializer_node::initialize(void*, blackhole::dynamic_t::null_t&&) (dest=0xa648b8, operand=<unknown type in /home/zbr/awork/elliptics/build/library/libelliptics.so.2.26, CU 0xb7c69, DIE 0x12ac2f>) at /usr/include/boost/variant/detail/initializer.hpp:115
No locals.
#16 0x00007f6e6aacd35a in dnet_log_write (logger=0xa648b8, record=0x7f6d187aa5d0, format=0x7f6e6ab156e0 "self: addr: %s, resetting state: %p") at /home/zbr/awork/elliptics/bindings/cpp/logger.cpp:263
args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7f6d187a8480, reg_save_area = 0x7f6d187a83c0}}
#17 0x00007f6e6aabe213 in dnet_io_process_network (data_=0xa65cf8) at /home/zbr/awork/elliptics/library/pool.c:896
local_dnet_log = 0xa648b8
local_dnet_record = 0x7f6d187aa5d0
addr_str = "no address", '\000' <repeats 117 times>
nio = 0xa65cf8
n = 0xa64cd0
data = 0xa74240
st = 0xa73e50
evs_size = 100
evs = 0x7f6d7c0008c0
evs_tmp = 0x0
ts = {tv_sec = 140106128162816, tv_nsec = 10888720}
tmp = 1
err = -104
num_events = 1
i = 0
prev_tv = {tv_sec = 1441673143, tv_usec = 269220}
curr_tv = {tv_sec = 10888720, tv_usec = 10888720}
#18 0x00007f6e6a6f2555 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#19 0x00007f6e68ec5b9d in clone () from /lib64/libc.so.6
No symbol table info available.
... and other C99 printf format specifiers
http://www.cplusplus.com/reference/cstdio/printf/
http://en.wikipedia.org/wiki/Printf_format_string#Format_placeholders
Under extensive elliptics testing I've gotten following crash due to some exception
It is latest v0.2 branch
(gdb) bt full
#0 0x00007f6a538bb9c8 in raise () from /lib64/libc.so.6
No symbol table info available.
#1 0x00007f6a538bd65a in abort () from /lib64/libc.so.6
No symbol table info available.
#2 0x00007f6a538b4187 in __assert_fail_base () from /lib64/libc.so.6
No symbol table info available.
#3 0x00007f6a538b4232 in __assert_fail () from /lib64/libc.so.6
No symbol table info available.
#4 0x00007f6a46f8f87c in blackhole::scoped_attributes_concept_t::~scoped_attributes_concept_t (this=0x7f69e8007448,
__in_chrg=<optimized out>) at /usr/include/blackhole/implementation/logger.ipp:198
__PRETTY_FUNCTION__ = "virtual blackhole::scoped_attributes_concept_t::~scoped_attributes_concept_t()"
#5 0x00007f6a46fa835f in blackhole::scoped_attributes_t::~scoped_attributes_t (this=0x7f69e8007448, __in_chrg=<optimized out>)
at /usr/include/blackhole/scoped_attributes.hpp:8
No locals.
#6 0x00007f6a467ccc2e in dnet_node_unset_trace_id () at /home/zbr/awork/elliptics/bindings/cpp/logger.cpp:178
local_attributes = @0x7f69e8007670: 0x7f69e8007448
...
(gdb) frame 4
#4 0x00007f6a46f8f87c in blackhole::scoped_attributes_concept_t::~scoped_attributes_concept_t (this=0x7f69e8007448,
__in_chrg=<optimized out>) at /usr/include/blackhole/implementation/logger.ipp:198
198 BOOST_ASSERT(m_logger->state.attributes.scoped.get() == this);
Define BLACKHOLE_HAVE_AT_LEAST_GCC46 determines which includes should be used. And it's not correctly set on gcc5.
Currently a logger's message supplier returns only a string view and it's inconvenient, because string view must point either on some externally allocated buffer or on string literal. It's possible to allow to return ADT of string | string_view.
message_t
class as a wrapper over variant.Using optional .inl
file.
Features:
Currently filtering only occurred for all attributes except local ones to prevent unnecessary initialization if filtering fails.
But there is also useful filtering including all available attributes.
Currently Blackhole shows LWP instead of thread id on Linux. It's likely that you want either TID or LWP, but not both.
Create option BLACKHOLE_USE_LWP
or something like this and move it to the configuration.
Consider using flat map (std::vector as underlying type) or std::map instead of std::unordered_map for attributes keeping and lookup.
At this moment if the logger object is already created there is no way to set attribute mapper to it.
This is required to avoid ifdef shit like this: https://github.com/3Hren/blackhole/blob/master/include/blackhole/attributes.hpp#L7
This is easily doable with custom stack allocator with heap fallback: https://howardhinnant.github.io/stack_alloc.html
Checklist:
ctor({ set_t, ... })
,get<T>(const K&) -> optional<const V&>
.get(const K&) -> optional<const attribute::value&>
.attribute::view
to provide partial view: view.partial<external/internal>(); Internally should use combined view with single underlying set.A declarative, efficient, and flexible JavaScript library for building user interfaces.
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
An Open Source Machine Learning Framework for Everyone
The Web framework for perfectionists with deadlines.
A PHP framework for web artisans
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
Some thing interesting about web. New door for the world.
A server is a program made to process requests and deliver data to clients.
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
Some thing interesting about visualization, use data art
Some thing interesting about game, make everyone happy.
We are working to build community through open source technology. NB: members must have two-factor auth.
Open source projects and samples from Microsoft.
Google ❤️ Open Source for everyone.
Alibaba Open Source for everyone
Data-Driven Documents codes.
China tencent open source team.