diff --git a/CMakeLists.txt b/CMakeLists.txt index e61d0fb9a..17926bf33 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -22,7 +22,8 @@ option(COVERAGE "run coverage test" OFF) option(DEVELOPER_MODE "enable developer's checks" OFF) option(CHECK_CPP_STYLE "check code style of C++ sources" OFF) -option(USE_CCACHE "Use ccache if it is available in the system" ON) +option(USE_CCACHE "use ccache if it is available in the system" ON) +option(LOGGING "enable logging of debug information in library" OFF) # Each engine can be enabled separately. # By default all experimental engines are turned off. @@ -76,6 +77,8 @@ set(SOURCE_FILES src/engines/blackhole.h src/out.cc src/out.h + src/logging.c + src/logging.h ) # Add each engine source separately if(ENGINE_CMAP) @@ -247,6 +250,10 @@ if(ENGINE_VCMAP) target_link_libraries(pmemkv PRIVATE ${TBB_LIBRARIES}) endif() +if(LOGGING) + add_definitions(-DPMEMKV_USE_LOGGING) +endif() + ## Configure make install/uninstall and packages configure_file(libpmemkv.pc.in libpmemkv.pc @ONLY) install(FILES ${CMAKE_BINARY_DIR}/libpmemkv.pc diff --git a/examples/pmemkv_basic_c/pmemkv_basic.c b/examples/pmemkv_basic_c/pmemkv_basic.c index 32a39695c..ef59f319c 100644 --- a/examples/pmemkv_basic_c/pmemkv_basic.c +++ b/examples/pmemkv_basic_c/pmemkv_basic.c @@ -18,7 +18,7 @@ assert(expr); \ } while (0) -#define LOG(msg) puts(msg) +#define LOG_EX(msg) puts(msg) #define MAX_VAL_LEN 64 static const uint64_t SIZE = 1024UL * 1024UL * 1024UL; @@ -39,7 +39,7 @@ int main(int argc, char *argv[]) } /* See libpmemkv_config(3) for more detailed example of config creation */ - LOG("Creating config"); + LOG_EX("Creating config"); pmemkv_config *cfg = pmemkv_config_new(); ASSERT(cfg != NULL); @@ -50,13 +50,13 @@ int main(int argc, char *argv[]) s = pmemkv_config_put_force_create(cfg, true); ASSERT(s == PMEMKV_STATUS_OK); - LOG("Opening pmemkv database with 'cmap' engine"); + LOG_EX("Opening pmemkv database with 'cmap' engine"); pmemkv_db *db = NULL; s = pmemkv_open("cmap", cfg, &db); ASSERT(s == PMEMKV_STATUS_OK); ASSERT(db != NULL); - LOG("Putting new key"); + LOG_EX("Putting new key"); const char *key1 = "key1"; const char *value1 = "value1"; s = pmemkv_put(db, key1, strlen(key1), value1, strlen(value1)); @@ -67,13 +67,13 @@ int main(int argc, char *argv[]) ASSERT(s == PMEMKV_STATUS_OK); ASSERT(cnt == 1); - LOG("Reading key back"); + LOG_EX("Reading key back"); char val[MAX_VAL_LEN]; s = pmemkv_get_copy(db, key1, strlen(key1), val, MAX_VAL_LEN, NULL); ASSERT(s == PMEMKV_STATUS_OK); ASSERT(!strcmp(val, "value1")); - LOG("Iterating existing keys"); + LOG_EX("Iterating existing keys"); const char *key2 = "key2"; const char *value2 = "value2"; const char *key3 = "key3"; @@ -82,16 +82,16 @@ int main(int argc, char *argv[]) pmemkv_put(db, key3, strlen(key3), value3, strlen(value3)); pmemkv_get_all(db, &get_kv_callback, NULL); - LOG("Removing existing key"); + LOG_EX("Removing existing key"); s = pmemkv_remove(db, key1, strlen(key1)); ASSERT(s == PMEMKV_STATUS_OK); ASSERT(pmemkv_exists(db, key1, strlen(key1)) == PMEMKV_STATUS_NOT_FOUND); - LOG("Defragmenting the database"); + LOG_EX("Defragmenting the database"); s = pmemkv_defrag(db, 0, 100); ASSERT(s == PMEMKV_STATUS_OK); - LOG("Closing database"); + LOG_EX("Closing database"); pmemkv_close(db); return 0; diff --git a/examples/pmemkv_basic_cpp/pmemkv_basic.cpp b/examples/pmemkv_basic_cpp/pmemkv_basic.cpp index 365358e9c..177d88157 100644 --- a/examples/pmemkv_basic_cpp/pmemkv_basic.cpp +++ b/examples/pmemkv_basic_cpp/pmemkv_basic.cpp @@ -11,13 +11,16 @@ #include #include +#include "../../src/logging.h" +#include "../../src/out.h" + #define ASSERT(expr) \ do { \ if (!(expr)) \ std::cout << pmemkv_errormsg() << std::endl; \ assert(expr); \ } while (0) -#define LOG(msg) std::cout << msg << std::endl +#define LOG_EX(msg) std::cout << msg << std::endl using namespace pmem::kv; @@ -31,7 +34,7 @@ int main(int argc, char *argv[]) } /* See libpmemkv_config(3) for more detailed example of config creation */ - LOG("Creating config"); + LOG_EX("Creating config"); config cfg; status s = cfg.put_path(argv[1]); @@ -41,13 +44,13 @@ int main(int argc, char *argv[]) s = cfg.put_force_create(true); ASSERT(s == status::OK); - LOG("Opening pmemkv database with 'cmap' engine"); + LOG_EX("Opening pmemkv database with 'cmap' engine"); db *kv = new db(); ASSERT(kv != nullptr); s = kv->open("cmap", std::move(cfg)); ASSERT(s == status::OK); - LOG("Putting new key"); + LOG_EX("Putting new key"); s = kv->put("key1", "value1"); ASSERT(s == status::OK); @@ -55,26 +58,26 @@ int main(int argc, char *argv[]) s = kv->count_all(cnt); ASSERT(s == status::OK && cnt == 1); - LOG("Reading key back"); + LOG_EX("Reading key back"); std::string value; s = kv->get("key1", &value); ASSERT(s == status::OK && value == "value1"); - LOG("Iterating existing keys"); + LOG_EX("Iterating existing keys"); s = kv->put("key2", "value2"); ASSERT(s == status::OK); s = kv->put("key3", "value3"); ASSERT(s == status::OK); kv->get_all([](string_view k, string_view v) { - LOG(" visited: " << k.data()); + LOG_EX(" visited: " << k.data()); return 0; }); - LOG("Defragmenting the database"); + LOG_EX("Defragmenting the database"); s = kv->defrag(0, 100); ASSERT(s == status::OK); - LOG("Removing existing key"); + LOG_EX("Removing existing key"); s = kv->remove("key1"); ASSERT(s == status::OK); s = kv->exists("key1"); @@ -90,7 +93,7 @@ int main(int argc, char *argv[]) oss << s; assert(oss.str() == "NOT_FOUND (2)"); - LOG("Closing database"); + LOG_EX("Closing database"); delete kv; return 0; diff --git a/examples/pmemkv_comparator_c/pmemkv_comparator.c b/examples/pmemkv_comparator_c/pmemkv_comparator.c index 90f26ccb0..6474fad99 100644 --- a/examples/pmemkv_comparator_c/pmemkv_comparator.c +++ b/examples/pmemkv_comparator_c/pmemkv_comparator.c @@ -19,7 +19,7 @@ } while (0) #define MIN(x, y) (((x) < (y)) ? (x) : (y)) -#define LOG(msg) puts(msg) +#define LOG_EX(msg) puts(msg) static const uint64_t SIZE = 1024UL * 1024UL * 1024UL; @@ -57,7 +57,7 @@ int main(int argc, char *argv[]) } /* See libpmemkv_config(3) for more detailed example of config creation */ - LOG("Creating config"); + LOG_EX("Creating config"); pmemkv_config *cfg = pmemkv_config_new(); ASSERT(cfg != NULL); @@ -74,13 +74,13 @@ int main(int argc, char *argv[]) s = pmemkv_config_put_comparator(cfg, cmp); ASSERT(s == PMEMKV_STATUS_OK); - LOG("Opening pmemkv database with 'csmap' engine"); + LOG_EX("Opening pmemkv database with 'csmap' engine"); pmemkv_db *db = NULL; s = pmemkv_open("csmap", cfg, &db); ASSERT(s == PMEMKV_STATUS_OK); ASSERT(db != NULL); - LOG("Putting new keys"); + LOG_EX("Putting new keys"); const char *key1 = "key1"; const char *value1 = "value1"; const char *key2 = "key2"; @@ -94,11 +94,11 @@ int main(int argc, char *argv[]) s = pmemkv_put(db, key3, strlen(key3), value3, strlen(value3)); ASSERT(s == PMEMKV_STATUS_OK); - LOG("Iterating over existing keys in order specified by the comparator"); + LOG_EX("Iterating over existing keys in order specified by the comparator"); s = pmemkv_get_all(db, &get_kv_callback, NULL); ASSERT(s == PMEMKV_STATUS_OK); - LOG("Closing database"); + LOG_EX("Closing database"); pmemkv_close(db); return 0; diff --git a/examples/pmemkv_comparator_cpp/pmemkv_comparator.cpp b/examples/pmemkv_comparator_cpp/pmemkv_comparator.cpp index 5b84bdcfb..245f906f4 100644 --- a/examples/pmemkv_comparator_cpp/pmemkv_comparator.cpp +++ b/examples/pmemkv_comparator_cpp/pmemkv_comparator.cpp @@ -11,13 +11,16 @@ #include #include +#include "../../src/logging.h" +#include "../../src/out.h" + #define ASSERT(expr) \ do { \ if (!(expr)) \ std::cout << pmemkv_errormsg() << std::endl; \ assert(expr); \ } while (0) -#define LOG(msg) std::cout << msg << std::endl +#define LOG_EX(msg) std::cout << msg << std::endl using namespace pmem::kv; @@ -52,7 +55,7 @@ int main(int argc, char *argv[]) } /* See libpmemkv_config(3) for more detailed example of config creation */ - LOG("Creating config"); + LOG_EX("Creating config"); config cfg; status s = cfg.put_path(argv[1]); @@ -64,13 +67,13 @@ int main(int argc, char *argv[]) s = cfg.put_comparator(lexicographical_comparator{}); ASSERT(s == status::OK); - LOG("Opening pmemkv database with 'csmap' engine"); + LOG_EX("Opening pmemkv database with 'csmap' engine"); db *kv = new db(); ASSERT(kv != nullptr); s = kv->open("csmap", std::move(cfg)); ASSERT(s == status::OK); - LOG("Putting new keys"); + LOG_EX("Putting new keys"); s = kv->put("key1", "value1"); ASSERT(s == status::OK); s = kv->put("key2", "value2"); @@ -78,13 +81,13 @@ int main(int argc, char *argv[]) s = kv->put("key3", "value3"); ASSERT(s == status::OK); - LOG("Iterating over existing keys in order specified by the comparator"); + LOG_EX("Iterating over existing keys in order specified by the comparator"); kv->get_all([](string_view k, string_view v) { - LOG(" visited: " << k.data()); + LOG_EX(" visited: " << k.data()); return 0; }); - LOG("Closing database"); + LOG_EX("Closing database"); delete kv; return 0; diff --git a/examples/pmemkv_open_cpp/pmemkv_open.cpp b/examples/pmemkv_open_cpp/pmemkv_open.cpp index 1a4bf4907..ea47ec396 100644 --- a/examples/pmemkv_open_cpp/pmemkv_open.cpp +++ b/examples/pmemkv_open_cpp/pmemkv_open.cpp @@ -10,13 +10,16 @@ #include #include +#include "../../src/logging.h" +#include "../../src/out.h" + #define ASSERT(expr) \ do { \ if (!(expr)) \ std::cout << pmemkv_errormsg() << std::endl; \ assert(expr); \ } while (0) -#define LOG(msg) std::cout << msg << std::endl +#define LOG_EX(msg) std::cout << msg << std::endl using namespace pmem::kv; @@ -39,19 +42,19 @@ int main(int argc, char *argv[]) } /* See libpmemkv_config(3) for more detailed example of creating a config */ - LOG("Creating config"); + LOG_EX("Creating config"); config cfg; status s = cfg.put_path(argv[1]); ASSERT(s == status::OK); - LOG("Opening pmemkv database with 'cmap' engine"); + LOG_EX("Opening pmemkv database with 'cmap' engine"); db *kv = new db(); ASSERT(kv != nullptr); s = kv->open("cmap", std::move(cfg)); ASSERT(s == status::OK); - LOG("Putting new key"); + LOG_EX("Putting new key"); s = kv->put("key1", "value1"); ASSERT(s == status::OK); @@ -59,28 +62,28 @@ int main(int argc, char *argv[]) s = kv->count_all(cnt); ASSERT(s == status::OK && cnt == 1); - LOG("Reading key back"); + LOG_EX("Reading key back"); std::string value; s = kv->get("key1", &value); ASSERT(s == status::OK && value == "value1"); - LOG("Iterating existing keys"); + LOG_EX("Iterating existing keys"); s = kv->put("key2", "value2"); ASSERT(s == status::OK); s = kv->put("key3", "value3"); ASSERT(s == status::OK); kv->get_all([](string_view k, string_view v) { - LOG(" visited: " << k.data()); + LOG_EX(" visited: " << k.data()); return 0; }); - LOG("Removing existing key"); + LOG_EX("Removing existing key"); s = kv->remove("key1"); ASSERT(s == status::OK); s = kv->exists("key1"); ASSERT(s == status::NOT_FOUND); - LOG("Closing database"); + LOG_EX("Closing database"); delete kv; return 0; diff --git a/examples/pmemkv_pmemobj_cpp/pmemkv_pmemobj.cpp b/examples/pmemkv_pmemobj_cpp/pmemkv_pmemobj.cpp index 53dac801e..fbb35d370 100644 --- a/examples/pmemkv_pmemobj_cpp/pmemkv_pmemobj.cpp +++ b/examples/pmemkv_pmemobj_cpp/pmemkv_pmemobj.cpp @@ -16,14 +16,17 @@ #include #include -#undef LOG +#include "../../src/logging.h" +#include "../../src/out.h" + +#undef LOG_EX #define ASSERT(expr) \ do { \ if (!(expr)) \ std::cout << pmemkv_errormsg() << std::endl; \ assert(expr); \ } while (0) -#define LOG(msg) std::cout << msg << std::endl +#define LOG_EX(msg) std::cout << msg << std::endl using namespace pmem::kv; using pmemoid_vector = pmem::obj::vector; @@ -57,7 +60,7 @@ int main(int argc, char *argv[]) pop.root()->oids->emplace_back(OID_NULL); }); - LOG("Creating configs"); + LOG_EX("Creating configs"); config cfg_1; config cfg_2; @@ -66,7 +69,7 @@ int main(int argc, char *argv[]) ret = cfg_2.put_oid(&(pop.root()->oids->at(1))); ASSERT(ret == status::OK); - LOG("Starting first cmap engine"); + LOG_EX("Starting first cmap engine"); db *kv_1 = new db(); ASSERT(kv_1 != nullptr); status s = kv_1->open("cmap", std::move(cfg_1)); @@ -74,42 +77,42 @@ int main(int argc, char *argv[]) *(pop.root()->str) = "some string"; - LOG("Starting second cmap engine"); + LOG_EX("Starting second cmap engine"); db *kv_2 = new db(); ASSERT(kv_2 != nullptr); s = kv_2->open("cmap", std::move(cfg_2)); ASSERT(s == status::OK); - LOG("Putting new key into first cmap"); + LOG_EX("Putting new key into first cmap"); s = kv_1->put("key_1", "value_1"); ASSERT(s == status::OK); - LOG("Putting new key into second cmap"); + LOG_EX("Putting new key into second cmap"); s = kv_2->put("key_2", "value_2"); ASSERT(s == status::OK); - LOG("Reading key back from first cmap"); + LOG_EX("Reading key back from first cmap"); std::string value; s = kv_1->get("key_1", &value); ASSERT(s == status::OK && value == "value_1"); - LOG("Reading key back from second cmap"); + LOG_EX("Reading key back from second cmap"); value.clear(); s = kv_2->get("key_2", &value); ASSERT(s == status::OK && value == "value_2"); - LOG("Defragmenting the first cmap"); + LOG_EX("Defragmenting the first cmap"); s = kv_1->defrag(0, 100); ASSERT(s == status::OK); - LOG("Defragmenting the second cmap"); + LOG_EX("Defragmenting the second cmap"); s = kv_2->defrag(0, 100); ASSERT(s == status::OK); - LOG("Stopping first cmap engine"); + LOG_EX("Stopping first cmap engine"); delete kv_1; - LOG("Stopping second cmap engine"); + LOG_EX("Stopping second cmap engine"); delete kv_2; } catch (std::exception &e) { diff --git a/src/libpmemkv.hpp b/src/libpmemkv.hpp index 24c2232a8..b669d419a 100644 --- a/src/libpmemkv.hpp +++ b/src/libpmemkv.hpp @@ -13,6 +13,8 @@ #include #include "libpmemkv.h" +#include "logging.h" +#include "out.h" #include /*! \file libpmemkv.hpp @@ -813,6 +815,12 @@ inline status db::open(const std::string &engine_name, config &&cfg) noexcept static_cast(pmemkv_open(engine_name.c_str(), cfg.release(), &db)); if (s == pmem::kv::status::OK) this->db_.reset(db); + + /* initialize the log file */ + // XXX: make 1.0 not hardcoded + out_init("libpmemkv", "PMEMKV_LOG_LEVEL", "PMEMKV_LOG_FILE", 1, 0); + + LOG_PMDK(3, "db open succesfully"); return s; } @@ -822,6 +830,11 @@ inline status db::open(const std::string &engine_name, config &&cfg) noexcept inline void db::close() noexcept { this->db_.reset(nullptr); + + LOG_PMDK(3, "db closed succesfully"); + + /* close the log file */ + out_fini(); } /** diff --git a/src/logging.c b/src/logging.c new file mode 100644 index 000000000..2a3b08853 --- /dev/null +++ b/src/logging.c @@ -0,0 +1,393 @@ +// SPDX-License-Identifier: BSD-3-Clause +/* Copyright 2014-2020, Intel Corporation */ + +// #include "valgrind.h" +#include "logging.h" + +#include +#include +#include +#include +#include +#include +#include + +static const char *Log_prefix; +static int Log_level; +static FILE *Out_fp; +static unsigned Log_alignment; + +// XXX: fix this hardcode +#define SRCVERSION "1.0" + +/* no Windows support, use just POSIX version */ +// #define util_strerror strerror_r +#define os_getenv getenv + +/* + * util_snprintf -- run snprintf; in case of truncation or a failure + * return a negative value, or the number of characters printed otherwise. + */ +int util_snprintf(char *str, size_t size, const char *format, ...) +{ + va_list ap; + va_start(ap, format); + int ret = vsnprintf(str, size, format, ap); + va_end(ap); + + if (ret < 0) { + // if (!errno) + // errno = EIO; + goto err; + } else if ((size_t)ret >= size) { + // errno = ENOBUFS; + goto err; + } + + return ret; +err: + return -1; +} + +/* + * util_getexecname -- return name of current executable + */ +char *util_getexecname(char *path, size_t pathlen) +{ + assert(pathlen != 0); + ssize_t cc; + + cc = readlink("/proc/self/exe", path, pathlen); + if (cc == -1) { + strncpy(path, "unknown", pathlen); + path[pathlen - 1] = '\0'; + } else { + path[cc] = '\0'; + } + + return path; +} + +/* + * util_strwinerror -- should never be called on posix OS - abort() + */ +void util_strwinerror(unsigned long err, char *buff, size_t bufflen) +{ + abort(); +} + +/* extra defines */ +#define OS_DIR_SEPARATOR '\\' +#define UTIL_MAX_ERR_MSG 128 +#ifndef NO_LIBPTHREAD +#define MAXPRINT 8192 /* maximum expected log line */ +#else +#define MAXPRINT 256 /* maximum expected log line for libpmem */ +#endif + +/* + * out_init -- initialize the log + * + * This is called from the library initialization code. + */ +void out_init(const char *log_prefix, const char *log_level_var, const char *log_file_var, + int major_version, int minor_version) +{ + static int once; + + /* only need to initialize the out module once */ + if (once) + return; + once++; + + Log_prefix = log_prefix; + +#ifdef PMEMKV_USE_LOGGING + char *log_level; + char *log_file; + + if ((log_level = os_getenv(log_level_var)) != NULL) { + Log_level = atoi(log_level); + if (Log_level < 0) { + Log_level = 0; + } + } + + if ((log_file = os_getenv(log_file_var)) != NULL && log_file[0] != '\0') { + + /* reserve more than enough space for a PID + '\0' */ + char log_file_pid[PATH_MAX]; + size_t len = strlen(log_file); + if (len > 0 && log_file[len - 1] == '-') { + if (util_snprintf(log_file_pid, PATH_MAX, "%s%d", log_file, + getpid()) < 0) { + // ERR("snprintf: %d", errno); + abort(); + } + log_file = log_file_pid; + } + + if ((Out_fp = fopen(log_file, "w")) == NULL) { + // char buff[UTIL_MAX_ERR_MSG]; + // util_strerror(errno, buff, UTIL_MAX_ERR_MSG); + // fprintf(stderr, "Error (%s): %s=%s: %s\n", log_prefix, + // log_file_var, log_file, buff); + + // ERR("snprintf: %d", errno); + abort(); + } + } +#endif /* PMEMKV_USE_LOGGING */ + + char *log_alignment = os_getenv("PMDK_LOG_ALIGN"); + if (log_alignment) { + int align = atoi(log_alignment); + if (align > 0) + Log_alignment = (unsigned)align; + } + + if (Out_fp == NULL) + Out_fp = stderr; + else + setlinebuf(Out_fp); + +#ifdef PMEMKV_USE_LOGGING + static char namepath[PATH_MAX]; + LOG_PMDK(1, "pid %d: program: %s", getpid(), + util_getexecname(namepath, PATH_MAX)); +#endif + LOG_PMDK(1, "%s version %d.%d", log_prefix, major_version, minor_version); + + static __attribute__((used)) const char *version_msg = "src version: " SRCVERSION; + LOG_PMDK(1, "%s", version_msg); +#if VG_PMEMCHECK_ENABLED + /* + * Attribute "used" to prevent compiler from optimizing out the variable + * when LOG expands to no code (!PMEMKV_USE_LOGGING) + */ + static __attribute__((used)) const char *pmemcheck_msg = + "compiled with support for Valgrind pmemcheck"; + LOG_PMDK(1, "%s", pmemcheck_msg); +#endif /* VG_PMEMCHECK_ENABLED */ +#if VG_HELGRIND_ENABLED + static __attribute__((used)) const char *helgrind_msg = + "compiled with support for Valgrind helgrind"; + LOG_PMDK(1, "%s", helgrind_msg); +#endif /* VG_HELGRIND_ENABLED */ +#if VG_MEMCHECK_ENABLED + static __attribute__((used)) const char *memcheck_msg = + "compiled with support for Valgrind memcheck"; + LOG_PMDK(1, "%s", memcheck_msg); +#endif /* VG_MEMCHECK_ENABLED */ +#if VG_DRD_ENABLED + static __attribute__((used)) const char *drd_msg = + "compiled with support for Valgrind drd"; + LOG_PMDK(1, "%s", drd_msg); +#endif /* VG_DRD_ENABLED */ +#if SDS_ENABLED + static __attribute__((used)) const char *shutdown_state_msg = + "compiled with support for shutdown state"; + LOG_PMDK(1, "%s", shutdown_state_msg); +#endif +#if NDCTL_ENABLED + static __attribute__((used)) const char *ndctl_ge_63_msg = + "compiled with libndctl 63+"; + LOG_PMDK(1, "%s", ndctl_ge_63_msg); +#endif + + // Last_errormsg_key_alloc(); +} + +/* + * out_fini -- close the log file + * + * This is called to close log file before process stop. + */ +void out_fini(void) +{ + if (Out_fp != NULL && Out_fp != stderr) { + fclose(Out_fp); + Out_fp = stderr; + } + + // Last_errormsg_fini(); +} + +/* + * out_print_func -- default print_func, goes to stderr or Out_fp + */ +static void out_print_func(const char *s) +{ + /* to suppress drd false-positive */ + /* XXX: confirm real nature of this issue: pmem/issues#863 */ +#ifdef SUPPRESS_FPUTS_DRD_ERROR + VALGRIND_ANNOTATE_IGNORE_READS_BEGIN(); + VALGRIND_ANNOTATE_IGNORE_WRITES_BEGIN(); +#endif + fputs(s, Out_fp); +#ifdef SUPPRESS_FPUTS_DRD_ERROR + VALGRIND_ANNOTATE_IGNORE_READS_END(); + VALGRIND_ANNOTATE_IGNORE_WRITES_END(); +#endif +} + +/* + * calling Print(s) calls the current print_func... + */ +typedef void (*Print_func)(const char *s); +typedef int (*Vsnprintf_func)(char *str, size_t size, const char *format, va_list ap); +static Print_func Print = out_print_func; +static Vsnprintf_func Vsnprintf = vsnprintf; + +/* + * out_set_print_func -- allow override of print_func used by out module + */ +void out_set_print_func(void (*print_func)(const char *s)) +{ + LOG_PMDK(3, "print %p", print_func); + + Print = (print_func == NULL) ? out_print_func : print_func; +} + +/* + * out_set_vsnprintf_func -- allow override of vsnprintf_func used by out module + */ +void out_set_vsnprintf_func(int (*vsnprintf_func)(char *str, size_t size, + const char *format, va_list ap)) +{ + LOG_PMDK(3, "vsnprintf %p", vsnprintf_func); + + Vsnprintf = (vsnprintf_func == NULL) ? vsnprintf : vsnprintf_func; +} + +/* + * out_snprintf -- (internal) custom snprintf implementation + */ +FORMAT_PRINTF(3, 4) +static int out_snprintf(char *str, size_t size, const char *format, ...) +{ + int ret; + va_list ap; + + va_start(ap, format); + ret = Vsnprintf(str, size, format, ap); + va_end(ap); + + return (ret); +} + +/* + * out_common -- common output code, all output goes through here + */ +static void out_common(const char *file, int line, const char *func, int level, + const char *suffix, const char *fmt, va_list ap) +{ + // int oerrno = errno; + char buf[MAXPRINT]; + unsigned cc = 0; + int ret; + const char *sep = ""; + char errstr[UTIL_MAX_ERR_MSG] = ""; + + // unsigned long olast_error = 0; + // #ifdef _WIN32 + // if (fmt && fmt[0] == '!' && fmt[1] == '!') + // olast_error = GetLastError(); + // #endif + + if (file) { + const char *f = strrchr(file, OS_DIR_SEPARATOR); + if (f) + file = f + 1; + ret = out_snprintf(&buf[cc], MAXPRINT - cc, "<%s>: <%d> [%s:%d %s] ", + Log_prefix, level, file, line, func); + if (ret < 0) { + Print("out_snprintf failed"); + // goto end; + return; + } + cc += (unsigned)ret; + if (cc < Log_alignment) { + memset(buf + cc, ' ', Log_alignment - cc); + cc = Log_alignment; + } + } + + if (fmt) { + if (*fmt == '!') { + sep = ": "; + fmt++; + if (*fmt == '!') { + fmt++; + /* it will abort on non Windows OS */ + // util_strwinerror(olast_error, errstr, + // UTIL_MAX_ERR_MSG); + } else { + // util_strerror(oerrno, errstr, UTIL_MAX_ERR_MSG); + } + } + ret = Vsnprintf(&buf[cc], MAXPRINT - cc, fmt, ap); + if (ret < 0) { + Print("Vsnprintf failed"); + // goto end; + return; + } + cc += (unsigned)ret; + } + + out_snprintf(&buf[cc], MAXPRINT - cc, "%s%s%s", sep, errstr, suffix); + + Print(buf); + + // end: + // errno = oerrno; + // #ifdef _WIN32 + // SetLastError(olast_error); + // #endif +} + +/* + * out -- output a line, newline added automatically + */ +void out(const char *fmt, ...) +{ + va_list ap; + va_start(ap, fmt); + + out_common(NULL, 0, NULL, 0, "\n", fmt, ap); + + va_end(ap); +} + +/* + * out_nonl -- output a line, no newline added automatically + */ +void out_nonl(int level, const char *fmt, ...) +{ + va_list ap; + + if (Log_level < level) + return; + + va_start(ap, fmt); + out_common(NULL, 0, NULL, level, "", fmt, ap); + + va_end(ap); +} + +/* + * out_log -- output a log line if Log_level >= level + */ +void out_log(const char *file, int line, const char *func, int level, const char *fmt, + ...) +{ + va_list ap; + + if (Log_level < level) + return; + + va_start(ap, fmt); + out_common(file, line, func, level, "\n", fmt, ap); + + va_end(ap); +} diff --git a/src/logging.h b/src/logging.h new file mode 100644 index 000000000..e278189cf --- /dev/null +++ b/src/logging.h @@ -0,0 +1,91 @@ +// SPDX-License-Identifier: BSD-3-Clause +/* Copyright 2014-2020, Intel Corporation */ + +#ifndef LIBPMEMKV_LOGGING_H +#define LIBPMEMKV_LOGGING_H + +#ifdef __cplusplus +extern "C" { +#endif + +#include +#include + +#ifndef EVALUATE_DBG_EXPRESSIONS +#if defined(PMEMKV_USE_LOGGING) || defined(__clang_analyzer__) || \ + defined(__COVERITY__) || defined(__KLOCWORK__) +#define EVALUATE_DBG_EXPRESSIONS 1 +#else +#define EVALUATE_DBG_EXPRESSIONS 0 +#endif +#endif + +#define FORMAT_PRINTF(a, b) __attribute__((__format__(__printf__, (a), (b)))) + +/* + * Enable functions for logging (if turned on in CMake) + * else define them as void. + */ +#ifdef PMEMKV_USE_LOGGING + +/* out_* functions imported from PMDK */ +#define OUT_LOG out_log +#define OUT_NONL out_nonl + +#else + +static __attribute__((always_inline)) inline void +out_log_discard(const char *file, int line, const char *func, int level, const char *fmt, + ...) +{ + (void)file; + (void)line; + (void)func; + (void)level; + (void)fmt; +} + +static __attribute__((always_inline)) inline void out_nonl_discard(int level, + const char *fmt, ...) +{ + (void)level; + (void)fmt; +} + +#define OUT_LOG out_log_discard +#define OUT_NONL out_nonl_discard + +#endif /* PMEMKV_USE_LOGGING */ + +/* produce debug/trace output */ +#define LOG_PMDK(level, ...) \ + do { \ + if (!EVALUATE_DBG_EXPRESSIONS) \ + break; \ + OUT_LOG(__FILE__, __LINE__, __func__, level, __VA_ARGS__); \ + } while (0) + +/* produce debug/trace output without prefix and new line */ +#define LOG_NONL(level, ...) \ + do { \ + if (!EVALUATE_DBG_EXPRESSIONS) \ + break; \ + OUT_NONL(level, __VA_ARGS__); \ + } while (0) + +void out_init(const char *log_prefix, const char *log_level_var, const char *log_file_var, + int major_version, int minor_version); +void out_fini(void); +void out(const char *fmt, ...) FORMAT_PRINTF(1, 2); +void out_nonl(int level, const char *fmt, ...) FORMAT_PRINTF(2, 3); +void out_log(const char *file, int line, const char *func, int level, const char *fmt, + ...) FORMAT_PRINTF(5, 6); +void out_set_print_func(void (*print_func)(const char *s)); +void out_set_vsnprintf_func(int (*vsnprintf_func)(char *str, size_t size, + const char *format, va_list ap)); + +#ifdef __cplusplus +} +#endif + +#endif /* LIBPMEMKV_LOGGING_H */ diff --git a/src/out.cc b/src/out.cc index 8c5d71bcf..699182864 100644 --- a/src/out.cc +++ b/src/out.cc @@ -1,5 +1,5 @@ // SPDX-License-Identifier: BSD-3-Clause -/* Copyright 2019, Intel Corporation */ +/* Copyright 2019-2020, Intel Corporation */ #include "out.h" diff --git a/src/out.h b/src/out.h index 63bb63f11..fbc3f49c0 100644 --- a/src/out.h +++ b/src/out.h @@ -1,9 +1,12 @@ // SPDX-License-Identifier: BSD-3-Clause -/* Copyright 2019, Intel Corporation */ +/* Copyright 2019-2020, Intel Corporation */ #ifndef LIBPMEMKV_OUT_H #define LIBPMEMKV_OUT_H +#include "logging.h" + +#include #include std::ostream &out_err_stream(const char *func);