Add timestamps to debug log and cache integrity check (#1540)

* Add UTC timestamp to debug output

for easier correlation with external events

Old output:
$ s3fs mybucket /bucket/  -o curldbg,dbglevel=debug -d -d -f
[CRT] s3fs_logger.cpp:LowSetLogLevel(201): change debug level from...
[INF]     s3fs.cpp:set_mountpoint_attribute(3989): PROC(uid=0, ...

New output:
$ s3fs mybucket /bucket/  -o curldbg,dbglevel=debug -d -d -f
2021-01-28T21:09:16.264Z [CRT] s3fs_logger.cpp:LowSetLogLevel(202):...
2021-01-28T21:09:16.264Z [INF]     s3fs.cpp:set_mountpoint_attrib...

* Add UTC timestamp to cache integrity check

for easier correlation with external events.

$ s3fs mybucket /mybucket  -oset_check_cache_sigusr1=/tmp/check.cache

Old output:
$ kill -s SIGUSR1 $(pgrep s3fs)
$ cat /tmp/check.cache
------------------------------------------------------------
Check cache file and its stats file consistency
------------------------------------------------------------
------------------------------------------------------------
Summary - Total files:                0
          Detected error files:       0
          Detected error directories: 0
------------------------------------------------------------

New output:
$ kill -s SIGUSR1 $(pgrep s3fs)
$ cat /tmp/check.cache
---------------------------------------------------------------------------
Check cache file and its stats file consistency at 2021-01-30T13:04:14.111Z
---------------------------------------------------------------------------
---------------------------------------------------------------------------
Summary - Total files:                0
          Detected error files:       0
          Detected error directories: 0
---------------------------------------------------------------------------

* Fix indentation of S3fsLog::GetCurrentTime()
This commit is contained in:
Carsten Grohmann 2021-02-04 02:41:29 +01:00 committed by GitHub
parent 67b9381825
commit 4c6690f5f0
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 31 additions and 15 deletions

View File

@ -29,6 +29,7 @@
#include "s3fs.h" #include "s3fs.h"
#include "fdcache.h" #include "fdcache.h"
#include "s3fs_util.h" #include "s3fs_util.h"
#include "s3fs_logger.h"
#include "string_util.h" #include "string_util.h"
#include "autolock.h" #include "autolock.h"
@ -50,14 +51,14 @@
// The following symbols are used by FdManager::RawCheckAllCache(). // The following symbols are used by FdManager::RawCheckAllCache().
// //
#define CACHEDBG_FMT_DIR_PROB "Directory: %s" #define CACHEDBG_FMT_DIR_PROB "Directory: %s"
#define CACHEDBG_FMT_HEAD "------------------------------------------------------------\n" \ #define CACHEDBG_FMT_HEAD "---------------------------------------------------------------------------\n" \
"Check cache file and its stats file consistency\n" \ "Check cache file and its stats file consistency at %s\n" \
"------------------------------------------------------------" "---------------------------------------------------------------------------"
#define CACHEDBG_FMT_FOOT "------------------------------------------------------------\n" \ #define CACHEDBG_FMT_FOOT "---------------------------------------------------------------------------\n" \
"Summary - Total files: %d\n" \ "Summary - Total files: %d\n" \
" Detected error files: %d\n" \ " Detected error files: %d\n" \
" Detected error directories: %d\n" \ " Detected error directories: %d\n" \
"------------------------------------------------------------" "---------------------------------------------------------------------------"
#define CACHEDBG_FMT_FILE_OK "File: %s%s -> [OK] no problem" #define CACHEDBG_FMT_FILE_OK "File: %s%s -> [OK] no problem"
#define CACHEDBG_FMT_FILE_PROB "File: %s%s" #define CACHEDBG_FMT_FILE_PROB "File: %s%s"
#define CACHEDBG_FMT_DIR_PROB "Directory: %s" #define CACHEDBG_FMT_DIR_PROB "Directory: %s"
@ -905,7 +906,7 @@ bool FdManager::CheckAllCache()
} }
// print head message // print head message
S3FS_PRN_CACHE(fp, CACHEDBG_FMT_HEAD); S3FS_PRN_CACHE(fp, CACHEDBG_FMT_HEAD, S3fsLog::GetCurrentTime());
// Loop in directory of cache file's stats // Loop in directory of cache file's stats
std::string top_path = CacheFileStat::GetCacheFileStatTopDir(); std::string top_path = CacheFileStat::GetCacheFileStatTopDir();

