From ea8f4961c6e4f94bf82e4c4cadbab4ec08824ae4 Mon Sep 17 00:00:00 2001 From: Simon Rettberg Date: Sun, 22 Feb 2015 22:03:39 +0100 Subject: [SERVER] Overhauled logging - Added message type parameter - Log to file and stdout, no more logging in memory - Added options to server.conf to filter which messages show up where --- server.config.example/server.conf | 16 ++++ src/server/altservers.c | 32 +++---- src/server/globals.c | 32 ++++++- src/server/helper.h | 4 +- src/server/image.c | 84 ++++++++--------- src/server/integrity.c | 14 +-- src/server/locks.c | 24 ++--- src/server/locks.h | 10 +-- src/server/log.c | 183 ++++++++++++++++++++++++++++++++++++++ src/server/log.h | 55 ++++++++++++ src/server/memlog.c | 123 ------------------------- src/server/memlog.h | 39 -------- src/server/net.c | 42 ++++----- src/server/server.c | 39 ++++---- src/server/sockhelper.c | 4 +- src/server/threadpool.c | 10 +-- src/server/uplink.c | 64 ++++++------- 17 files changed, 445 insertions(+), 330 deletions(-) create mode 100644 src/server/log.c create mode 100644 src/server/log.h delete mode 100644 src/server/memlog.c delete mode 100644 src/server/memlog.h diff --git a/server.config.example/server.conf b/server.config.example/server.conf index aeae8d5..3e5aa8c 100644 --- a/server.config.example/server.conf +++ b/server.config.example/server.conf @@ -14,3 +14,19 @@ uplinkTimeout=1250 ; timeout in ms for send/recv on connections to clients (using an image on this server) clientTimeout=15000 +; Log related config +[logging] +; log file path and name +file=./dnbd3.log +; which type of messages to log to file +fileMask=ERROR WARNING MINOR INFO DEBUG1 +; which to log to console (stdout) +consoleMask=ERROR WARNING MINOR INFO +; Valid types (warning: specifying invalid types will not yield an error!) +; ERROR Fatal error, server will terminate +; WARNING Major issue, something is broken but keep running +; MINOR Minor issue, more of a hickup than serious problem +; INFO Informational message +; DEBUG1 Debug information, used for medium verbosity +; DEBUG2 Used for debug messages that would show up a lot + diff --git a/src/server/altservers.c b/src/server/altservers.c index e9bdba5..7ebe36b 100644 --- a/src/server/altservers.c +++ b/src/server/altservers.c @@ -2,7 +2,7 @@ #include "uplink.h" #include "locks.h" #include "sockhelper.h" -#include "memlog.h" +#include "log.h" #include "helper.h" #include "globals.h" #include "image.h" @@ -42,7 +42,7 @@ void altservers_init() spin_init( &altServersLock, PTHREAD_PROCESS_PRIVATE ); memset( altServers, 0, SERVER_MAX_ALTS * sizeof(dnbd3_alt_server_t) ); if ( 0 != thread_create( &altThread, NULL, &altservers_main, (void *)NULL ) ) { - memlogf( "[ERROR] Could not start altservers connector thread" ); + logadd( LOG_ERROR, "Could not start altservers connector thread" ); exit( EXIT_FAILURE ); } initDone = true; @@ -86,13 +86,13 @@ int altservers_load() else *space++ = '\0'; if ( !parse_address( line, &host ) ) { if ( space != NULL ) *--space = ' '; - memlogf( "[WARNING] Invalid entry in alt-servers file ignored: '%s'", line ); + logadd( LOG_WARNING, "Invalid entry in alt-servers file ignored: '%s'", line ); continue; } if ( altservers_add( &host, space, isPrivate, isClientOnly ) ) ++count; } fclose( fp ); - printf( "[DEBUG] Added %d alt servers\n", count ); + logadd( LOG_DEBUG1, "Added %d alt servers\n", count ); return count; } @@ -110,7 +110,7 @@ bool altservers_add(dnbd3_host_t *host, const char *comment, const int isPrivate } if ( freeSlot == -1 ) { if ( numAltServers >= SERVER_MAX_ALTS ) { - memlogf( "[WARNING] Cannot add another alt server, maximum of %d already reached.", (int)SERVER_MAX_ALTS ); + logadd( LOG_WARNING, "Cannot add another alt server, maximum of %d already reached.", (int)SERVER_MAX_ALTS ); spin_unlock( &altServersLock ); return false; } @@ -157,7 +157,7 @@ void altservers_findUplink(dnbd3_connection_t *uplink) } // End of loop - no free slot spin_unlock( &pendingLockProduce ); - memlogf( "[WARNING] No more free RTT measurement slots, ignoring a request..." ); + logadd( LOG_WARNING, "No more free RTT measurement slots, ignoring a request..." ); } /** @@ -363,7 +363,7 @@ static void *altservers_main(void *data UNUSED) // Init signal-pipe signalFd = signal_new(); if ( signalFd < 0 ) { - memlogf( "[WARNING] error creating signal object. Uplink feature unavailable." ); + logadd( LOG_WARNING, "error creating signal object. Uplink feature unavailable." ); goto cleanup; } // LOOP @@ -373,7 +373,7 @@ static void *altservers_main(void *data UNUSED) if ( _shutdown ) goto cleanup; if ( ret == SIGNAL_ERROR ) { if ( errno == EAGAIN || errno == EINTR ) continue; - memlogf( "[WARNING] Error on signal_clear on alservers_main! Things will break!" ); + logadd( LOG_WARNING, "Error on signal_clear on alservers_main! Things will break!" ); usleep( 100000 ); } // Work your way through the queue @@ -390,7 +390,7 @@ static void *altservers_main(void *data UNUSED) uplink->rttTestResult = RTT_NOT_REACHABLE; pending[itLink] = NULL; pthread_mutex_unlock( &pendingLockConsume ); - printf( "[DEBUG] Image has gone away that was queued for RTT measurement\n" ); + logadd( LOG_DEBUG1, "Image has gone away that was queued for RTT measurement\n" ); continue; } assert( uplink->rttTestResult == RTT_INPROGRESS ); @@ -430,35 +430,35 @@ static void *altservers_main(void *data UNUSED) } if ( protocolVersion < MIN_SUPPORTED_SERVER ) goto server_failed; if ( name == NULL || strcmp( name, image->lower_name ) != 0 ) { - ERROR_GOTO_VA( server_failed, "[ERROR] Server offers image '%s', requested '%s'", name, image->lower_name ); + ERROR_GOTO( server_failed, "[ERROR] Server offers image '%s', requested '%s'", name, image->lower_name ); } if ( rid != image->rid ) { - ERROR_GOTO_VA( server_failed, "[ERROR] Server provides rid %d, requested was %d (%s)", + ERROR_GOTO( server_failed, "[ERROR] Server provides rid %d, requested was %d (%s)", (int)rid, (int)image->rid, image->lower_name ); } if ( imageSize != image->filesize ) { - ERROR_GOTO_VA( server_failed, "[ERROR] Remote size: %" PRIu64 ", expected: %" PRIu64 " (%s)", + ERROR_GOTO( server_failed, "[ERROR] Remote size: %" PRIu64 ", expected: %" PRIu64 " (%s)", imageSize, image->filesize, image->lower_name ); } // Request first block (NOT random!) ++++++++++++++++++++++++++++++ fixup_request( request ); if ( !dnbd3_get_block( sock, 0, DNBD3_BLOCK_SIZE, 0 ) ) { - ERROR_GOTO_VA( server_failed, "[ERROR] Could not request random block for %s", image->lower_name ); + ERROR_GOTO( server_failed, "[ERROR] Could not request random block for %s", image->lower_name ); } // See if requesting the block succeeded ++++++++++++++++++++++ if ( !dnbd3_get_reply( sock, &reply ) ) { char buf[100] = { 0 }; host_to_string( &servers[itAlt], buf, 100 ); - ERROR_GOTO_VA( server_failed, "[ERROR] Received corrupted reply header (%s) after CMD_GET_BLOCK (%s)", + ERROR_GOTO( server_failed, "[ERROR] Received corrupted reply header (%s) after CMD_GET_BLOCK (%s)", buf, image->lower_name ); } // check reply header if ( reply.cmd != CMD_GET_BLOCK || reply.size != DNBD3_BLOCK_SIZE ) { - ERROR_GOTO_VA( server_failed, "[ERROR] Reply to random block request is %d bytes for %s", + ERROR_GOTO( server_failed, "[ERROR] Reply to random block request is %d bytes for %s", reply.size, image->lower_name ); } if ( recv( sock, buffer, DNBD3_BLOCK_SIZE, MSG_WAITALL ) != DNBD3_BLOCK_SIZE ) { - ERROR_GOTO_VA( server_failed, "[ERROR] Could not read random block payload for %s", image->lower_name ); + ERROR_GOTO( server_failed, "[ERROR] Could not read random block payload for %s", image->lower_name ); } clock_gettime( CLOCK_MONOTONIC_RAW, &end ); // Measurement done - everything fine so far diff --git a/src/server/globals.c b/src/server/globals.c index 441b2d1..a0d6ea9 100644 --- a/src/server/globals.c +++ b/src/server/globals.c @@ -1,6 +1,6 @@ #include "globals.h" #include "ini.h" -#include "memlog.h" +#include "log.h" #include "../types.h" #include #include @@ -22,6 +22,8 @@ int _clientTimeout = 15000; #define SAVE_TO_VAR_BOOL(ss, kk) do { if (strcmp(section, #ss) == 0 && strcmp(key, #kk) == 0) _ ## kk = atoi(value) != 0 || strcmp(value, "true") == 0 || strcmp(value, "True") == 0 || strcmp(value, "TRUE") == 0; } while (0) #define SAVE_TO_VAR_INT(ss, kk) do { if (strcmp(section, #ss) == 0 && strcmp(key, #kk) == 0) _ ## kk = atoi(value); } while (0) +static void handleMaskString( const char *value, void(*func)(logmask_t) ); + static int ini_handler(void *custom UNUSED, const char* section, const char* key, const char* value) { if ( _basePath == NULL ) SAVE_TO_VAR_STR( dnbd3, basePath ); @@ -33,6 +35,16 @@ static int ini_handler(void *custom UNUSED, const char* section, const char* key SAVE_TO_VAR_INT( dnbd3, clientPenalty ); SAVE_TO_VAR_INT( dnbd3, uplinkTimeout ); SAVE_TO_VAR_INT( dnbd3, clientTimeout ); + if ( strcmp( section, "logging" ) == 0 && strcmp( key, "fileMask" ) == 0 ) handleMaskString( value, &log_setFileMask ); + if ( strcmp( section, "logging" ) == 0 && strcmp( key, "consoleMask" ) == 0 ) handleMaskString( value, &log_setConsoleMask ); + if ( strcmp( section, "logging" ) == 0 && strcmp( key, "file" ) == 0 ) { + if ( log_openLogFile( value ) ) { + logadd( LOG_INFO, "Opened log file %s", value ); + } else { + logadd( LOG_ERROR, "Could not open log file %s", value ); + exit( EXIT_FAILURE ); + } + } return 1; } @@ -44,11 +56,11 @@ void globals_loadConfig() ini_parse( name, &ini_handler, NULL ); free( name ); if ( _basePath == NULL || _basePath[0] == '\0' ) { - memlogf( "[ERROR] Need to specify basePath in " CONFIG_FILENAME ); + logadd( LOG_ERROR, "Need to specify basePath in " CONFIG_FILENAME ); exit( EXIT_FAILURE ); } if ( _basePath[0] != '/' ) { - memlogf( "[ERROR] _basePath must be absolute!" ); + logadd( LOG_ERROR, "_basePath must be absolute!" ); exit( EXIT_FAILURE ); } char *end = _basePath + strlen( _basePath ) - 1; @@ -57,3 +69,17 @@ void globals_loadConfig() if ( _serverPenalty < 0 ) _serverPenalty = 0; if ( _clientPenalty < 0 ) _clientPenalty = 0; } + +#define SETLOGBIT(name) do { if ( strstr( value, #name ) != NULL ) mask |= LOG_ ## name; } while (0) +static void handleMaskString( const char *value, void(*func)(logmask_t) ) +{ + logmask_t mask = 0; + SETLOGBIT( ERROR ); + SETLOGBIT( WARNING ); + SETLOGBIT( MINOR ); + SETLOGBIT( INFO ); + SETLOGBIT( DEBUG1 ); + SETLOGBIT( DEBUG2 ); + (*func)( mask ); +} + diff --git a/src/server/helper.h b/src/server/helper.h index 7c962d7..e108d81 100644 --- a/src/server/helper.h +++ b/src/server/helper.h @@ -2,14 +2,14 @@ #define HELPER_H_ #include "server.h" +#include "log.h" #include #include #include #include #include "../types.h" -#define ERROR_GOTO(jumplabel, errormsg) do { memlogf(errormsg); goto jumplabel; } while (0); -#define ERROR_GOTO_VA(jumplabel, errormsg, ...) do { memlogf(errormsg, __VA_ARGS__); goto jumplabel; } while (0); +#define ERROR_GOTO(jumplabel, ...) do { logadd(LOG_ERROR, __VA_ARGS__); goto jumplabel; } while (0); bool parse_address(char *string, dnbd3_host_t *host); bool host_to_string(const dnbd3_host_t *host, char *target, size_t targetlen); diff --git a/src/server/image.c b/src/server/image.c index ccee548..bf8c3a6 100644 --- a/src/server/image.c +++ b/src/server/image.c @@ -1,7 +1,7 @@ #include "image.h" #include "helper.h" #include "fileutil.h" -#include "memlog.h" +#include "log.h" #include "uplink.h" #include "locks.h" #include "integrity.h" @@ -112,7 +112,7 @@ void image_updateCachemap(dnbd3_image_t *image, uint64_t start, uint64_t end, co if ( image->cache_map == NULL ) { // Image seems already complete spin_unlock( &image->lock ); - printf( "[DEBUG] image_updateCachemap with no cache_map: %s", image->path ); + logadd( LOG_DEBUG1, "image_updateCachemap with no cache_map: %s", image->path ); return; } while ( pos < end ) { @@ -465,7 +465,7 @@ static bool image_load_all_internal(char *base, char *path) struct dirent *entry; DIR *dir = opendir( path ); if ( dir == NULL ) { - memlogf( "[ERROR] Could not opendir '%s' for loading", path ); + logadd( LOG_ERROR, "Could not opendir '%s' for loading", path ); return false; } const int pathLen = strlen( path ); @@ -475,7 +475,7 @@ static bool image_load_all_internal(char *base, char *path) while ( (entry = readdir( dir )) != NULL ) { if ( strcmp( entry->d_name, "." ) == 0 || strcmp( entry->d_name, ".." ) == 0 ) continue; if ( strlen( entry->d_name ) > SUBDIR_LEN ) { - memlogf( "[WARNING] Skipping entry %s: Too long (max %d bytes)", entry->d_name, (int)SUBDIR_LEN ); + logadd( LOG_WARNING, "Skipping entry %s: Too long (max %d bytes)", entry->d_name, (int)SUBDIR_LEN ); continue; } if ( entry->d_name[0] == '/' || path[pathLen - 1] == '/' ) { @@ -484,7 +484,7 @@ static bool image_load_all_internal(char *base, char *path) snprintf( subpath, len, "%s/%s", path, entry->d_name ); } if ( stat( subpath, &st ) < 0 ) { - memlogf( "[WARNING] stat() for '%s' failed. Ignoring....", subpath ); + logadd( LOG_WARNING, "stat() for '%s' failed. Ignoring....", subpath ); continue; } if ( S_ISDIR( st.st_mode )) { @@ -548,7 +548,7 @@ static bool image_load(char *base, char *path, int withUplink) *dst = '\0'; } if ( revision <= 0 ) { - memlogf( "[WARNING] Image '%s' has invalid revision ID %d", path, revision ); + logadd( LOG_WARNING, "Image '%s' has invalid revision ID %d", path, revision ); goto load_error; } @@ -560,22 +560,22 @@ static bool image_load(char *base, char *path, int withUplink) // ### Now load the actual image related data ### fdImage = open( path, O_RDONLY ); if ( fdImage < 0 ) { - memlogf( "[ERROR] Could not open '%s' for reading...", path ); + logadd( LOG_ERROR, "Could not open '%s' for reading...", path ); goto load_error; } // Determine file size const off_t seekret = lseek( fdImage, 0, SEEK_END ); if ( seekret < 0 ) { - memlogf( "[ERROR] Could not seek to end of file '%s'", path ); + logadd( LOG_ERROR, "Could not seek to end of file '%s'", path ); goto load_error; } else if ( seekret == 0 ) { - memlogf( "[WARNING] Empty image file '%s'", path ); + logadd( LOG_WARNING, "Empty image file '%s'", path ); goto load_error; } uint64_t fileSize = (uint64_t)seekret; // Filesize must be multiple of 4096 if ( fileSize % DNBD3_BLOCK_SIZE != 0 ) { - memlogf( "[INFO] Image size of '%s' is not a multiple of %d, fixing...", path, (int)DNBD3_BLOCK_SIZE ); + logadd( LOG_INFO, "Image size of '%s' is not a multiple of %d, fixing...", path, (int)DNBD3_BLOCK_SIZE ); fileSize = image_pad( path, fileSize ); if ( fileSize == 0 ) goto load_error; } @@ -593,7 +593,7 @@ static bool image_load(char *base, char *path, int withUplink) // Check CRC32 if ( crc32list != NULL ) { if ( !image_checkRandomBlocks( 4, fdImage, fileSize, crc32list, cache_map ) ) { - memlogf( "[ERROR] quick crc32 check of %s failed. Data corruption?", path ); + logadd( LOG_ERROR, "quick crc32 check of %s failed. Data corruption?", path ); goto load_error; } } @@ -602,15 +602,15 @@ static bool image_load(char *base, char *path, int withUplink) if ( existing != NULL ) { if ( existing->filesize != fileSize ) { // Image will be replaced below - memlogf( "[WARNING] Size of image '%s:%d' has changed.", existing->lower_name, (int)existing->rid ); + logadd( LOG_WARNING, "Size of image '%s:%d' has changed.", existing->lower_name, (int)existing->rid ); } else if ( existing->crc32 != NULL && crc32list != NULL && memcmp( existing->crc32, crc32list, sizeof(uint32_t) * hashBlockCount ) != 0 ) { // Image will be replaced below - memlogf( "[WARNING] CRC32 list of image '%s:%d' has changed.", existing->lower_name, (int)existing->rid ); - memlogf( "[WARNING] The image will be reloaded, but you should NOT replace existing images while the server is running." ); - memlogf( "[WARNING] Actually even if it's not running this should never be done. Use a new RID instead!" ); + logadd( LOG_WARNING, "CRC32 list of image '%s:%d' has changed.", existing->lower_name, (int)existing->rid ); + logadd( LOG_WARNING, "The image will be reloaded, but you should NOT replace existing images while the server is running." ); + logadd( LOG_WARNING, "Actually even if it's not running this should never be done. Use a new RID instead!" ); } else if ( existing->crc32 == NULL && crc32list != NULL ) { - memlogf( "[INFO] Found CRC-32 list for already loaded image '%s:%d', adding...", existing->lower_name, (int)existing->rid ); + logadd( LOG_INFO, "Found CRC-32 list for already loaded image '%s:%d', adding...", existing->lower_name, (int)existing->rid ); existing->crc32 = crc32list; existing->masterCrc32 = masterCrc; crc32list = NULL; @@ -618,7 +618,7 @@ static bool image_load(char *base, char *path, int withUplink) goto load_error; } else if ( existing->cache_map != NULL && cache_map == NULL ) { // Just ignore that fact, if replication is really complete the cache map will be removed anyways - memlogf( "[INFO] Image '%s:%d' has no cache map on disk!", existing->lower_name, (int)existing->rid ); + logadd( LOG_INFO, "Image '%s:%d' has no cache map on disk!", existing->lower_name, (int)existing->rid ); function_return = true; goto load_error; } else { @@ -670,7 +670,7 @@ static bool image_load(char *base, char *path, int withUplink) if ( image->cacheFd < 0 ) { // Proxy mode without disk caching is pointless, bail out image->cacheFd = -1; - memlogf( "[ERROR] Could not open incomplete image %s for writing!", path ); + logadd( LOG_ERROR, "Could not open incomplete image %s for writing!", path ); image = image_free( image ); goto load_error; } @@ -689,13 +689,13 @@ static bool image_load(char *base, char *path, int withUplink) } if ( i >= _num_images ) { if ( _num_images >= SERVER_MAX_IMAGES ) { - memlogf( "[ERROR] Cannot load image '%s': maximum number of images reached.", path ); + logadd( LOG_ERROR, "Cannot load image '%s': maximum number of images reached.", path ); spin_unlock( &_images_lock ); image = image_free( image ); goto load_error; } _images[_num_images++] = image; - printf( "[DEBUG] Loaded image '%s'\n", image->lower_name ); + logadd( LOG_DEBUG1, "Loaded image '%s'\n", image->lower_name ); } // Keep fd for reading image->readFd = fdImage; @@ -724,7 +724,7 @@ static uint8_t* image_loadCacheMap(const char * const imagePath, const int64_t f retval = calloc( 1, map_size ); const ssize_t rd = read( fdMap, retval, map_size ); if ( map_size != rd ) { - memlogf( "[WARNING] Could only read %d of expected %d bytes of cache map of '%s'", (int)rd, (int)map_size, fileSize ); + logadd( LOG_WARNING, "Could only read %d of expected %d bytes of cache map of '%s'", (int)rd, (int)map_size, fileSize ); // Could not read complete map, that means the rest of the image file will be considered incomplete } close( fdMap ); @@ -746,26 +746,26 @@ static uint32_t* image_loadCrcList(const char * const imagePath, const int64_t f if ( fdHash >= 0 ) { off_t fs = lseek( fdHash, 0, SEEK_END ); if ( fs < (hashBlocks + 1) * 4 ) { - memlogf( "[WARNING] Ignoring crc32 list for '%s' as it is too short", imagePath ); + logadd( LOG_WARNING, "Ignoring crc32 list for '%s' as it is too short", imagePath ); } else { if ( 0 != lseek( fdHash, 0, SEEK_SET ) ) { - memlogf( "[WARNING] Could not seek back to beginning of '%s'", hashFile ); + logadd( LOG_WARNING, "Could not seek back to beginning of '%s'", hashFile ); } else { if ( read( fdHash, masterCrc, sizeof(uint32_t) ) != 4 ) { - memlogf( "[WARNING] Error reading first crc32 of '%s'", imagePath ); + logadd( LOG_WARNING, "Error reading first crc32 of '%s'", imagePath ); } else { retval = calloc( hashBlocks, sizeof(uint32_t) ); if ( read( fdHash, retval, hashBlocks * sizeof(uint32_t) ) != hashBlocks * (ssize_t)sizeof(uint32_t) ) { free( retval ); retval = NULL; - memlogf( "[WARNING] Could not read crc32 list of '%s'", imagePath ); + logadd( LOG_WARNING, "Could not read crc32 list of '%s'", imagePath ); } else { uint32_t lists_crc = crc32( 0L, Z_NULL, 0 ); lists_crc = crc32( lists_crc, (Bytef*)retval, hashBlocks * sizeof(uint32_t) ); if ( lists_crc != *masterCrc ) { free( retval ); retval = NULL; - memlogf( "[WARNING] CRC-32 of CRC-32 list mismatch. CRC-32 list of '%s' might be corrupted.", imagePath ); + logadd( LOG_WARNING, "CRC-32 of CRC-32 list mismatch. CRC-32 list of '%s' might be corrupted.", imagePath ); } } } @@ -811,7 +811,7 @@ bool image_create(char *image, int revision, uint64_t size) assert( image != NULL ); assert( size >= DNBD3_BLOCK_SIZE ); if ( revision <= 0 ) { - memlogf( "[ERROR] revision id invalid: %d", revision ); + logadd( LOG_ERROR, "revision id invalid: %d", revision ); return false; } const int PATHLEN = 2000; @@ -827,7 +827,7 @@ bool image_create(char *image, int revision, uint64_t size) snprintf( path, PATHLEN, "%s/%s.r%d", _basePath, image, revision ); } if ( file_isReadable( path ) ) { - memlogf( "[ERROR] Image %s with rid %d already exists!", image, revision ); + logadd( LOG_ERROR, "Image %s with rid %d already exists!", image, revision ); return false; } snprintf( cache, PATHLEN, "%s.map", path ); @@ -838,23 +838,23 @@ bool image_create(char *image, int revision, uint64_t size) fdImage = open( path, O_RDWR | O_TRUNC | O_CREAT, 0644 ); fdCache = open( cache, O_RDWR | O_TRUNC | O_CREAT, 0644 ); if ( fdImage < 0 ) { - memlogf( "[ERROR] Could not open %s for writing.", path ); + logadd( LOG_ERROR, "Could not open %s for writing.", path ); goto failure_cleanup; } if ( fdCache < 0 ) { - memlogf( "[ERROR] Could not open %s for writing.", cache ); + logadd( LOG_ERROR, "Could not open %s for writing.", cache ); goto failure_cleanup; } // Try cache map first if ( !file_alloc( fdCache, 0, mapsize ) ) { const int err = errno; - memlogf( "[ERROR] Could not allocate %d bytes for %s (errno=%d)", mapsize, cache, err ); + logadd( LOG_ERROR, "Could not allocate %d bytes for %s (errno=%d)", mapsize, cache, err ); goto failure_cleanup; } // Now write image if ( !file_alloc( fdImage, 0, size ) ) { const int err = errno; - memlogf( "[ERROR] Could not allocate %" PRIu64 " bytes for %s (errno=%d)", size, path, err ); + logadd( LOG_ERROR, "Could not allocate %" PRIu64 " bytes for %s (errno=%d)", size, path, err ); goto failure_cleanup; } close( fdImage ); @@ -985,7 +985,7 @@ static bool image_clone(int sock, char *name, uint16_t revision, uint64_t imageS uint32_t lists_crc = crc32( 0L, Z_NULL, 0 ); lists_crc = crc32( lists_crc, (Bytef*)crc32list, crc32len ); if ( lists_crc != masterCrc ) { - memlogf( "[WARNING] OTF-Clone: Corrupted CRC-32 list. ignored. (%s)", name ); + logadd( LOG_WARNING, "OTF-Clone: Corrupted CRC-32 list. ignored. (%s)", name ); } else { int fd = open( crcFile, O_WRONLY | O_CREAT, 0644 ); write( fd, &lists_crc, sizeof(uint32_t) ); @@ -1199,7 +1199,7 @@ bool image_checkBlocksCrc32(int fd, uint32_t *crc32list, const int *blocks, cons const int n = MIN( (int)sizeof(buffer), bytesToGo - bytes ); const int r = pread( fd, buffer, n, readPos ); if ( r <= 0 ) { - memlogf( "[WARNING] CRC-Check: Read error (errno=%d)", errno ); + logadd( LOG_WARNING, "CRC-Check: Read error (errno=%d)", errno ); return false; } crc = crc32( crc, (Bytef*)buffer, r ); @@ -1223,11 +1223,11 @@ static int64_t image_pad(const char *path, const int64_t currentSize) int tmpFd = open( path, O_WRONLY | O_APPEND ); bool success = false; if ( tmpFd < 0 ) { - memlogf( "[WARNING] Can't open image for writing, can't fix %s", path ); + logadd( LOG_WARNING, "Can't open image for writing, can't fix %s", path ); } else if ( lseek( tmpFd, currentSize, SEEK_SET ) != currentSize ) { - memlogf( "[WARNING] lseek() failed, can't fix %s", path ); + logadd( LOG_WARNING, "lseek() failed, can't fix %s", path ); } else if ( write( tmpFd, buffer, missing ) != missing ) { - memlogf( "[WARNING] write() failed, can't fix %s", path ); + logadd( LOG_WARNING, "write() failed, can't fix %s", path ); } else { success = true; } @@ -1253,16 +1253,16 @@ static bool image_ensureDiskSpace(uint64_t size) const int64_t available = file_freeDiskSpace( _basePath ); if ( available == -1 ) { const int e = errno; - memlogf( "[WARNING] Could not get free disk space (errno %d), will assume there is enough space left... ;-)\n", e ); + logadd( LOG_WARNING, "Could not get free disk space (errno %d), will assume there is enough space left... ;-)\n", e ); return true; } if ( (uint64_t)available > size ) return true; if ( dnbd3_serverUptime() < 10 * 3600 ) { - memlogf( "[INFO] Only %dMiB free, %dMiB requested, but server uptime < 10 hours...", (int)(available / (1024ll * 1024ll)), + logadd( LOG_INFO, "Only %dMiB free, %dMiB requested, but server uptime < 10 hours...", (int)(available / (1024ll * 1024ll)), (int)(size / (1024 * 1024)) ); return false; } - memlogf( "[INFO] Only %dMiB free, %dMiB requested, freeing an image...", (int)(available / (1024ll * 1024ll)), + logadd( LOG_INFO, "Only %dMiB free, %dMiB requested, freeing an image...", (int)(available / (1024ll * 1024ll)), (int)(size / (1024 * 1024)) ); // Find least recently used image dnbd3_image_t *oldest = NULL; @@ -1280,12 +1280,12 @@ static bool image_ensureDiskSpace(uint64_t size) image_release( current ); } if ( oldest == NULL || time( NULL ) - oldest->atime < 86400 ) { - printf( "[DEBUG] No image is old enough :-(\n" ); + logadd( LOG_DEBUG1, "No image is old enough :-(\n" ); return false; } oldest = image_lock( oldest ); if ( oldest == NULL ) return false; - memlogf( "[INFO] '%s:%d' has to go!", oldest->lower_name, (int)oldest->rid ); + logadd( LOG_INFO, "'%s:%d' has to go!", oldest->lower_name, (int)oldest->rid ); unlink( oldest->path ); size_t len = strlen( oldest->path ) + 5 + 1; char buffer[len]; diff --git a/src/server/integrity.c b/src/server/integrity.c index 352b1a5..f32fd9c 100644 --- a/src/server/integrity.c +++ b/src/server/integrity.c @@ -3,7 +3,7 @@ #include "locks.h" #include "image.h" #include "globals.h" -#include "memlog.h" +#include "log.h" #include "helper.h" #include @@ -44,7 +44,7 @@ void integrity_init() bRunning = true; if ( 0 != thread_create( &thread, NULL, &integrity_main, (void *)NULL ) ) { bRunning = false; - memlogf( "[WARNING] Could not start integrity check thread. Corrupted images will not be detected." ); + logadd( LOG_WARNING, "Could not start integrity check thread. Corrupted images will not be detected." ); return; } queueLen = 0; @@ -53,7 +53,7 @@ void integrity_init() void integrity_shutdown() { assert( queueLen != -1 ); - printf( "[DEBUG] Shutting down integrity checker...\n" ); + logadd( LOG_DEBUG1, "Shutting down integrity checker...\n" ); pthread_mutex_lock( &integrityQueueLock ); pthread_cond_signal( &queueSignal ); pthread_mutex_unlock( &integrityQueueLock ); @@ -62,7 +62,7 @@ void integrity_shutdown() usleep( 10000 ); pthread_mutex_destroy( &integrityQueueLock ); pthread_cond_destroy( &queueSignal ); - printf( "[DEBUG] Integrity checker exited normally.\n" ); + logadd( LOG_DEBUG1, "Integrity checker exited normally.\n" ); } /** @@ -86,7 +86,7 @@ void integrity_check(dnbd3_image_t *image, int block) if ( freeSlot == -1 ) { if ( queueLen >= CHECK_QUEUE_SIZE ) { pthread_mutex_unlock( &integrityQueueLock ); - printf( "[DEBUG] Check queue full, discarding check request...\n" ); + logadd( LOG_DEBUG1, "Check queue full, discarding check request...\n" ); return; } freeSlot = queueLen++; @@ -137,9 +137,9 @@ static void* integrity_main(void * data UNUSED) memcpy( buffer, image->crc32, required ); spin_unlock( &image->lock ); if ( image_checkBlocksCrc32( image->readFd, (uint32_t*)buffer, blocks, fileSize ) ) { - //printf( "[DEBUG] CRC check of block %d for %s succeeded :-)\n", blocks[0], image->lower_name ); + //logadd( LOG_DEBUG] CRC check of block %d for %s succeeded :-)\n", blocks[0, ", image->lower_name ); } else { - memlogf( "[WARNING] Hash check for block %d of %s failed!", blocks[0], image->lower_name ); + logadd( LOG_WARNING, "Hash check for block %d of %s failed!", blocks[0], image->lower_name ); image_updateCachemap( image, blocks[0] * HASH_BLOCK_SIZE, (blocks[0] + 1) * HASH_BLOCK_SIZE, false ); } pthread_mutex_lock( &integrityQueueLock ); diff --git a/src/server/locks.c b/src/server/locks.c index de37734..6c411e5 100644 --- a/src/server/locks.c +++ b/src/server/locks.c @@ -15,7 +15,7 @@ #include #include #include "globals.h" -#include "memlog.h" +#include "log.h" #include "helper.h" #include "signal.h" @@ -66,13 +66,13 @@ int debug_spin_init(const char *name, const char *file, int line, pthread_spinlo pthread_spin_lock( &initdestory ); for (int i = 0; i < MAXLOCKS; ++i) { if ( locks[i].lock == lock ) { - printf( "[ERROR] Lock %p (%s) already initialized (%s:%d)\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Lock %p (%s) already initialized (%s:%d)\n", (void*)lock, name, file, line ); exit( 4 ); } if ( first == -1 && locks[i].lock == NULL ) first = i; } if ( first == -1 ) { - printf( "[ERROR] No more free debug locks (%s:%d)\n", file, line ); + logadd( LOG_ERROR, "No more free debug locks (%s:%d)\n", file, line ); pthread_spin_unlock( &initdestory ); debug_dump_lock_stats(); exit( 4 ); @@ -97,7 +97,7 @@ int debug_spin_lock(const char *name, const char *file, int line, pthread_spinlo } pthread_spin_unlock( &initdestory ); if ( l == NULL ) { - printf( "[ERROR] Tried to lock uninitialized lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Tried to lock uninitialized lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); debug_dump_lock_stats(); exit( 4 ); } @@ -119,7 +119,7 @@ int debug_spin_lock(const char *name, const char *file, int line, pthread_spinlo t->time = 0; pthread_spin_unlock( &initdestory ); if ( l->locked ) { - printf( "[ERROR] Lock sanity check: lock %p (%s) already locked at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Lock sanity check: lock %p (%s) already locked at %s:%d\n", (void*)lock, name, file, line ); exit( 4 ); } l->locked = 1; @@ -144,7 +144,7 @@ int debug_spin_trylock(const char *name, const char *file, int line, pthread_spi } pthread_spin_unlock( &initdestory ); if ( l == NULL ) { - printf( "[ERROR] Tried to lock uninitialized lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Tried to lock uninitialized lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); debug_dump_lock_stats(); exit( 4 ); } @@ -167,7 +167,7 @@ int debug_spin_trylock(const char *name, const char *file, int line, pthread_spi pthread_spin_unlock( &initdestory ); if ( retval == 0 ) { if ( l->locked ) { - printf( "[ERROR] Lock sanity check: lock %p (%s) already locked at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Lock sanity check: lock %p (%s) already locked at %s:%d\n", (void*)lock, name, file, line ); exit( 4 ); } l->locked = 1; @@ -193,11 +193,11 @@ int debug_spin_unlock(const char *name, const char *file, int line, pthread_spin } pthread_spin_unlock( &initdestory ); if ( l == NULL ) { - printf( "[ERROR] Tried to unlock uninitialized lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Tried to unlock uninitialized lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); exit( 4 ); } if ( !l->locked ) { - printf( "[ERROR] Unlock sanity check: lock %p (%s) not locked at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Unlock sanity check: lock %p (%s) not locked at %s:%d\n", (void*)lock, name, file, line ); exit( 4 ); } l->locked = 0; @@ -214,7 +214,7 @@ int debug_spin_destroy(const char *name, const char *file, int line, pthread_spi for (int i = 0; i < MAXLOCKS; ++i) { if ( locks[i].lock == lock ) { if ( locks[i].locked ) { - printf( "[ERROR] Tried to destroy lock %p (%s) at %s:%d when it is still locked\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Tried to destroy lock %p (%s) at %s:%d when it is still locked\n", (void*)lock, name, file, line ); exit( 4 ); } locks[i].lock = NULL; @@ -223,7 +223,7 @@ int debug_spin_destroy(const char *name, const char *file, int line, pthread_spi return pthread_spin_destroy( lock ); } } - printf( "[ERROR] Tried to destroy non-existent lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); + logadd( LOG_ERROR, "Tried to destroy non-existent lock %p (%s) at %s:%d\n", (void*)lock, name, file, line ); exit( 4 ); } @@ -290,7 +290,7 @@ void debug_locks_start_watchdog() #ifdef _DEBUG watchdogSignal = signal_new(); if ( 0 != thread_create( &watchdog, NULL, &debug_thread_watchdog, (void *)NULL ) ) { - memlogf( "[ERROR] Could not start debug-lock watchdog." ); + logadd( LOG_ERROR, "Could not start debug-lock watchdog." ); return; } #endif diff --git a/src/server/locks.h b/src/server/locks.h index efd0a37..27af006 100644 --- a/src/server/locks.h +++ b/src/server/locks.h @@ -37,7 +37,7 @@ void debug_dump_lock_stats(); #ifdef DEBUG_THREADS extern int debugThreadCount; -#define thread_create(thread,attr,routine,arg) (printf("[THREAD CREATE] %d @ %s:%d\n", debugThreadCount, __FILE__, (int)__LINE__), debug_thread_create(thread, attr, routine, arg)) +#define thread_create(thread,attr,routine,arg) (logadd( LOG_THREAD CREATE, "%d @ %s:%d\n", debugThreadCount, __FILE__, (int)__LINE__), debug_thread_create(thread, attr, routine, arg)) static inline pthread_t debug_thread_create(pthread_t *thread, const pthread_attr_t *attr, void *(*start_routine)(void*), void *arg) { int i; @@ -47,26 +47,26 @@ static inline pthread_t debug_thread_create(pthread_t *thread, const pthread_att return pthread_create( thread, attr, start_routine, arg ); } -#define thread_detach(thread) (printf("[THREAD DETACH] %d @ %s:%d\n", debugThreadCount, __FILE__, __LINE__), debug_thread_detach(thread)) +#define thread_detach(thread) (logadd( LOG_THREAD DETACH, "%d @ %s:%d\n", debugThreadCount, __FILE__, __LINE__), debug_thread_detach(thread)) static inline int debug_thread_detach(pthread_t thread) { const int ret = pthread_detach(thread); if (ret == 0) { --debugThreadCount; } else { - printf("[THREAD DETACH] Tried to detach invalid thread (error %d)\n", (int)errno); + logadd( LOG_THREAD DETACH, "Tried to detach invalid thread (error %d)\n", (int)errno); exit(1); } return ret; } -#define thread_join(thread,value) (printf("[THREAD JOIN] %d @ %s:%d\n", debugThreadCount, __FILE__, __LINE__), debug_thread_join(thread,value)) +#define thread_join(thread,value) (logadd( LOG_THREAD JOIN, "%d @ %s:%d\n", debugThreadCount, __FILE__, __LINE__), debug_thread_join(thread,value)) static inline int debug_thread_join(pthread_t thread, void **value_ptr) { const int ret = pthread_join(thread, value_ptr); if (ret == 0) { --debugThreadCount; } else { - printf("[THREAD JOIN] Tried to join invalid thread (error %d)\n", (int)errno); + logadd( LOG_THREAD JOIN, "Tried to join invalid thread (error %d)\n", (int)errno); exit(1); } return ret; diff --git a/src/server/log.c b/src/server/log.c new file mode 100644 index 0000000..6d77dc5 --- /dev/null +++ b/src/server/log.c @@ -0,0 +1,183 @@ +/* + * This file is part of the Distributed Network Block Device 3 + * + * Copyright(c) 2011-2012 Simon Rettberg + * + * This file may be licensed under the terms of of the + * GNU General Public License Version 2 (the ``GPL''). + * + * Software distributed under the License is distributed + * on an ``AS IS'' basis, WITHOUT WARRANTY OF ANY KIND, either + * express or implied. See the GPL for the specific language + * governing rights and limitations. + * + * You should have received a copy of the GPL along with this + * program. If not, go to http://www.gnu.org/licenses/gpl.html + * or write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. + * + */ + +#include "log.h" +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#define LINE_LEN (800) + +static pthread_mutex_t logLock = PTHREAD_MUTEX_INITIALIZER; +static logmask_t maskFile = 31; +static logmask_t maskCon = 15; + +static char *logFile = NULL; +static int logFd = -1; + + +static int writeLevel(char *buffer, logmask_t level); + + +void log_setFileMask(logmask_t mask) +{ + maskFile = mask; +} + +void log_setConsoleMask(logmask_t mask) +{ + maskCon = mask; +} + +bool log_openLogFile(const char *path) +{ + pthread_mutex_lock( &logLock ); + if ( logFd >= 0 ) { + close( logFd ); + } + if ( path == NULL && logFile == NULL ) + goto unlock; + if ( path != NULL ) { + free( logFile ); + logFile = strdup( path ); + } + logFd = open( logFile, O_WRONLY | O_CREAT | O_APPEND, 0644 ); + if ( logFd < 0 ) + goto unlock; +unlock: ; + pthread_mutex_unlock( &logLock ); + return logFd >= 0; +} + +void logadd(const logmask_t mask, const char *fmt, ...) +{ + if ( ( (maskFile | maskCon) & mask ) == 0 ) + return; + va_list ap; + int ret; + time_t rawtime; + struct tm *timeinfo; + char buffer[LINE_LEN]; + + time( &rawtime ); + timeinfo = localtime( &rawtime ); + size_t offset = strftime( buffer, LINE_LEN, "[%d.%m. %H:%M:%S] ", timeinfo ); + offset += writeLevel( buffer + offset, mask ); + va_start( ap, fmt ); + ret = vsnprintf( buffer + offset, LINE_LEN - offset, fmt, ap ); + va_end( ap ); + if ( ret < 0 ) return; + ret += offset; + if ( ret + 1 >= LINE_LEN ) { + buffer[LINE_LEN-2] = '\0'; + ret = LINE_LEN - 2; + } + if ( ret > 0 && buffer[ret-1] != '\n' ) { + buffer[ret++] = '\n'; + buffer[ret] = '\0'; + } + if ( maskFile & mask ) { + pthread_mutex_lock( &logLock ); + if ( logFd >= 0 ) { + int done = 0; + while (done < ret ) { + const int wr = write( logFd, buffer + done, ret - done ); + if ( wr < 0 ) { + printf( "Logging to file failed! (errno=%d)\n", errno ); + break; + } + done += wr; + } + } + pthread_mutex_unlock( &logLock ); + } + if ( maskCon & mask ) { + fputs( buffer, stdout ); + fflush( stdout ); + } +} + +bool log_fetch(char *buffer, int size) +{ + if ( logFile == NULL || size <= 1 ) + return false; + int fd = open( logFile, O_RDONLY ); + if ( fd < 0 ) + return false; + off_t off = lseek( fd, 0, SEEK_END ); + if ( off == (off_t)-1 ) { + close( fd ); + return false; + } + if ( (off_t)size <= off ) { + off -= size; + } else { + off = 0; + } + ssize_t ret = pread( fd, buffer, size - 1, off ); + close( fd ); + if ( ret < 0 ) + return false; + buffer[ret] = '\0'; + return true; +} + +static int writeLevel(char *buffer, logmask_t level) +{ + const char *word; + char *dest = buffer; + switch ( level ) { + case LOG_ERROR: + word = "ERROR"; + break; + case LOG_WARNING: + word = "WARNING"; + break; + case LOG_MINOR: + word = "Warning"; + break; + case LOG_INFO: + word = "Info"; + break; + case LOG_DEBUG1: + word = "DEBUG1"; + break; + case LOG_DEBUG2: + word = "DEBUG2"; + break; + default: + word = "!?!?!?"; + break; + } + while ( ( *dest++ = *word++ ) ); + *--dest = ':'; + *++dest = ' '; + return (int)( dest - buffer ) + 1; +} + diff --git a/src/server/log.h b/src/server/log.h new file mode 100644 index 0000000..f273cab --- /dev/null +++ b/src/server/log.h @@ -0,0 +1,55 @@ +/* + * This file is part of the Distributed Network Block Device 3 + * + * Copyright(c) 2011-2012 Simon Rettberg + * + * This file may be licensed under the terms of of the + * GNU General Public License Version 2 (the ``GPL''). + * + * Software distributed under the License is distributed + * on an ``AS IS'' basis, WITHOUT WARRANTY OF ANY KIND, either + * express or implied. See the GPL for the specific language + * governing rights and limitations. + * + * You should have received a copy of the GPL along with this + * program. If not, go to http://www.gnu.org/licenses/gpl.html + * or write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. + * + */ + +#ifndef LOG_H_ +#define LOG_H_ + +#include + +typedef unsigned int logmask_t; +#define LOG_ERROR ((logmask_t)1) // Fatal error, server will terminate +#define LOG_WARNING ((logmask_t)2) // Major issue, something is broken but keep running +#define LOG_MINOR ((logmask_t)4) // Minor issue, more of a hickup than serious problem +#define LOG_INFO ((logmask_t)8) // Informational message +#define LOG_DEBUG1 ((logmask_t)16) // Debug information, use this for non-spammy stuff +#define LOG_DEBUG2 ((logmask_t)32) // Use this for debug messages that will show up a lot + +void log_setFileMask(logmask_t mask); + +void log_setConsoleMask(logmask_t mask); + +/** + * Open or reopen the log file. If path is NULL and the + * function was called with a path before, the same path + * will be used again. + */ +bool log_openLogFile(const char *path); + +/** + * Add a line to the log + */ +void logadd(const logmask_t mask, const char *text, ...); + +/** + * Return last size bytes of log. + */ +bool log_fetch(char *buffer, int size); + +#endif /* LOG_H_ */ diff --git a/src/server/memlog.c b/src/server/memlog.c deleted file mode 100644 index 1d95c5a..0000000 --- a/src/server/memlog.c +++ /dev/null @@ -1,123 +0,0 @@ -/* - * This file is part of the Distributed Network Block Device 3 - * - * Copyright(c) 2011-2012 Simon Rettberg - * - * This file may be licensed under the terms of of the - * GNU General Public License Version 2 (the ``GPL''). - * - * Software distributed under the License is distributed - * on an ``AS IS'' basis, WITHOUT WARRANTY OF ANY KIND, either - * express or implied. See the GPL for the specific language - * governing rights and limitations. - * - * You should have received a copy of the GPL along with this - * program. If not, go to http://www.gnu.org/licenses/gpl.html - * or write to the Free Software Foundation, Inc., - * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. - * - */ - -#include -#include -#include -#include -#include -#include -#include -#include "locks.h" - -#define MAX(a,b) (a > b ? a : b) - -static pthread_spinlock_t logLock; - -#define LINE_LEN 500 -#define LINE_COUNT 50 - -typedef struct -{ - uint16_t len; - char text[LINE_LEN]; -} LogLine; - -// This will be used as a ring buffer -static LogLine *logBuffer = NULL; -// bufferPos counts up, use modulo LINE_COUNT to get array index -static int bufferPos = 0; - -void initmemlog() -{ - // Use main spinlock to make sure we really init only once - if ( logBuffer ) return; - spin_init( &logLock, PTHREAD_PROCESS_PRIVATE ); - logBuffer = (LogLine *)calloc( LINE_COUNT, sizeof(LogLine) ); -} - -void memlogf(const char *fmt, ...) -{ - if ( logBuffer == NULL ) { - va_list ap; - va_start( ap, fmt ); - vprintf( fmt, ap ); - va_end( ap ); - printf( "\n" ); - return; // Not initialized yet - } - va_list ap; - int ret; - time_t rawtime; - struct tm *timeinfo; - time( &rawtime ); - timeinfo = localtime( &rawtime ); - spin_lock( &logLock ); - LogLine * const line = (LogLine *)&(logBuffer[bufferPos % LINE_COUNT]); - const size_t offset = strftime( line->text, LINE_LEN, "[%d.%m. %H:%M:%S] ", timeinfo ); - if ( offset == 0 ) *line->text = '\0'; - va_start( ap, fmt ); - ret = vsnprintf( line->text + offset, LINE_LEN - offset, fmt, ap ); - va_end( ap ); - char *end = line->text + strlen( line->text ); - while ( end > line->text && *--end == '\n' ) - *end = '\0'; // remove trailing \n - // glibc 2.0 would return -1 if the buffer was too small - // glibc 2.1 would return the number of bytes required if the buffer was too small - // so to be safe either way, let strlen do the job - line->len = strlen( line->text ); - if ( ret > 0 || line->len > 0 ) ++bufferPos; - spin_unlock( &logLock ); - puts( line->text ); -} - -char *fetchlog(int maxlines) -{ - if ( !logBuffer ) return NULL ; - if ( maxlines <= 0 || maxlines > LINE_COUNT ) maxlines = LINE_COUNT; - const int start = MAX(0, bufferPos - maxlines); - int len = 1, i; - //printf("Outputting log from %d to %d\n", start, bufferPos); - spin_lock( &logLock ); - // Determine required buffer space for all log lines - for (i = start; i < bufferPos; ++i) { - if ( logBuffer[i % LINE_COUNT].len > 0 ) { - len += logBuffer[i % LINE_COUNT].len + 1; - } - } - //printf("Have to allocate %d bytes\n", len); - // Allocate buffer. If this is a bottleneck because of malloc, consider passing a buffer to the function that the caller allocates on the stack - char *retval = (char *)calloc( len, sizeof(char) ); - if ( retval == NULL ) goto endFunction; - // Concatenate all log lines, delimit using '\n' - char *pos = retval; - for (i = start; i < bufferPos; ++i) { - LogLine * const line = (LogLine *)&(logBuffer[i % LINE_COUNT]); - if ( line->len > 0 ) { - memcpy( pos, (char *)line->text, line->len ); - pos += line->len; - *pos++ = '\n'; - } - } - *pos = '\0'; - endFunction: - spin_unlock( &logLock ); - return retval; -} diff --git a/src/server/memlog.h b/src/server/memlog.h deleted file mode 100644 index 38c4349..0000000 --- a/src/server/memlog.h +++ /dev/null @@ -1,39 +0,0 @@ -/* - * This file is part of the Distributed Network Block Device 3 - * - * Copyright(c) 2011-2012 Simon Rettberg - * - * This file may be licensed under the terms of of the - * GNU General Public License Version 2 (the ``GPL''). - * - * Software distributed under the License is distributed - * on an ``AS IS'' basis, WITHOUT WARRANTY OF ANY KIND, either - * express or implied. See the GPL for the specific language - * governing rights and limitations. - * - * You should have received a copy of the GPL along with this - * program. If not, go to http://www.gnu.org/licenses/gpl.html - * or write to the Free Software Foundation, Inc., - * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. - * - */ - -#ifndef MEMLOG_H_ -#define MEMLOG_H_ - -void initmemlog(); - -/** - * Add a line to the log - */ -void memlogf(char *text, ...); - -/** - * Return log lines, separated by \n - * You need to free() the returned memory after use - * Returns NULL on error - * maxlines - Limit number of lines returned, 0 = everything - */ -char *fetchlog(int maxlines); - -#endif /* MEMLOG_H_ */ diff --git a/src/server/net.c b/src/server/net.c index cde5f36..1d30183 100644 --- a/src/server/net.c +++ b/src/server/net.c @@ -37,7 +37,7 @@ #include "image.h" #include "uplink.h" #include "altservers.h" -#include "memlog.h" +#include "log.h" #include "helper.h" #include "../serialize.h" #include "../config.h" @@ -52,18 +52,18 @@ static inline bool recv_request_header(int sock, dnbd3_request_t *request) if ( errno == EINTR && ++fails < 10 ) continue; if ( ret >= 0 || ++fails > SOCKET_TIMEOUT_SERVER_RETRIES ) return false; if ( errno == EAGAIN ) continue; - printf( "[DEBUG] Error receiving request: Could not read message header (%d/%d, e=%d)\n", ret, (int)sizeof(*request), errno ); + logadd( LOG_DEBUG1, "Error receiving request: Could not read message header (%d/%d, e=%d)\n", ret, (int)sizeof(*request), errno ); return false; } // Make sure all bytes are in the right order (endianness) fixup_request( *request ); if ( request->magic != dnbd3_packet_magic ) { - printf( "[DEBUG] Magic in client request incorrect (cmd: %d, len: %d)\n", (int)request->cmd, (int)request->size ); + logadd( LOG_DEBUG1, "Magic in client request incorrect (cmd: %d, len: %d)\n", (int)request->cmd, (int)request->size ); return false; } // Payload sanity check if ( request->cmd != CMD_GET_BLOCK && request->size > MAX_PAYLOAD ) { - memlogf( "[WARNING] Client tries to send a packet of type %d with %d bytes payload. Dropping client.", (int)request->cmd, + logadd( LOG_WARNING, "Client tries to send a packet of type %d with %d bytes payload. Dropping client.", (int)request->cmd, (int)request->size ); return false; } @@ -76,15 +76,15 @@ static inline bool recv_request_header(int sock, dnbd3_request_t *request) static inline bool recv_request_payload(int sock, uint32_t size, serialized_buffer_t *payload) { if ( size == 0 ) { - memlogf( "[BUG] Called recv_request_payload() to receive 0 bytes" ); + logadd( LOG_ERROR, "Called recv_request_payload() to receive 0 bytes" ); return false; } if ( size > MAX_PAYLOAD ) { - memlogf( "[BUG] Called recv_request_payload() for more bytes than the passed buffer could hold!" ); + logadd( LOG_ERROR, "Called recv_request_payload() for more bytes than the passed buffer could hold!" ); return false; } if ( recv( sock, payload->buffer, size, MSG_WAITALL ) != size ) { - printf( "[ERROR] Could not receive request payload of length %d\n", (int)size ); + logadd( LOG_DEBUG1, "Could not receive request payload of length %d\n", (int)size ); return false; } // Prepare payload buffer for reading @@ -98,7 +98,7 @@ static inline bool send_reply(int sock, dnbd3_reply_t *reply, void *payload) fixup_reply( *reply ); if ( !payload || size == 0 ) { if ( send( sock, reply, sizeof(dnbd3_reply_t), 0 ) != sizeof(dnbd3_reply_t) ) { - printf( "[DEBUG] Send failed (header-only)\n" ); + logadd( LOG_DEBUG1, "Send failed (header-only)\n" ); return false; } } else { @@ -108,7 +108,7 @@ static inline bool send_reply(int sock, dnbd3_reply_t *reply, void *payload) iov[1].iov_base = payload; iov[1].iov_len = (size_t)size; if ( (size_t)writev( sock, iov, 2 ) != sizeof(dnbd3_reply_t) + size ) { - printf( "[DEBUG] Send failed (reply with payload of %u bytes)\n", size ); + logadd( LOG_DEBUG1, "Send failed (reply with payload of %u bytes)\n", size ); return false; } } @@ -146,7 +146,7 @@ void *net_client_handler(void *dnbd3_client) // Receive first packet. This must be CMD_SELECT_IMAGE by protocol specification if ( recv_request_header( client->sock, &request ) ) { if ( request.cmd != CMD_SELECT_IMAGE ) { - printf( "[DEBUG] Client sent invalid handshake (%d). Dropping Client\n", (int)request.cmd ); + logadd( LOG_DEBUG1, "Client sent invalid handshake (%d). Dropping Client\n", (int)request.cmd ); } else { if ( recv_request_payload( client->sock, request.size, &payload ) ) { client_version = serializer_get_uint16( &payload ); @@ -155,16 +155,16 @@ void *net_client_handler(void *dnbd3_client) client->isServer = serializer_get_uint8( &payload ); if ( request.size < 3 || !image_name || client_version < MIN_SUPPORTED_CLIENT ) { if ( client_version < MIN_SUPPORTED_CLIENT ) { - printf( "[DEBUG] Client too old\n" ); + logadd( LOG_DEBUG1, "Client too old\n" ); } else { - printf( "[DEBUG] Incomplete handshake received\n" ); + logadd( LOG_DEBUG1, "Incomplete handshake received\n" ); } } else { client->image = image = image_getOrClone( image_name, rid ); if ( image == NULL ) { - //printf( "[DEBUG] Client requested non-existent image '%s' (rid:%d), rejected\n", image_name, (int)rid ); + //logadd( LOG_DEBUG1, "Client requested non-existent image '%s' (rid:%d), rejected\n", image_name, (int)rid ); } else if ( !image->working ) { - printf( "[DEBUG] Client requested non-working image '%s' (rid:%d), rejected\n", image_name, (int)rid ); + logadd( LOG_DEBUG1, "Client requested non-working image '%s' (rid:%d), rejected\n", image_name, (int)rid ); } else { image_file = image->readFd; serializer_reset_write( &payload ); @@ -199,7 +199,7 @@ void *net_client_handler(void *dnbd3_client) case CMD_GET_BLOCK: if ( request.offset >= image->filesize ) { // Sanity check - memlogf( "[WARNING] Client requested non-existent block" ); + logadd( LOG_WARNING, "Client requested non-existent block" ); reply.size = 0; reply.cmd = CMD_ERROR; send_reply( client->sock, &reply, NULL ); @@ -207,7 +207,7 @@ void *net_client_handler(void *dnbd3_client) } if ( request.offset + request.size > image->filesize ) { // Sanity check - memlogf( "[WARNING] Client requested data block that extends beyond image size" ); + logadd( LOG_WARNING, "Client requested data block that extends beyond image size" ); reply.size = 0; reply.cmd = CMD_ERROR; send_reply( client->sock, &reply, NULL ); @@ -215,7 +215,7 @@ void *net_client_handler(void *dnbd3_client) } if ( request.size > image->filesize ) { // Sanity check - memlogf( "[WARNING] Client requested data block that is bigger than the image size" ); + logadd( LOG_WARNING, "Client requested data block that is bigger than the image size" ); reply.size = 0; reply.cmd = CMD_ERROR; send_reply( client->sock, &reply, NULL ); @@ -273,7 +273,7 @@ void *net_client_handler(void *dnbd3_client) spin_unlock( &image->lock ); if ( !isCached ) { if ( !uplink_request( client, request.handle, request.offset, request.size ) ) { - printf( "[DEBUG] Could not relay uncached request to upstream proxy\n" ); + logadd( LOG_DEBUG1, "Could not relay uncached request to upstream proxy\n" ); goto exit_client_cleanup; } break; // DONE @@ -290,7 +290,7 @@ void *net_client_handler(void *dnbd3_client) // Send reply header if ( send( client->sock, &reply, sizeof(dnbd3_reply_t), (request.size == 0 ? 0 : MSG_MORE) ) != sizeof(dnbd3_reply_t) ) { if ( lock ) pthread_mutex_unlock( &client->sendMutex ); - printf( "[DEBUG] Sending CMD_GET_BLOCK header failed\n" ); + logadd( LOG_DEBUG1, "Sending CMD_GET_BLOCK header failed\n" ); goto exit_client_cleanup; } @@ -303,7 +303,7 @@ void *net_client_handler(void *dnbd3_client) if ( ret <= 0 ) { if ( lock ) pthread_mutex_unlock( &client->sendMutex ); if ( ret < 0 && errno != 32 && errno != 104 ) - printf( "[DEBUG] sendfile failed (image to net. sent %d/%d, errno=%d)\n", + logadd( LOG_DEBUG1, "sendfile failed (image to net. sent %d/%d, errno=%d)\n", (int)done, (int)request.size, (int)errno ); if ( errno == EBADF || errno == EINVAL || errno == EIO ) image->working = false; goto exit_client_cleanup; @@ -354,7 +354,7 @@ set_name: ; break; default: - memlogf( "[ERROR] Unknown command: %d", (int)request.cmd ); + logadd( LOG_ERROR, "Unknown command: %d", (int)request.cmd ); break; } diff --git a/src/server/server.c b/src/server/server.c index d50e532..77619eb 100644 --- a/src/server/server.c +++ b/src/server/server.c @@ -40,7 +40,7 @@ #include "uplink.h" #include "net.h" #include "altservers.h" -#include "memlog.h" +#include "log.h" #include "globals.h" #include "integrity.h" #include "helper.h" @@ -110,7 +110,7 @@ void dnbd3_cleanup() _shutdown = true; debug_locks_stop_watchdog(); - memlogf( "INFO: Cleanup...\n" ); + logadd( LOG_INFO, "Cleanup..." ); if ( listeners != NULL ) sock_destroyPollList( listeners ); listeners = NULL; @@ -274,15 +274,14 @@ int main(int argc, char *argv[]) // No one-shot detected, normal server operation if ( demonize ) daemon( 1, 0 ); - initmemlog(); spin_init( &_clients_lock, PTHREAD_PROCESS_PRIVATE ); spin_init( &_images_lock, PTHREAD_PROCESS_PRIVATE ); altservers_init(); integrity_init(); - memlogf( "DNBD3 server starting.... Machine type: " ENDIAN_MODE ); + logadd( LOG_INFO, "DNBD3 server starting.... Machine type: " ENDIAN_MODE ); if ( altservers_load() < 0 ) { - memlogf( "[WARNING] Could not load alt-servers. Does the file exist in %s?", _configDir ); + logadd( LOG_WARNING, "Could not load alt-servers. Does the file exist in %s?", _configDir ); } #ifdef _DEBUG @@ -296,10 +295,10 @@ int main(int argc, char *argv[]) signal( SIGHUP, dnbd3_handleSignal ); signal( SIGUSR2, dnbd3_handleSignal ); - printf( "Loading images....\n" ); + logadd( LOG_INFO, "Loading images...." ); // Load all images in base path if ( !image_loadAll( NULL ) ) { - printf( "[ERROR] Could not load images.\n" ); + logadd( LOG_ERROR, "Could not load images." ); return EXIT_FAILURE; } @@ -311,11 +310,11 @@ int main(int argc, char *argv[]) // setup network listeners = sock_newPollList(); if ( listeners == NULL ) { - printf( "Didnt get a poll list!\n" ); + logadd( LOG_ERROR, "Didnt get a poll list!" ); exit( EXIT_FAILURE ); } if ( !sock_listen( listeners, bindAddress, PORT ) ) { - printf( "Could not listen on any local interface.\n" ); + logadd( LOG_ERROR, "Could not listen on any local interface." ); exit( EXIT_FAILURE ); } struct sockaddr_storage client; @@ -327,26 +326,25 @@ int main(int argc, char *argv[]) //thread_create(&(thread_rpc), NULL, &dnbd3_rpc_mainloop, NULL); // Initialize thread pool if ( !threadpool_init( 8 ) ) { - printf( "Could not init thread pool!\n" ); + logadd( LOG_ERROR, "Could not init thread pool!\n" ); exit( EXIT_FAILURE ); } - memlogf( "[INFO] Server is ready..." ); + logadd( LOG_INFO, "Server is ready..." ); // +++++++++++++++++++++++++++++++++++++++++++++++++++ main loop while ( !_shutdown ) { // Handle signals if ( sigReload ) { sigReload = false; - memlogf( "INFO: SIGUSR1 received, re-scanning image directory" ); + logadd( LOG_INFO, "SIGUSR1 received, re-scanning image directory" ); image_loadAll( NULL ); } if ( sigPrintStats ) { sigPrintStats = false; - printf( "[DEBUG] SIGUSR2 received, stats incoming\n" ); - printf( " ** Images **\n" ); + logadd( LOG_WARNING, " ** Images **" ); image_printAll(); - printf( " ** Clients **\n" ); + logadd( LOG_WARNING, " ** Clients **" ); dnbd3_printClients(); } // @@ -355,11 +353,10 @@ int main(int argc, char *argv[]) if ( fd < 0 ) { const int err = errno; if ( err == EINTR || err == EAGAIN ) continue; - memlogf( "[ERROR] Client accept failure (err=%d)", err ); + logadd( LOG_ERROR, "Client accept failure (err=%d)", err ); usleep( 10000 ); // 10ms continue; } - //memlogf("INFO: Client connected\n"); dnbd3_client_t *dnbd3_client = dnbd3_initClient( &client, fd ); if ( dnbd3_client == NULL ) { @@ -375,7 +372,7 @@ int main(int argc, char *argv[]) } if ( !threadpool_run( net_client_handler, (void *)dnbd3_client ) ) { - memlogf( "[ERROR] Could not start thread for new client." ); + logadd( LOG_ERROR, "Could not start thread for new client." ); dnbd3_removeClient( dnbd3_client ); dnbd3_client = dnbd3_freeClient( dnbd3_client ); continue; @@ -392,7 +389,7 @@ dnbd3_client_t* dnbd3_initClient(struct sockaddr_storage *client, int fd) { dnbd3_client_t *dnbd3_client = calloc( 1, sizeof(dnbd3_client_t) ); if ( dnbd3_client == NULL ) { // This will never happen thanks to memory overcommit - memlogf( "[ERROR] Could not alloc dnbd3_client_t for new client." ); + logadd( LOG_ERROR, "Could not alloc dnbd3_client_t for new client." ); return NULL ; } @@ -407,7 +404,7 @@ dnbd3_client_t* dnbd3_initClient(struct sockaddr_storage *client, int fd) memcpy( dnbd3_client->host.addr, &(v6->sin6_addr), 16 ); dnbd3_client->host.port = v6->sin6_port; } else { - memlogf( "[ERROR] New client has unknown address family %d, disconnecting...", (int)client->ss_family ); + logadd( LOG_ERROR, "New client has unknown address family %d, disconnecting...", (int)client->ss_family ); free( dnbd3_client ); return NULL ; } @@ -479,7 +476,7 @@ static bool dnbd3_addClient(dnbd3_client_t *client) } if ( _num_clients >= SERVER_MAX_CLIENTS ) { spin_unlock( &_clients_lock ); - memlogf( "[ERROR] Maximum number of clients reached!" ); + logadd( LOG_ERROR, "Maximum number of clients reached!" ); return false; } _clients[_num_clients++] = client; diff --git a/src/server/sockhelper.c b/src/server/sockhelper.c index 4cd0b56..fbde74c 100644 --- a/src/server/sockhelper.c +++ b/src/server/sockhelper.c @@ -1,5 +1,5 @@ #include "sockhelper.h" -#include "memlog.h" +#include "log.h" #include #include #include // inet_ntop @@ -49,7 +49,7 @@ int sock_connect(const dnbd3_host_t * const addr, const int connect_ms, const in } #endif else { - printf( "[DEBUG] Unsupported address type: %d\n", (int)addr->type ); + logadd( LOG_DEBUG1, "Unsupported address type: %d\n", (int)addr->type ); return -1; } int client_sock = socket( proto, SOCK_STREAM, IPPROTO_TCP ); diff --git a/src/server/threadpool.c b/src/server/threadpool.c index 44649e4..ad146ea 100644 --- a/src/server/threadpool.c +++ b/src/server/threadpool.c @@ -57,17 +57,17 @@ bool threadpool_run(void *(*startRoutine)(void *), void *arg) if ( entry == NULL ) { entry = (entry_t*)malloc( sizeof(entry_t) ); if ( entry == NULL ) { - printf( "[WARNING] Could not alloc entry_t for new thread\n" ); + logadd( LOG_WARNING, "Could not alloc entry_t for new thread\n" ); return false; } entry->signalFd = signal_newBlocking(); if ( entry->signalFd < 0 ) { - printf( "[WARNING] Could not create signalFd for new thread pool thread\n" ); + logadd( LOG_WARNING, "Could not create signalFd for new thread pool thread\n" ); free( entry ); return false; } if ( 0 != thread_create( &(entry->thread), &threadAttrs, threadpool_worker, (void*)entry ) ) { - printf( "[WARNING] Could not create new thread for thread pool\n" ); + logadd( LOG_WARNING, "Could not create new thread for thread pool\n" ); signal_close( entry->signalFd ); free( entry ); return false; @@ -93,7 +93,7 @@ static void *threadpool_worker(void *entryPtr) if ( _shutdown ) break; if ( ret > 0 ) { if ( entry->startRoutine == NULL ) { - printf( "[DEBUG] Worker woke up but has no work to do!\n" ); + logadd( LOG_DEBUG1, "Worker woke up but has no work to do!\n" ); continue; } // Start assigned work @@ -119,7 +119,7 @@ static void *threadpool_worker(void *entryPtr) spin_unlock( &poolLock ); setThreadName( "[pool]" ); } else { - printf( "[DEBUG] Unexpected return value %d for signal_wait in threadpool worker!\n", ret ); + logadd( LOG_DEBUG1, "Unexpected return value %d for signal_wait in threadpool worker!\n", ret ); } } signal_close( entry->signalFd ); diff --git a/src/server/uplink.c b/src/server/uplink.c index 2459171..edf8b89 100644 --- a/src/server/uplink.c +++ b/src/server/uplink.c @@ -1,6 +1,6 @@ #include "uplink.h" #include "locks.h" -#include "memlog.h" +#include "log.h" #include "sockhelper.h" #include "image.h" #include "helper.h" @@ -48,7 +48,7 @@ bool uplink_init(dnbd3_image_t *image, int sock, dnbd3_host_t *host) return true; // There's already an uplink, so should we consider this success or failure? } if ( image->cache_map == NULL ) { - memlogf( "[WARNING] Uplink was requested for image %s, but it is already complete", image->lower_name ); + logadd( LOG_WARNING, "Uplink was requested for image %s, but it is already complete", image->lower_name ); goto failure; } link = image->uplink = calloc( 1, sizeof(dnbd3_connection_t) ); @@ -69,7 +69,7 @@ bool uplink_init(dnbd3_image_t *image, int sock, dnbd3_host_t *host) link->shutdown = false; spin_init( &link->queueLock, PTHREAD_PROCESS_PRIVATE ); if ( 0 != thread_create( &(link->thread), NULL, &uplink_mainloop, (void *)link ) ) { - memlogf( "[ERROR] Could not start thread for new uplink." ); + logadd( LOG_ERROR, "Could not start thread for new uplink." ); goto failure; } spin_unlock( &image->lock ); @@ -140,19 +140,19 @@ bool uplink_request(dnbd3_client_t *client, uint64_t handle, uint64_t start, uin spin_lock( &client->image->lock ); if ( client->image->uplink == NULL ) { spin_unlock( &client->image->lock ); - printf( "[DEBUG] Uplink request for image with no uplink (%s)\n", client->image->lower_name ); + logadd( LOG_DEBUG1, "Uplink request for image with no uplink (%s)\n", client->image->lower_name ); return false; } dnbd3_connection_t * const uplink = client->image->uplink; if ( uplink->shutdown ) { spin_unlock( &client->image->lock ); - printf( "[DEBUG] Uplink request for image with uplink shutting down (%s)\n", client->image->lower_name ); + logadd( LOG_DEBUG1, "Uplink request for image with uplink shutting down (%s)\n", client->image->lower_name ); return false; } // Check if the client is the same host as the uplink. If so assume this is a circular proxy chain if ( isSameAddress( &uplink->currentServer, &client->host ) ) { spin_unlock( &client->image->lock ); - printf( "[DEBUG] Proxy cycle detected.\n" ); + logadd( LOG_DEBUG1, "Proxy cycle detected.\n" ); return false; } @@ -176,7 +176,7 @@ bool uplink_request(dnbd3_client_t *client, uint64_t handle, uint64_t start, uin if ( freeSlot == -1 ) { if ( uplink->queueLen >= SERVER_MAX_UPLINK_QUEUE ) { spin_unlock( &uplink->queueLock ); - memlogf( "[WARNING] Uplink queue is full, consider increasing SERVER_MAX_UPLINK_QUEUE. Dropping client..." ); + logadd( LOG_WARNING, "Uplink queue is full, consider increasing SERVER_MAX_UPLINK_QUEUE. Dropping client..." ); return false; } freeSlot = uplink->queueLen++; @@ -206,7 +206,7 @@ bool uplink_request(dnbd3_client_t *client, uint64_t handle, uint64_t start, uin uplink->queue[freeSlot].status = (foundExisting == -1 ? ULR_NEW : ULR_PENDING); #ifdef _DEBUG uplink->queue[freeSlot].entered = time( NULL ); - //printf( "[V %p] Inserting request at slot %d, was %d, now %d, handle %" PRIu64 ", Range: %" PRIu64 "-%" PRIu64 "\n", (void*)uplink, freeSlot, old, uplink->queue[freeSlot].status, uplink->queue[freeSlot].handle, start, end ); + //logadd( LOG_DEBUG2 %p] Inserting request at slot %d, was %d, now %d, handle %" PRIu64 ", Range: %" PRIu64 "-%" PRIu64 "\n", (void*)uplink, freeSlot, old, uplink->queue[freeSlot].status, uplink->queue[freeSlot, ".handle, start, end ); #endif spin_unlock( &uplink->queueLock ); @@ -238,19 +238,19 @@ static void* uplink_mainloop(void *data) // fdEpoll = epoll_create( 2 ); if ( fdEpoll == -1 ) { - memlogf( "[WARNING] epoll_create failed. Uplink unavailable." ); + logadd( LOG_WARNING, "epoll_create failed. Uplink unavailable." ); goto cleanup; } link->signal = signal_new(); if ( link->signal < 0 ) { - memlogf( "[WARNING] error creating pipe. Uplink unavailable." ); + logadd( LOG_WARNING, "error creating pipe. Uplink unavailable." ); goto cleanup; } memset( &ev, 0, sizeof(ev) ); ev.events = EPOLLIN; ev.data.fd = link->signal; if ( epoll_ctl( fdEpoll, EPOLL_CTL_ADD, link->signal, &ev ) < 0 ) { - memlogf( "[WARNING] adding eventfd to epoll set failed" ); + logadd( LOG_WARNING, "adding eventfd to epoll set failed" ); goto cleanup; } while ( !_shutdown && !link->shutdown ) { @@ -273,7 +273,7 @@ static void* uplink_mainloop(void *data) link->image->working = true; buffer[0] = '@'; if ( host_to_string( &link->currentServer, buffer + 1, sizeof(buffer) - 1 ) ) { - printf( "[DEBUG] (Uplink %s) Now connected to %s\n", link->image->lower_name, buffer + 1 ); + logadd( LOG_DEBUG1, "(Uplink %s) Now connected to %s\n", link->image->lower_name, buffer + 1 ); setThreadName( buffer ); } // Re-send all pending requests @@ -283,7 +283,7 @@ static void* uplink_mainloop(void *data) ev.events = EPOLLIN | EPOLLRDHUP | EPOLLPRI; ev.data.fd = link->fd; if ( epoll_ctl( fdEpoll, EPOLL_CTL_ADD, link->fd, &ev ) < 0 ) { - memlogf( "[WARNING] adding uplink to epoll set failed" ); + logadd( LOG_WARNING, "adding uplink to epoll set failed" ); goto cleanup; } nextAltCheck = time( NULL ) + altCheckInterval; @@ -297,7 +297,7 @@ static void* uplink_mainloop(void *data) numSocks = epoll_wait( fdEpoll, events, MAXEVENTS, waitTime ); if ( _shutdown || link->shutdown ) goto cleanup; if ( numSocks < 0 ) { // Error? - memlogf( "[DEBUG] epoll_wait() error %d", (int)errno); + logadd( LOG_DEBUG1, "epoll_wait() error %d", (int)errno); usleep( 10000 ); continue; } @@ -306,17 +306,17 @@ static void* uplink_mainloop(void *data) // Check for errors.... if ( (events[i].events & (EPOLLERR | EPOLLHUP | EPOLLRDHUP)) || !(events[i].events & EPOLLIN) ) { if ( events[i].data.fd == link->signal ) { - memlogf( "[WARNING] epoll error on signal in uplink_mainloop!" ); + logadd( LOG_WARNING, "epoll error on signal in uplink_mainloop!" ); goto cleanup; } if ( events[i].data.fd == link->fd ) { link->fd = -1; close( events[i].data.fd ); - printf( "[DEBUG] Uplink gone away, panic!\n" ); + logadd( LOG_DEBUG1, "Uplink gone away, panic!\n" ); } else if ( events[i].data.fd == link->signal ) { - printf( "[DEBUG] Error on uplink signal fd!\n" ); + logadd( LOG_DEBUG1, "Error on uplink signal fd!\n" ); } else { - printf( "[DEBUG] Error on unknown FD in uplink epoll\n" ); + logadd( LOG_DEBUG1, "Error on unknown FD in uplink epoll\n" ); close( events[i].data.fd ); } continue; @@ -325,7 +325,7 @@ static void* uplink_mainloop(void *data) if ( events[i].data.fd == link->signal ) { // Event on the signal fd -> a client requests data if ( signal_clear( link->signal ) == SIGNAL_ERROR ) { - memlogf( "[WARNING] Errno on eventfd on uplink for %s! Things will break!", link->image->lower_name ); + logadd( LOG_WARNING, "Errno on eventfd on uplink for %s! Things will break!", link->image->lower_name ); } if ( link->fd != -1 ) { // Uplink seems fine, relay requests to it... @@ -336,7 +336,7 @@ static void* uplink_mainloop(void *data) if ( link->fd == -1 ) nextAltCheck = 0; if ( _shutdown || link->shutdown ) goto cleanup; } else { - printf( "[DEBUG] Sanity check: unknown FD ready on epoll! Closing...\n" ); + logadd( LOG_DEBUG1, "Sanity check: unknown FD ready on epoll! Closing...\n" ); close( events[i].data.fd ); } } @@ -360,7 +360,7 @@ static void* uplink_mainloop(void *data) // It seems it's time for a check if ( image_isComplete( link->image ) ) { // Quit work if image is complete - memlogf( "[INFO] Replication of %s complete.", link->image->lower_name ); + logadd( LOG_INFO, "Replication of %s complete.", link->image->lower_name ); if ( spin_trylock( &link->image->lock ) == 0 ) { image_markComplete( link->image ); spin_unlock( &link->image->lock ); @@ -437,7 +437,7 @@ static void uplink_sendRequests(dnbd3_connection_t *link, bool newOnly) spin_lock( &link->queueLock ); for (j = 0; j < link->queueLen; ++j) { if ( link->queue[j].status != ULR_NEW && (newOnly || link->queue[j].status != ULR_PENDING) ) continue; - //printf( "[V %p] Sending slot %d, now %d, handle %" PRIu64 ", Range: %" PRIu64 "-%" PRIu64 "\n", (void*)link, j, link->queue[j].status, link->queue[j].handle, link->queue[j].from, link->queue[j].to ); + //logadd( LOG_DEBUG2 %p] Sending slot %d, now %d, handle %" PRIu64 ", Range: %" PRIu64 "-%" PRIu64 "\n", (void*)link, j, link->queue[j].status, link->queue[j].handle, link->queue[j].from, link->queue[j, ".to ); link->queue[j].status = ULR_PENDING; const uint64_t offset = link->queue[j].from; const uint32_t size = link->queue[j].to - link->queue[j].from; @@ -447,7 +447,7 @@ static void uplink_sendRequests(dnbd3_connection_t *link, bool newOnly) // Non-critical - if the connection dropped or the server was changed // the thread will re-send this request as soon as the connection // is reestablished. - printf( "[DEBUG] Error forwarding request to uplink server!\n" ); + logadd( LOG_DEBUG1, "Error forwarding request to uplink server!\n" ); altservers_serverFailed( &link->currentServer ); return; } @@ -490,7 +490,7 @@ static void uplink_sendReplicationRequest(dnbd3_connection_t *link) const uint64_t offset = link->replicationHandle = (uint64_t)i * (uint64_t)requestBlockSize; const uint32_t size = MIN( image->filesize - offset, requestBlockSize ); if ( !dnbd3_get_block( link->fd, offset, size, link->replicationHandle ) ) { - printf( "[DEBUG] Error sending background replication request to uplink server!\n" ); + logadd( LOG_DEBUG1, "Error sending background replication request to uplink server!\n" ); return; } if ( i == len ) link->replicatedLastBlock = true; // Special treatment, last byte in map could represent less than 8 blocks @@ -513,19 +513,19 @@ static void uplink_handleReceive(dnbd3_connection_t *link) if ( ret == REPLY_INTR && !_shutdown && !link->shutdown ) continue; if ( ret == REPLY_AGAIN ) break; if ( ret == REPLY_CLOSED ) { - memlogf( "[INFO] Uplink: Remote host hung up (%s)", link->image->path ); + logadd( LOG_INFO, "Uplink: Remote host hung up (%s)", link->image->path ); goto error_cleanup; } if ( ret == REPLY_WRONGMAGIC ) { - memlogf( "[WARNING] Uplink server's packet did not start with dnbd3_packet_magic (%s)", link->image->path ); + logadd( LOG_WARNING, "Uplink server's packet did not start with dnbd3_packet_magic (%s)", link->image->path ); goto error_cleanup; } if ( ret != REPLY_OK ) { - memlogf( "[INFO] Uplink: Connection error %d (%s)", ret, link->image->path ); + logadd( LOG_INFO, "Uplink: Connection error %d (%s)", ret, link->image->path ); goto error_cleanup; } if ( inReply.size > 9000000 ) { // TODO: Configurable - memlogf( "[WARNING] Pure evil: Uplink server sent too much payload for %s", link->image->path ); + logadd( LOG_WARNING, "Pure evil: Uplink server sent too much payload for %s", link->image->path ); goto error_cleanup; } @@ -537,7 +537,7 @@ static void uplink_handleReceive(dnbd3_connection_t *link) while ( done < inReply.size ) { ret = recv( link->fd, link->recvBuffer + done, inReply.size - done, MSG_NOSIGNAL ); if ( ret <= 0 ) { - memlogf( "[INFO] Lost connection to uplink server of %s (payload)", link->image->path ); + logadd( LOG_INFO, "Lost connection to uplink server of %s (payload)", link->image->path ); goto error_cleanup; } done += ret; @@ -572,7 +572,7 @@ static void uplink_handleReceive(dnbd3_connection_t *link) for (i = link->queueLen - 1; i >= 0; --i) { dnbd3_queued_request_t * const req = &link->queue[i]; if ( req->status == ULR_PROCESSING ) { - //printf( "[V %p] Reply slot %d, handle %" PRIu64 ", Range: %" PRIu64 "-%" PRIu64 "\n", (void*)link, i, req->handle, req->from, req->to ); + //logadd( LOG_DEBUG2 %p, "Reply slot %d, handle %" PRIu64 ", Range: %" PRIu64 "-%" PRIu64 "\n", (void*)link, i, req->handle, req->from, req->to ); assert( req->from >= start && req->to <= end ); dnbd3_client_t * const client = req->client; outReply.cmd = CMD_GET_BLOCK; @@ -597,7 +597,7 @@ static void uplink_handleReceive(dnbd3_connection_t *link) spin_unlock( &link->queueLock ); #ifdef _DEBUG if ( !served && start != link->replicationHandle ) - printf( "[DEBUG %p] %s -- Unmatched reply: %" PRIu64 " to %" PRIu64 "\n", (void*)link, link->image->lower_name, start, end ); + logadd( LOG_DEBUG2, "%p, %s -- Unmatched reply: %" PRIu64 " to %" PRIu64, (void*)link, link->image->lower_name, start, end ); #endif if ( start == link->replicationHandle ) link->replicationHandle = 0; } @@ -641,7 +641,7 @@ static void uplink_addCrc32(dnbd3_connection_t *uplink) uint32_t lists_crc = crc32( 0L, Z_NULL, 0 ); lists_crc = crc32( lists_crc, (Bytef*)buffer, bytes ); if ( lists_crc != masterCrc ) { - memlogf( "[WARNING] Received corrupted crc32 list from uplink server (%s)!", uplink->image->lower_name ); + logadd( LOG_WARNING, "Received corrupted crc32 list from uplink server (%s)!", uplink->image->lower_name ); free( buffer ); return; } -- cgit v1.2.3-55-g7522