Merge pull request #28 from bitshares/variant_test

Logging fix
This commit is contained in:
Abit 2018-03-23 21:11:08 +01:00 committed by GitHub
commit 0fe2e61b21
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
6 changed files with 289 additions and 38 deletions

View file

@ -11,10 +11,10 @@
namespace fc
{
namespace detail
{
class log_context_impl;
class log_message_impl;
namespace detail
{
class log_context_impl;
class log_message_impl;
}
/**
@ -24,19 +24,19 @@ namespace fc
{
public:
/**
* @brief Define's the various log levels for reporting.
* @brief Define's the various log levels for reporting.
*
* Each log level includes all higher levels such that
* Each log level includes all higher levels such that
* Debug includes Error, but Error does not include Debug.
*/
enum values
{
all,
debug,
info,
warn,
error,
off
all,
debug,
info,
warn,
error,
off
};
log_level( values v = off ):value(v){}
explicit log_level( int v ):value( static_cast<values>(v)){}
@ -53,14 +53,14 @@ namespace fc
*
* @see FC_LOG_CONTEXT
*/
class log_context
class log_context
{
public:
log_context();
log_context( log_level ll,
const char* file,
uint64_t line,
const char* method );
const char* file,
uint64_t line,
const char* method );
~log_context();
explicit log_context( const variant& v, uint32_t max_depth );
variant to_variant( uint32_t max_depth )const;
@ -108,16 +108,16 @@ namespace fc
public:
log_message();
/**
* @param ctx - generally provided using the FC_LOG_CONTEXT(LEVEL) macro
* @param ctx - generally provided using the FC_LOG_CONTEXT(LEVEL) macro
*/
log_message( log_context ctx, std::string format, variant_object args = variant_object() );
~log_message();
log_message( const variant& v, uint32_t max_depth );
variant to_variant(uint32_t max_depth)const;
string get_message()const;
log_context get_context()const;
string get_format()const;
variant_object get_data()const;
@ -148,7 +148,7 @@ FC_REFLECT_TYPENAME( fc::log_message );
*/
#define FC_LOG_CONTEXT(LOG_LEVEL) \
fc::log_context( fc::log_level::LOG_LEVEL, __FILE__, __LINE__, __func__ )
/**
* @def FC_LOG_MESSAGE(LOG_LEVEL,FORMAT,...)
*
@ -159,5 +159,7 @@ FC_REFLECT_TYPENAME( fc::log_message );
* @param ... A set of key/value pairs denoted as ("key",val)("key2",val2)...
*/
#define FC_LOG_MESSAGE( LOG_LEVEL, FORMAT, ... ) \
fc::log_message( FC_LOG_CONTEXT(LOG_LEVEL), FORMAT, fc::limited_mutable_variant_object(FC_MAX_LOG_OBJECT_DEPTH)__VA_ARGS__ )
fc::log_message( FC_LOG_CONTEXT(LOG_LEVEL), \
FORMAT, \
fc::limited_mutable_variant_object( FC_MAX_LOG_OBJECT_DEPTH, true )__VA_ARGS__ )

View file

@ -5,7 +5,7 @@
#include <fc/shared_ptr.hpp>
#include <fc/log/log_message.hpp>
namespace fc
namespace fc
{
class appender;
@ -14,13 +14,13 @@ namespace fc
*
*
@code
void my_class::func()
void my_class::func()
{
fc_dlog( my_class_logger, "Format four: ${arg} five: ${five}", ("arg",4)("five",5) );
}
@endcode
*/
class logger
class logger
{
public:
static logger get( const fc::string& name = "default");
@ -149,19 +149,46 @@ namespace fc
BOOST_PP_LPAREN() BOOST_PP_STRINGIZE(base),fc::variant(base,FC_MAX_LOG_OBJECT_DEPTH) BOOST_PP_RPAREN()
#define FC_FORMAT( SEQ )\
BOOST_PP_SEQ_FOR_EACH( FC_FORMAT_ARG, v, SEQ )
BOOST_PP_SEQ_FOR_EACH( FC_FORMAT_ARG, v, SEQ )
// takes a ... instead of a SEQ arg because it can be called with an empty SEQ
// takes a ... instead of a SEQ arg because it can be called with an empty SEQ
// from FC_CAPTURE_AND_THROW()
#define FC_FORMAT_ARG_PARAMS( ... )\
BOOST_PP_SEQ_FOR_EACH( FC_FORMAT_ARGS, v, __VA_ARGS__ )
BOOST_PP_SEQ_FOR_EACH( FC_FORMAT_ARGS, v, __VA_ARGS__ )
#define FC_DUMP_FORMAT_ARG_NAME(r, unused, base) \
"(" BOOST_PP_STRINGIZE(base) ")"
#define FC_DUMP_FORMAT_ARG_NAMES( SEQ )\
BOOST_PP_SEQ_FOR_EACH( FC_DUMP_FORMAT_ARG_NAME, v, SEQ )
// TODO FC_FORMAT_ARG_PARAMS(...) may throw exceptions when calling fc::variant(...) inside,
// as a quick-fix / workaround, we catch all exceptions here.
// However, to log as much info as possible, it's better to catch exceptions when processing each argument
#define idump( SEQ ) \
ilog( FC_FORMAT(SEQ), FC_FORMAT_ARG_PARAMS(SEQ) )
{ \
try { \
ilog( FC_FORMAT(SEQ), FC_FORMAT_ARG_PARAMS(SEQ) ); \
} catch( ... ) { \
ilog ( "[ERROR: Got exception while trying to dump ( ${args} )]",("args",FC_DUMP_FORMAT_ARG_NAMES(SEQ)) ); \
} \
}
#define wdump( SEQ ) \
wlog( FC_FORMAT(SEQ), FC_FORMAT_ARG_PARAMS(SEQ) )
{ \
try { \
wlog( FC_FORMAT(SEQ), FC_FORMAT_ARG_PARAMS(SEQ) ); \
} catch( ... ) { \
wlog ( "[ERROR: Got exception while trying to dump ( ${args} )]",("args",FC_DUMP_FORMAT_ARG_NAMES(SEQ)) ); \
} \
}
#define edump( SEQ ) \
elog( FC_FORMAT(SEQ), FC_FORMAT_ARG_PARAMS(SEQ) )
{ \
try { \
elog( FC_FORMAT(SEQ), FC_FORMAT_ARG_PARAMS(SEQ) ); \
} catch( ... ) { \
elog ( "[ERROR: Got exception while trying to dump ( ${args} )]",("args",FC_DUMP_FORMAT_ARG_NAMES(SEQ)) ); \
} \
}
// this disables all normal logging statements -- not something you'd normally want to do,
// but it's useful if you're benchmarking something and suspect logging is causing
@ -177,4 +204,4 @@ namespace fc
# define ilog(...) FC_MULTILINE_MACRO_BEGIN FC_MULTILINE_MACRO_END
# undef dlog
# define dlog(...) FC_MULTILINE_MACRO_BEGIN FC_MULTILINE_MACRO_END
#endif
#endif

View file

@ -221,18 +221,35 @@ namespace fc
class limited_mutable_variant_object : public mutable_variant_object
{
public:
limited_mutable_variant_object( uint32_t max_depth );
limited_mutable_variant_object( uint32_t max_depth, bool skip_on_exception = false );
template<typename T>
limited_mutable_variant_object& operator()( string key, T&& var )
{
set( std::move(key), variant( fc::forward<T>(var), _max_depth ) );
if( _reached_depth_limit )
// _skip_on_exception will always be true here
return *this;
optional<variant> v;
try
{
v = variant( fc::forward<T>(var), _max_depth );
}
catch( ... )
{
if( !_skip_on_exception )
throw;
v = variant( "[ERROR: Caught exception while converting data to variant]" );
}
set( std::move(key), *v );
return *this;
}
limited_mutable_variant_object& operator()( const variant_object& vo );
private:
const uint32_t _max_depth;
const uint32_t _max_depth; ///< The depth limit
const bool _reached_depth_limit; ///< Indicates whether we've reached depth limit
const bool _skip_on_exception; ///< If set to true, won't rethrow exceptions when reached depth limit
};
/** @ingroup Serializable */

View file

@ -365,15 +365,35 @@ namespace fc
return *this;
}
limited_mutable_variant_object::limited_mutable_variant_object( uint32_t m )
: mutable_variant_object(), _max_depth(m - 1)
limited_mutable_variant_object::limited_mutable_variant_object( uint32_t m, bool skip_on_exception )
: mutable_variant_object(),
_max_depth(m - 1),
_reached_depth_limit(m == 0),
_skip_on_exception(skip_on_exception)
{
FC_ASSERT( m > 0, "Recursion depth exceeded!" );
if( !skip_on_exception )
FC_ASSERT( m > 0, "Recursion depth exceeded!" );
else if( m == 0 )
set( "__err_msg", "[ERROR: Recusion depth exceeded!]" );
}
limited_mutable_variant_object& limited_mutable_variant_object::operator()( const variant_object& vo )
{
mutable_variant_object::operator()( vo );
if( _reached_depth_limit )
// _skip_on_exception will always be true here
return *this;
try
{
mutable_variant_object::operator()( vo );
}
catch( ... )
{
if( !_skip_on_exception )
throw;
else
set( "__err_msg", "[ERROR: Caught exception in operator()( const variant_object& ).]" );
}
return *this;
}

View file

@ -59,5 +59,6 @@ add_executable( all_tests all_tests.cpp
serialization_test.cpp
time_test.cpp
utf8_test.cpp
variant_test.cpp
)
target_link_libraries( all_tests fc )

184
tests/variant_test.cpp Normal file
View file

@ -0,0 +1,184 @@
#include <boost/test/unit_test.hpp>
#include <fc/log/logger.hpp>
#include <fc/container/flat.hpp>
#include <fc/io/raw.hpp>
#include <fc/reflect/variant.hpp>
#include <fc/static_variant.hpp>
#include <fc/log/logger_config.hpp>
namespace fc { namespace test {
struct item;
inline bool operator == ( const item& a, const item& b );
inline bool operator < ( const item& a, const item& b );
struct item_wrapper
{
item_wrapper() {}
item_wrapper(item&& it) { v.reserve(1); v.insert( it ); }
boost::container::flat_set<struct item> v;
};
inline bool operator == ( const item_wrapper& a, const item_wrapper& b )
{ return ( std::tie( a.v ) == std::tie( b.v ) ); }
inline bool operator < ( const item_wrapper& a, const item_wrapper& b )
{ return ( std::tie( a.v ) < std::tie( b.v ) ); }
struct item
{
item(int32_t lvl = 0) : level(lvl) {}
item(item_wrapper&& wp, int32_t lvl = 0) : level(lvl), w(wp) {}
int32_t level;
item_wrapper w;
};
inline bool operator == ( const item& a, const item& b )
{ return ( std::tie( a.level, a.w ) == std::tie( b.level, b.w ) ); }
inline bool operator < ( const item& a, const item& b )
{ return ( std::tie( a.level, a.w ) < std::tie( b.level, b.w ) ); }
} } // namespace fc::test
FC_REFLECT( fc::test::item_wrapper, (v) );
FC_REFLECT( fc::test::item, (level)(w) );
BOOST_AUTO_TEST_SUITE(fc_variant_and_log)
BOOST_AUTO_TEST_CASE( nested_objects_test )
{ try {
ilog( "Suppressing logging (but not disabled)" );
fc::logging_config cfg;
fc::logger_config dlc;
dlc.name = "default";
dlc.level = fc::log_level::debug;
dlc.appenders.push_back("stderr");
cfg.loggers.push_back( dlc );
fc::configure_logging( cfg );
auto create_nested_object = []( uint32_t level )
{
ilog( "Creating nested object with ${lv} level(s)", ("lv",level) );
fc::test::item nested;
for( uint32_t i = 1; i <= level; i++ )
{
if( i % 10 == 0 )
ilog( "Creating level ${lv}", ("lv",i) );
fc::test::item_wrapper wp( std::move(nested) );
nested = fc::test::item( std::move(wp), i );
}
return nested;
};
for (int nested_loops = 0; nested_loops <= 100; ++nested_loops )
{
int nested_levels = nested_loops * 3 + 2;
auto nested = create_nested_object( nested_loops );
fc::variant v;
BOOST_TEST_MESSAGE( "========== About to nested object convert to variant. ==========" );
BOOST_CHECK_THROW( to_variant( nested, v, nested_levels ), fc::assert_exception );
try{ try { try { try {
to_variant( nested, v, nested_levels ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_LOG_AND_RETHROW( (nested) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_RETHROW( (nested) ); BOOST_FAIL( "Expected exception." );
} FC_LOG_AND_RETHROW( ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_LOG ( (nested) ); // CAPTURE_AND_LOG should never throw again
to_variant( nested, v, nested_levels + 1 );
BOOST_TEST_MESSAGE( "========== About to convert nested object from variant. ==========" );
fc::test::item unpacked;
BOOST_CHECK_THROW( from_variant( v, unpacked, nested_levels ), fc::assert_exception );
try{ try { try { try {
from_variant( v, unpacked, nested_levels ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_LOG_AND_RETHROW( (v) ); BOOST_FAIL( "Expected exception." );
} FC_LOG_AND_RETHROW( ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_RETHROW( (v) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_LOG ( (v) ); // CAPTURE_AND_LOG should never throw again
from_variant( v, unpacked, nested_levels + 1 );
BOOST_CHECK( unpacked == nested );
// both log and dump should never throw
BOOST_TEST_MESSAGE( "========== About to log obj. ==========" );
ilog( "The obj is ${a}, variant is ${v}", ("a",nested)("v",v) );
BOOST_TEST_MESSAGE( "========== About to dump obj. ==========" );
idump( (nested)(v) );
fc::static_variant<fc::test::item> sv( nested ), sv1;
BOOST_TEST_MESSAGE( "========== About to convert static_variant to variant. ==========" );
BOOST_CHECK_THROW( to_variant( sv, v, nested_levels + 1 ), fc::assert_exception );
try{ try { try { try {
to_variant( sv, v, nested_levels + 1 ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_RETHROW( (sv) ); BOOST_FAIL( "Expected exception." );
} FC_LOG_AND_RETHROW( ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_LOG_AND_RETHROW( (sv) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_LOG ( (sv) ); // CAPTURE_AND_LOG should never throw again
to_variant( sv, v, nested_levels + 2 );
BOOST_TEST_MESSAGE( "========== About to convert static_variant from variant. ==========" );
BOOST_CHECK_THROW( from_variant( v, sv1, nested_levels + 1 ), fc::assert_exception );
try{ try { try { try {
from_variant( v, sv1, nested_levels + 1 ); BOOST_FAIL( "Expected exception." );
} FC_LOG_AND_RETHROW( ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_RETHROW( (v) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_LOG_AND_RETHROW( (v) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_LOG ( (v) ); // CAPTURE_AND_LOG should never throw again
from_variant( v, sv1, nested_levels + 2 );
BOOST_CHECK( sv == sv1 );
// both log and dump should never throw
BOOST_TEST_MESSAGE( "========== About to log static_variant. ==========" );
wlog( "The static_variant is ${a}, variant is $(v)", ("a",sv)("v",v) );
BOOST_TEST_MESSAGE( "========== About to dump static_variant. ==========" );
wdump( (sv)(v) );
std::vector<fc::static_variant<fc::test::item>> vec(300), vec1;
for( int i = 0; i < 300; i++ )
vec.push_back(sv);
BOOST_TEST_MESSAGE( "========== About to convert vector to variant. ==========" );
BOOST_CHECK_THROW( to_variant( vec, v, nested_levels + 2 ), fc::assert_exception );
try{ try { try { try {
to_variant( vec, v, nested_levels + 2 ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_RETHROW( (vec) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_LOG_AND_RETHROW( (vec) ); BOOST_FAIL( "Expected exception." );
} FC_LOG_AND_RETHROW( ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_LOG ( (vec) ); // CAPTURE_AND_LOG should never throw again
to_variant( vec, v, nested_levels + 3 );
BOOST_TEST_MESSAGE( "========== About to convert vector from variant. ==========" );
BOOST_CHECK_THROW( from_variant( v, vec1, nested_levels + 2 ), fc::assert_exception );
try{ try { try { try {
from_variant( v, vec1, nested_levels + 2 ); BOOST_FAIL( "Expected exception." );
} FC_LOG_AND_RETHROW( ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_LOG_AND_RETHROW( (v) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_RETHROW( (v) ); BOOST_FAIL( "Expected exception." );
} FC_CAPTURE_AND_LOG ( (v) ); // CAPTURE_AND_LOG should never throw again
from_variant( v, vec1, nested_levels + 3 );
BOOST_CHECK( vec == vec1 );
// both log and dump should never throw
BOOST_TEST_MESSAGE( "========== About to log vector. ==========" );
elog( "The vector is ${a}, variant is ${v}", ("a",vec)("v",v) );
BOOST_TEST_MESSAGE( "========== About to dump vector. ==========" );
edump( (vec)(v) );
}
fc::configure_logging( fc::logging_config::default_config() );
ilog( "End suppressing logging" );
} FC_CAPTURE_LOG_AND_RETHROW ( (0) ) }
BOOST_AUTO_TEST_SUITE_END()