View File

@ -29,11 +29,12 @@
//------------------------------------------------------------------- //-------------------------------------------------------------------
const int S3fsLog::NEST_MAX; const int S3fsLog::NEST_MAX;
const char* S3fsLog::nest_spaces[S3fsLog::NEST_MAX] = {"", " ", " ", " "}; const char* S3fsLog::nest_spaces[S3fsLog::NEST_MAX] = {"", " ", " ", " "};
const char* S3fsLog::LOGFILEENV = "S3FS_LOGFILE"; const char* S3fsLog::LOGFILEENV = "S3FS_LOGFILE";
S3fsLog* S3fsLog::pSingleton = NULL; S3fsLog* S3fsLog::pSingleton = NULL;
S3fsLog::s3fs_log_level S3fsLog::debug_level = S3fsLog::LEVEL_CRIT; S3fsLog::s3fs_log_level S3fsLog::debug_level = S3fsLog::LEVEL_CRIT;
FILE* S3fsLog::logfp = NULL; FILE* S3fsLog::logfp = NULL;
std::string* S3fsLog::plogfile = NULL; std::string* S3fsLog::plogfile = NULL;
char S3fsLog::current_time[32] = "";
//------------------------------------------------------------------- //-------------------------------------------------------------------
// S3fsLog class : class methods // S3fsLog class : class methods

View File

@ -23,6 +23,7 @@
#include <cstdio> #include <cstdio>
#include <syslog.h> #include <syslog.h>
#include <sys/time.h>
//------------------------------------------------------------------- //-------------------------------------------------------------------
// S3fsLog class // S3fsLog class
@ -46,6 +47,7 @@ class S3fsLog
static s3fs_log_level debug_level; static s3fs_log_level debug_level;
static FILE* logfp; static FILE* logfp;
static std::string* plogfile; static std::string* plogfile;
static char current_time[32];
protected: protected:
bool LowLoadEnv(); bool LowLoadEnv();
@ -69,6 +71,18 @@ class S3fsLog
LEVEL_ERR == (level & LEVEL_DBG) ? LOG_ERR : LOG_CRIT ); LEVEL_ERR == (level & LEVEL_DBG) ? LOG_ERR : LOG_CRIT );
} }
static const char* GetCurrentTime()
{
struct timeval now;
struct tm res;
char tmp[32];
gettimeofday(&now, NULL);
strftime(tmp, sizeof(tmp), "%Y-%m-%dT%H:%M:%S", gmtime_r(&now.tv_sec, &res));
snprintf(current_time, sizeof(current_time), "%s.%03ldZ", tmp, (now.tv_usec / 1000));
return current_time;
}
static const char* GetLevelString(s3fs_log_level level) static const char* GetLevelString(s3fs_log_level level)
{ {
return ( LEVEL_DBG == (level & LEVEL_DBG) ? "[DBG] " : return ( LEVEL_DBG == (level & LEVEL_DBG) ? "[DBG] " :
@ -132,7 +146,7 @@ class S3fsLog
if(S3fsLog::IsS3fsLogLevel(level)){ \ if(S3fsLog::IsS3fsLogLevel(level)){ \
if(foreground || S3fsLog::IsSetLogFile()){ \ if(foreground || S3fsLog::IsSetLogFile()){ \
S3fsLog::SeekEnd(); \ S3fsLog::SeekEnd(); \
fprintf(S3fsLog::GetOutputLogFile(), "%s%s:%s(%d): " fmt "%s\n", S3fsLog::GetLevelString(level), __FILE__, __func__, __LINE__, __VA_ARGS__); \ fprintf(S3fsLog::GetOutputLogFile(), "%s %s%s:%s(%d): " fmt "%s\n", S3fsLog::GetCurrentTime(), S3fsLog::GetLevelString(level), __FILE__, __func__, __LINE__, __VA_ARGS__); \
S3fsLog::Flush(); \ S3fsLog::Flush(); \
}else{ \ }else{ \
syslog(S3fsLog::GetSyslogLevel(level), "%s%s:%s(%d): " fmt "%s", instance_name.c_str(), __FILE__, __func__, __LINE__, __VA_ARGS__); \ syslog(S3fsLog::GetSyslogLevel(level), "%s%s:%s(%d): " fmt "%s", instance_name.c_str(), __FILE__, __func__, __LINE__, __VA_ARGS__); \
@ -145,7 +159,7 @@ class S3fsLog
if(S3fsLog::IsS3fsLogLevel(level)){ \ if(S3fsLog::IsS3fsLogLevel(level)){ \
if(foreground || S3fsLog::IsSetLogFile()){ \ if(foreground || S3fsLog::IsSetLogFile()){ \
S3fsLog::SeekEnd(); \ S3fsLog::SeekEnd(); \
fprintf(S3fsLog::GetOutputLogFile(), "%s%s%s:%s(%d): " fmt "%s\n", S3fsLog::GetLevelString(level), S3fsLog::GetS3fsLogNest(nest), __FILE__, __func__, __LINE__, __VA_ARGS__); \ fprintf(S3fsLog::GetOutputLogFile(), "%s %s%s%s:%s(%d): " fmt "%s\n", S3fsLog::GetCurrentTime(), S3fsLog::GetLevelString(level), S3fsLog::GetS3fsLogNest(nest), __FILE__, __func__, __LINE__, __VA_ARGS__); \
S3fsLog::Flush(); \ S3fsLog::Flush(); \
}else{ \ }else{ \
syslog(S3fsLog::GetSyslogLevel(level), "%s%s" fmt "%s", instance_name.c_str(), S3fsLog::GetS3fsLogNest(nest), __VA_ARGS__); \ syslog(S3fsLog::GetSyslogLevel(level), "%s%s" fmt "%s", instance_name.c_str(), S3fsLog::GetS3fsLogNest(nest), __VA_ARGS__); \
@ -157,7 +171,7 @@ class S3fsLog
do{ \ do{ \
if(foreground || S3fsLog::IsSetLogFile()){ \ if(foreground || S3fsLog::IsSetLogFile()){ \
S3fsLog::SeekEnd(); \ S3fsLog::SeekEnd(); \
fprintf(S3fsLog::GetOutputLogFile(), "[CURL DBG] " fmt "%s\n", __VA_ARGS__); \ fprintf(S3fsLog::GetOutputLogFile(), "%s [CURL DBG] " fmt "%s\n", S3fsLog::GetCurrentTime(), __VA_ARGS__); \
S3fsLog::Flush(); \ S3fsLog::Flush(); \
}else{ \ }else{ \
syslog(S3fsLog::GetSyslogLevel(S3fsLog::LEVEL_CRIT), "%s" fmt "%s", instance_name.c_str(), __VA_ARGS__); \ syslog(S3fsLog::GetSyslogLevel(S3fsLog::LEVEL_CRIT), "%s" fmt "%s", instance_name.c_str(), __VA_ARGS__); \
@ -181,7 +195,7 @@ class S3fsLog
do{ \ do{ \
if(foreground || S3fsLog::IsSetLogFile()){ \ if(foreground || S3fsLog::IsSetLogFile()){ \
S3fsLog::SeekEnd(); \ S3fsLog::SeekEnd(); \
fprintf(S3fsLog::GetOutputLogFile(), "%s%s%s:%s(%d): " fmt "%s\n", S3fsLog::GetLevelString(S3fsLog::LEVEL_INFO), S3fsLog::GetS3fsLogNest(0), __FILE__, __func__, __LINE__, __VA_ARGS__, ""); \ fprintf(S3fsLog::GetOutputLogFile(), "%s %s%s%s:%s(%d): " fmt "%s\n", S3fsLog::GetCurrentTime(), S3fsLog::GetLevelString(S3fsLog::LEVEL_INFO), S3fsLog::GetS3fsLogNest(0), __FILE__, __func__, __LINE__, __VA_ARGS__, ""); \
S3fsLog::Flush(); \ S3fsLog::Flush(); \
}else{ \ }else{ \
syslog(S3fsLog::GetSyslogLevel(S3fsLog::LEVEL_INFO), "%s%s" fmt "%s", instance_name.c_str(), S3fsLog::GetS3fsLogNest(0), __VA_ARGS__, ""); \ syslog(S3fsLog::GetSyslogLevel(S3fsLog::LEVEL_INFO), "%s%s" fmt "%s", instance_name.c_str(), S3fsLog::GetS3fsLogNest(0), __VA_ARGS__, ""); \