Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP
Browse files

Logging enhancements for C-based components.

- renamed C-land log levels to match Java log levels
- added LOGMAXSIZE to eucalyptus.conf template
- added LOGPREFIX support in CC and NC, though not into eucalyptus.conf
- enabled printing of method, file, and number in log prefix
- added log_sem for synchronization, making logging thread-safe
- added general semaphore functions: sem_prolaag & sem_verhogen
- added log file stat() to check for file being deleted or moved away
- can optionally close log file on every message, though off by default
- tweaked log-related comments and defaults

Resolves EUCA-2958
Relates to EUCA-2957, EUCA-2600, EUCA-2597, EUCA-2953, EUCA-2958, EUCA-2211, EUCA-3006
  • Loading branch information...
commit c2783912b132e7aac1a161a8c258cb74957dc30b 1 parent 5976e3e
@dmitrii dmitrii authored
View
18 cluster/handlers.c
@@ -3485,7 +3485,13 @@ int init_log(void)
configInitValues(configKeysRestartCC, configKeysNoRestartCC); // initialize config subsystem
readConfigFile(configFiles, 2);
- configReadLogParams (&(config->log_level), &(config->log_roll_number), &(config->log_max_size_bytes));
+
+ char * log_prefix;
+ configReadLogParams (&(config->log_level), &(config->log_roll_number), &(config->log_max_size_bytes), &log_prefix);
+ if (log_prefix && strlen(log_prefix)>0) {
+ safe_strncpy (config->log_prefix, log_prefix, sizeof (config->log_prefix));
+ free (log_prefix);
+ }
// set the log file path (levels and size limits are set below)
log_file_set(logFile);
@@ -3496,6 +3502,7 @@ int init_log(void)
// update log params on every request so that the updated values discovered
// by monitoring_thread will get picked up by other processes, too
log_params_set (config->log_level, (int)config->log_roll_number, config->log_max_size_bytes);
+ log_prefix_set (config->log_prefix);
return 0;
}
@@ -3600,9 +3607,16 @@ int update_config(void) {
logprintfl(EUCAINFO, "update_config(): ingressing new options.\n");
// read log params from config file and update in-memory configuration
- configReadLogParams (&(config->log_level), &(config->log_roll_number), &(config->log_max_size_bytes));
+ char * log_prefix;
+ configReadLogParams (&(config->log_level), &(config->log_roll_number), &(config->log_max_size_bytes), &log_prefix);
+ if (log_prefix && strlen(log_prefix)>0) {
+ safe_strncpy (config->log_prefix, log_prefix, sizeof (config->log_prefix));
+ free (log_prefix);
+ }
+
// reconfigure the logging subsystem to use the new values, if any
log_params_set (config->log_level, (int)config->log_roll_number, config->log_max_size_bytes);
+ log_prefix_set (config->log_prefix);
// NODES
logprintfl(EUCAINFO, "update_config(): refreshing node list.\n");
View
1  cluster/handlers.h
@@ -216,6 +216,7 @@ typedef struct ccConfig_t {
long log_max_size_bytes;
int log_roll_number;
int log_level;
+ char log_prefix[64];
char proxyPath[MAX_PATH];
char proxyIp[32];
int use_proxy;
View
19 node/handlers.c
@@ -475,12 +475,16 @@ update_log_params (void)
int log_level;
int log_roll_number;
long log_max_size_bytes;
+ char * log_prefix;
// read log params from config file and update in-memory configuration
- configReadLogParams (&log_level, &log_roll_number, &log_max_size_bytes);
+ configReadLogParams (&log_level, &log_roll_number, &log_max_size_bytes, &log_prefix);
// reconfigure the logging subsystem to use the new values, if any
log_params_set (log_level, log_roll_number, log_max_size_bytes);
+ log_prefix_set (log_prefix);
+ if (log_prefix)
+ free (log_prefix);
}
void *
@@ -715,7 +719,7 @@ void *startup_thread (void * arg)
// serialize domain creation as hypervisors can get confused with
// too many simultaneous create requests
- logprintfl (EUCADEBUG2, "[%s] instance about to boot\n", instance->instanceId);
+ logprintfl (EUCATRACE, "[%s] instance about to boot\n", instance->instanceId);
boolean created = FALSE;
for (i=0; i<MAX_CREATE_TRYS; i++) { // retry loop
@@ -1099,10 +1103,15 @@ static int init (void)
inst_sem = sem_alloc (1, "mutex");
inst_copy_sem = sem_alloc (1, "mutex");
addkey_sem = sem_alloc (1, "mutex");
- if (!hyp_sem || !inst_sem || !inst_copy_sem || !addkey_sem) {
+ sem * log_sem = sem_alloc (1, "mutex");
+ if (!hyp_sem || !inst_sem || !inst_copy_sem || !addkey_sem || !log_sem) {
logprintfl (EUCAFATAL, "failed to create and initialize semaphores\n");
return ERROR_FATAL;
}
+ if (log_sem_set(log_sem) != 0) {
+ logprintfl (EUCAFATAL, "failed to set logging semaphore\n");
+ return ERROR_FATAL;
+ }
if ((loop_sem = diskutil_get_loop_sem())==NULL) { // NC does not need GRUB for now
logprintfl (EUCAFATAL, "failed to find all dependencies\n");
@@ -1453,7 +1462,7 @@ int doDescribeInstances (ncMetadata *meta, char **instIds, int instIdsLen, ncIns
if (init())
return 1;
- logprintfl (EUCADEBUG2, "doDescribeInstances: invoked\n");
+ logprintfl (EUCATRACE, "doDescribeInstances: invoked\n"); // response will be at INFO, so this is TRACE
if (nc_state.H->doDescribeInstances)
ret = nc_state.H->doDescribeInstances (&nc_state, meta, instIds, instIdsLen, outInsts, outInstsLen);
@@ -1833,7 +1842,7 @@ doDescribeSensors (ncMetadata *meta,
if (init())
return 1;
- logprintfl (EUCADEBUG2, "doDescribeSensors: invoked (instIdsLen=%d sensorIdsLen=%d)\n", instIdsLen, sensorIdsLen);
+ logprintfl (EUCADEBUG, "doDescribeSensors: invoked (instIdsLen=%d sensorIdsLen=%d)\n", instIdsLen, sensorIdsLen);
if (nc_state.H->doDescribeSensors)
ret = nc_state.H->doDescribeSensors (&nc_state, meta, historySize, collectionIntervalTimeMs, instIds, instIdsLen, sensorIds, sensorIdsLen, outResources, outResourcesLen);
View
1  node/handlers.h
@@ -140,6 +140,7 @@ static configEntry configKeysNoRestartNC[] = {
{"LOGLEVEL", "DEBUG"},
{"LOGROLLNUMBER", "4"},
{"LOGMAXSIZE", "10485760"},
+ {"LOGPREFIX", ""},
{NULL, NULL}
};
View
6 node/handlers_default.c
@@ -353,7 +353,7 @@ doDescribeInstances( struct nc_state_t *nc,
ncInstance *instance, *tmp;
int total, i, j, k;
- logprintfl(EUCADEBUG, "doDescribeInstances: userId=%s correlationId=%s epoch=%d services[0].name=%s services[0].type=%s services[0].uris[0]=%s\n",
+ logprintfl(EUCADEBUG, "invoked userId=%s correlationId=%s epoch=%d services[0]{.name=%s .type=%s .uris[0]=%s}\n",
SP(meta->userId),
SP(meta->correlationId),
meta->epoch,
@@ -456,11 +456,11 @@ doDescribeResource( struct nc_state_t *nc,
res = allocate_resource ("OK", nc->iqn, nc->mem_max, mem_free, nc->disk_max, disk_free, nc->cores_max, cores_free, "none");
if (res == NULL) {
- logprintfl (EUCAERROR, "error: doDescribeResouce: out of memory\n");
+ logprintfl (EUCAERROR, "out of memory\n");
return 1;
}
*outRes = res;
- logprintfl(EUCADEBUG, "doDescribeResource: cores=%d/%lld mem=%lld/%lld disk=%lld/%lld iqn=%s\n",
+ logprintfl(EUCADEBUG, "returning cores=%d/%lld mem=%lld/%lld disk=%lld/%lld iqn=%s\n",
cores_free, nc->cores_max,
mem_free, nc->mem_max,
disk_free, nc->disk_max,
View
4 node/xml.c
@@ -340,7 +340,7 @@ static void error_handler (void * ctx, const char * fmt, ...)
if (buf[i]=='\n' || i==(sizeof(buf)-1)) {
size = 0;
buf[i]='\0';
- logprintfl (EUCADEBUG, "ERROR from XML2/XSLT {%s}\n", buf);
+ logprintfl (EUCATRACE, "ERROR from XML2/XSLT {%s}\n", buf);
}
if (buf[i]=='\0') {
break;
@@ -475,7 +475,7 @@ int gen_libvirt_attach_xml (const char *volumeId, const ncInstance *instance, co
snprintf (path, sizeof (path), EUCALYPTUS_VOLUME_XML_PATH_FORMAT, instance->instancePath, volumeId);
ret = write_xml_file (doc, instance->instanceId, path, "volume")
|| apply_xslt_stylesheet (xslt_path, path, NULL, xml, xml_size);
- logprintfl (EUCADEBUG2, "XML={%s}\n", xml);
+ logprintfl (EUCATRACE, "XML={%s}\n", xml);
xmlFreeDoc(doc);
pthread_mutex_unlock (&xml_mutex);
View
2  storage/backing.c
@@ -102,7 +102,7 @@ extern struct nc_state_t nc_state;
static void bs_errors (const char * msg) {
// we normally do not care to print all messages from blobstore as many are errors that we can handle
- logprintfl (EUCADEBUG2, "{%u} blobstore: %s", (unsigned int)pthread_self(), msg);
+ logprintfl (EUCATRACE, "{%u} blobstore: %s", (unsigned int)pthread_self(), msg);
}
static void stat_blobstore (const char * conf_instances_path, const char * name, blobstore_meta * meta)
View
34 storage/blobstore.c
@@ -323,7 +323,7 @@ static int close_and_unlock (int fd)
int ret = 0;
{ // critical section
pthread_mutex_lock (&_blobstore_mutex); // grab global lock (we will not block below and we may be deallocating)
- logprintfl (EUCADEBUG2, "{%u} close_and_unlock: obtained global lock for closing of fd=%d\n", (unsigned int)pthread_self(), fd);
+ logprintfl (EUCATRACE, "{%u} close_and_unlock: obtained global lock for closing of fd=%d\n", (unsigned int)pthread_self(), fd);
blobstore_filelock * path_lock = NULL; // lock struct to which this fd belongs
int index = -1; // index of this fd entry in the lock struct
@@ -372,11 +372,11 @@ static int close_and_unlock (int fd)
* next_ptr = path_lock->next; // remove from LL
do_free = TRUE;
_locks_list_rem_ctr++;
- logprintfl (EUCADEBUG2, "{%u} close_and_unlock: unlocked and freed fd=%d path=%s\n",
+ logprintfl (EUCATRACE, "{%u} close_and_unlock: unlocked and freed fd=%d path=%s\n",
(unsigned int)pthread_self(), fd, path_lock->path);
} else {
- logprintfl (EUCADEBUG2, "{%u} close_and_unlock: kept fd=%d path=%d open/refs=%d/%d\n",
+ logprintfl (EUCATRACE, "{%u} close_and_unlock: kept fd=%d path=%d open/refs=%d/%d\n",
(unsigned int)pthread_self(), fd, path_lock->path, open_fds, path_lock->refs);
}
pthread_rwlock_unlock (&(path_lock->lock)); // give up the Posix lock
@@ -408,7 +408,7 @@ static int close_and_unlock (int fd)
else
_close_error_ctr++;
- logprintfl (EUCADEBUG2, "{%u} close_and_unlock: releasing global lock for closing of fd=%d ret=%d\n", (unsigned int)pthread_self(), fd, ret);
+ logprintfl (EUCATRACE, "{%u} close_and_unlock: releasing global lock for closing of fd=%d ret=%d\n", (unsigned int)pthread_self(), fd, ret);
pthread_mutex_unlock (&_blobstore_mutex);
} // end of critical section
@@ -521,7 +521,7 @@ static int open_and_lock (const char * path,
// open/create the file, using Posix file locks for inter-process locking
int fd = open (path, o_flags, mode);
- logprintfl (EUCADEBUG2, "{%u} open_and_lock: open fd=%d flags=%0x path=%s\n", (unsigned int)pthread_self(), fd, o_flags, path);
+ logprintfl (EUCATRACE, "{%u} open_and_lock: open fd=%d flags=%0x path=%s\n", (unsigned int)pthread_self(), fd, o_flags, path);
if (fd == -1) {
PROPAGATE_ERR (BLOBSTORE_ERROR_UNKNOWN);
goto error;
@@ -593,7 +593,7 @@ static int open_and_lock (const char * path,
pthread_mutex_unlock (&_blobstore_mutex);
goto error;
}
- logprintfl (EUCADEBUG2, "{%u} open_and_lock: could not acquire %s lock, sleeping on %s\n", (unsigned int)pthread_self(), (ret==0)?("file"):("posix"), path);
+ logprintfl (EUCATRACE, "{%u} open_and_lock: could not acquire %s lock, sleeping on %s\n", (unsigned int)pthread_self(), (ret==0)?("file"):("posix"), path);
usleep (BLOBSTORE_SLEEP_INTERVAL_USEC);
}
@@ -618,7 +618,7 @@ static int open_and_lock (const char * path,
struct flock l;
fcntl (fd, F_GETLK, flock_whole_file (&l, l_type));
- logprintfl (EUCADEBUG2, "{%u} open_and_lock: locked fd=%d path=%s flags=%d ino=%d mode=%0o [lock type=%d whence=%d start=%d length=%d]\n",
+ logprintfl (EUCATRACE, "{%u} open_and_lock: locked fd=%d path=%s flags=%d ino=%d mode=%0o [lock type=%d whence=%d start=%d length=%d]\n",
(unsigned int)pthread_self(), fd, path, o_flags, s.st_ino, s.st_mode, l.l_type, l.l_whence, l.l_start, l.l_len);
}
return fd;
@@ -669,11 +669,11 @@ static int open_and_lock (const char * path,
* next_ptr = path_lock->next; // remove from LL
do_free = TRUE;
_locks_list_rem_ctr++;
- logprintfl (EUCADEBUG2, "{%u} open_and_lock: freed fd=%d path=%s\n",
+ logprintfl (EUCATRACE, "{%u} open_and_lock: freed fd=%d path=%s\n",
(unsigned int)pthread_self(), fd, path_lock->path);
} else {
- logprintfl (EUCADEBUG2, "{%u} open_and_lock: kept fd=%d path=%d open/refs=%d/%d\n",
+ logprintfl (EUCATRACE, "{%u} open_and_lock: kept fd=%d path=%d open/refs=%d/%d\n",
(unsigned int)pthread_self(), fd, path_lock->path, open_fds, path_lock->refs);
}
@@ -992,7 +992,7 @@ int blobstore_lock ( blobstore * bs, long long timeout_usec)
char meta_path [PATH_MAX];
snprintf (meta_path, sizeof(meta_path), "%s/%s", bs->path, BLOBSTORE_METADATA_FILE);
- logprintfl (EUCADEBUG2, "{%u} blobstore_lock: called for %s\n", (unsigned int)pthread_self(), bs->path);
+ logprintfl (EUCATRACE, "{%u} blobstore_lock: called for %s\n", (unsigned int)pthread_self(), bs->path);
int fd = open_and_lock (meta_path, BLOBSTORE_FLAG_RDWR, timeout_usec, BLOBSTORE_FILE_PERM);
if (fd!=-1)
bs->fd = fd;
@@ -1004,7 +1004,7 @@ int blobstore_unlock ( blobstore * bs )
{
int fd = bs->fd;
bs->fd = -1;
- logprintfl (EUCADEBUG2, "{%u} blobstore_unlock: called for %s\n", (unsigned int)pthread_self(), bs->path);
+ logprintfl (EUCATRACE, "{%u} blobstore_unlock: called for %s\n", (unsigned int)pthread_self(), bs->path);
return close_and_unlock (fd);
}
@@ -1283,7 +1283,7 @@ static int read_array_blockblob_metadata_path (blockblob_path_t path_t, const bl
break;
}
- logprintfl(EUCADEBUG2, "%s => [%d] READ LINE %s rdLen %d, n %d\n", __func__, fd, line, rdLen, n);
+ logprintfl(EUCAEXTREME, "%s => [%d] READ LINE %s rdLen %d, n %d\n", __func__, fd, line, rdLen, n);
// Add one more entry to our metadata array
if((bigger_lines = realloc(lines, ((i + 1) * sizeof(char *)))) == NULL) {
@@ -2094,7 +2094,7 @@ blockblob * blockblob_open ( blobstore * bs,
return NULL;
}
- logprintfl (EUCADEBUG2, "{%u} blockblob_open: opening blob id=%s flags=%d timeout=%lld\n", (unsigned int)pthread_self(), id, flags, timeout_usec);
+ logprintfl (EUCATRACE, "{%u} blockblob_open: opening blob id=%s flags=%d timeout=%lld\n", (unsigned int)pthread_self(), id, flags, timeout_usec);
blockblob * bbs = NULL; // a temp LL of blockblobs, used for computing free space and for purging
blockblob * bb = calloc (1, sizeof (blockblob));
@@ -2350,9 +2350,9 @@ blockblob * blockblob_open ( blobstore * bs,
}
out:
- logprintfl (EUCADEBUG2, "{%u} blockblob_open: done with blob id=%s ret=%012lx\n", (unsigned int)pthread_self(), id, bb);
+ logprintfl (EUCATRACE, "{%u} blockblob_open: done with blob id=%s ret=%012lx\n", (unsigned int)pthread_self(), id, bb);
if (bb==NULL) {
- logprintfl (EUCADEBUG2, "{%u} blockblob_open: errno=%d msg=%s\n", (unsigned int)pthread_self(), _blobstore_errno, blobstore_get_last_msg());
+ logprintfl (EUCATRACE, "{%u} blockblob_open: errno=%d msg=%s\n", (unsigned int)pthread_self(), _blobstore_errno, blobstore_get_last_msg());
}
free_bbs (bbs);
@@ -2389,7 +2389,7 @@ int blockblob_close ( blockblob * bb )
return -1;
}
int ret = 0;
- logprintfl (EUCADEBUG2, "{%u} blockblob_close: closing blob id=%s\n", (unsigned int)pthread_self(), bb->id);
+ logprintfl (EUCATRACE, "{%u} blockblob_close: closing blob id=%s\n", (unsigned int)pthread_self(), bb->id);
// do not remove /dev/loop* if it is used by device mapper
// (we do not care about BLOCKBLOB_STATUS_OPENED because
@@ -4193,7 +4193,7 @@ int main (int argc, char ** argv)
getcwd (cwd, sizeof (cwd));
srandom (time(NULL));
- logfile (NULL, EUCADEBUG2, 4);
+ logfile (NULL, EUCATRACE, 4);
blobstore_set_error_function (dummy_err_fn);
// if an argument is specified, it is treated as a blob name to create
View
2  storage/vbr.c
@@ -1039,7 +1039,7 @@ void art_free (artifact * a) // frees the artifact and all its dependencies
for (int i = 0; i < MAX_ARTIFACT_DEPS && a->deps[i]; i++) {
art_free (a->deps[i]);
}
- logprintfl (EUCADEBUG2, "[%s] freeing artifact %03d|%s size=%lld vbr=%u cache=%d file=%d\n",
+ logprintfl (EUCATRACE, "[%s] freeing artifact %03d|%s size=%lld vbr=%u cache=%d file=%d\n",
a->instanceId, a->seq, a->id, a->size_bytes, a->vbr, a->may_be_cached, a->must_be_file);
free (a);
}
View
2  storage/walrus.c
@@ -245,7 +245,7 @@ static int walrus_request_timeout (const char * walrus_op, const char * verb, co
assert (strlen(cert64_str)+11<=BUFSIZE);
char cert_hdr [BUFSIZE];
snprintf (cert_hdr, BUFSIZE, "EucaCert: %s", cert64_str);
- logprintfl (EUCADEBUG2, "{%u} walrus_request: base64 certificate, %s\n", (unsigned int)pthread_self(), get_string_stats(cert64_str));
+ logprintfl (EUCATRACE, "{%u} walrus_request: base64 certificate, %s\n", (unsigned int)pthread_self(), get_string_stats(cert64_str));
headers = curl_slist_append (headers, cert_hdr);
free (cert64_str);
free (cert_str);
View
16 tools/eucalyptus.conf
@@ -26,13 +26,21 @@ CLOUD_OPTS=""
###########################################################################
# The level of logging output. Valid settings are, in descending order of
-# verbosity, DEBUG, INFO, WARN, ERROR, and FATAL. The default is DEBUG.
-LOGLEVEL="DEBUG"
+# verbosity: EXTREME, TRACE, DEBUG, INFO, WARN, ERROR, and FATAL. The
+# default is DEBUG.
+#LOGLEVEL="DEBUG".
-# The number of old log files to keep when rotating logs. The default
-# is 4.
+# The number of old log files to keep when rotating logs, in range [0-999].
+# The default is 4. When set to 0, no rotation is performed and log size
+# limit is (LOGMAXSIZE, below) is not enforced.
#LOGROLLNUMBER="4"
+# The maximum size of the log file, in bytes. 10MB by default. For this
+# size to be enforced, LOGROLLNUMBER, above, must be 1 or higher. If log
+# rotation is performed by an outside tool, either set LOGROLLNUMBER to 0
+# or set this limit to a large value.
+#LOGMAXSIZE=10485760
+
# On a NC, this defines the TCP port on which the NC will listen.
# On a CC, this defines the TCP port on which the CC will contact NCs.
NC_PORT="8775"
View
12 util/adb-helpers.h
@@ -203,17 +203,17 @@ static inline void copy_vm_type_from_adb (virtualMachine * params, adb_virtualMa
for (i = 0; i<EUCA_MAX_VBRS && i<params->virtualBootRecordLen; i++) {
adb_virtualBootRecordType_t * vbr_type = adb_virtualMachineType_get_virtualBootRecord_at (vm_type, env, i);
safe_strncpy (params->virtualBootRecord[i].resourceLocation, adb_virtualBootRecordType_get_resourceLocation(vbr_type, env), CHAR_BUFFER_SIZE);
- logprintfl (EUCADEBUG2, "resource location: %s\n", params->virtualBootRecord[i].resourceLocation);
+ logprintfl (EUCATRACE, "resource location: %s\n", params->virtualBootRecord[i].resourceLocation);
safe_strncpy (params->virtualBootRecord[i].guestDeviceName, adb_virtualBootRecordType_get_guestDeviceName(vbr_type, env), SMALL_CHAR_BUFFER_SIZE);
- logprintfl (EUCADEBUG2, " guest dev name: %s\n", params->virtualBootRecord[i].guestDeviceName);
+ logprintfl (EUCATRACE, " guest dev name: %s\n", params->virtualBootRecord[i].guestDeviceName);
params->virtualBootRecord[i].size = adb_virtualBootRecordType_get_size(vbr_type, env);
- logprintfl (EUCADEBUG2, " size: %d\n", params->virtualBootRecord[i].size);
+ logprintfl (EUCATRACE, " size: %d\n", params->virtualBootRecord[i].size);
safe_strncpy (params->virtualBootRecord[i].formatName, adb_virtualBootRecordType_get_format(vbr_type, env), SMALL_CHAR_BUFFER_SIZE);
- logprintfl (EUCADEBUG2, " format: %s\n", params->virtualBootRecord[i].formatName);
+ logprintfl (EUCATRACE, " format: %s\n", params->virtualBootRecord[i].formatName);
safe_strncpy (params->virtualBootRecord[i].id, adb_virtualBootRecordType_get_id(vbr_type, env), SMALL_CHAR_BUFFER_SIZE);
- logprintfl (EUCADEBUG2, " id: %s\n", params->virtualBootRecord[i].id);
+ logprintfl (EUCATRACE, " id: %s\n", params->virtualBootRecord[i].id);
safe_strncpy (params->virtualBootRecord[i].typeName, adb_virtualBootRecordType_get_type(vbr_type, env), SMALL_CHAR_BUFFER_SIZE);
- logprintfl (EUCADEBUG2, " type: %s\n", params->virtualBootRecord[i].typeName);
+ logprintfl (EUCATRACE, " type: %s\n", params->virtualBootRecord[i].typeName);
}
}
View
7 util/config.c
@@ -157,16 +157,17 @@ int readConfigFile(char configFiles[][MAX_PATH], int numFiles)
}
// helper for reading log-related params from eucalyptus.conf
-void configReadLogParams(int *log_level_out, int *log_roll_number_out, long *log_max_size_bytes_out)
+void configReadLogParams(int *log_level_out, int *log_roll_number_out, long *log_max_size_bytes_out, char **log_prefix)
{
char * s = configFileValue ("LOGLEVEL");
- // assert (s); // we should always have a value, from file or the default
+ assert (s!=NULL); // configFileValue should return default
* log_level_out = log_level_int (s);
- free (s);
long l;
configFileValueLong ("LOGROLLNUMBER", &l);
* log_roll_number_out = (int)l;
configFileValueLong ("LOGMAXSIZE", log_max_size_bytes_out);
+
+ * log_prefix = configFileValue ("LOGPREFIX");
}
View
2  util/config.h
@@ -36,6 +36,6 @@ char *configFileValue(const char *key);
int configFileValueLong(const char *key, long *val);
int isConfigModified (char configFiles[][MAX_PATH], int numFiles);
int readConfigFile(char configFiles[][MAX_PATH], int numFiles);
-void configReadLogParams(int *log_level_out, int *log_roll_number_out, long *log_max_size_bytes_out);
+void configReadLogParams(int *log_level_out, int *log_roll_number_out, long *log_max_size_bytes_out, char **log_prefix);
#endif /* CONFIG_H */
View
8 util/euca_auth.c
@@ -253,7 +253,7 @@ char * euca_sign_url (const char * verb, const char * date, const char * url)
logprintfl (EUCAERROR, "error: failed to open private key file %s\n", pk_file);
RSA_free (rsa);
} else {
- logprintfl (EUCADEBUG2, "euca_sign_url(): reading private key file %s\n", pk_file);
+ logprintfl (EUCATRACE, "euca_sign_url(): reading private key file %s\n", pk_file);
PEM_read_RSAPrivateKey(fp, &rsa, NULL, NULL); /* read the PEM-encoded file into rsa struct */
if ( rsa==NULL ) {
logprintfl (EUCAERROR, "error: failed to read private key file %s\n", pk_file);
@@ -273,14 +273,14 @@ char * euca_sign_url (const char * verb, const char * date, const char * url)
/* finally, SHA1 and sign with PK */
assert ((strlen(verb)+strlen(date)+strlen(url)+4)<=BUFSIZE);
snprintf (input, BUFSIZE, "%s\n%s\n%s\n", verb, date, url);
- logprintfl (EUCADEBUG2, "euca_sign_url(): signing input %s\n", get_string_stats(input));
+ logprintfl (EUCAEXTREME, "euca_sign_url(): signing input %s\n", get_string_stats(input));
SHA1 ((unsigned char *)input, strlen(input), sha1);
if ((ret = RSA_sign (NID_sha1, sha1, SHA_DIGEST_LENGTH, sig, &siglen, rsa))!=1) {
logprintfl (EUCAERROR, "error: RSA_sign() failed\n");
} else {
- logprintfl (EUCADEBUG2, "euca_sign_url(): signing output %d\n", sig[siglen-1]);
+ logprintfl (EUCAEXTREME, "euca_sign_url(): signing output %d\n", sig[siglen-1]);
sig_str = base64_enc (sig, siglen);
- logprintfl (EUCADEBUG2, "euca_sign_url(): base64 signature %s\n", get_string_stats((char *)sig_str));
+ logprintfl (EUCAEXTREME, "euca_sign_url(): base64 signature %s\n", get_string_stats((char *)sig_str));
}
free (sig);
}
View
68 util/fault.c
@@ -188,7 +188,7 @@ str_trim_suffix (char *str, const char *suffix)
} else {
int trim = strlen (str) - strlen (suffix);
*(str + trim) = '\0';
- PRINTF1 (("str_trim_suffix() returning: %s\n", str));
+ logprintfl (EUCATRACE, "str_trim_suffix() returning: %s\n", str);
}
return str;
}
@@ -244,13 +244,13 @@ is_suppressed_eucafault (const char *fault_id)
while (suppose) {
if (!strcmp (fault_id, suppose->id)) {
- PRINTF (("is_suppressed_eucafault() returning TRUE for %s.\n",
- fault_id));
+ logprintfl (EUCATRACE, "is_suppressed_eucafault() returning TRUE for %s.\n",
+ fault_id);
return TRUE;
}
suppose = suppose->next;
}
- PRINTF (("is_suppressed_eucafault() returning FALSE for %s.\n", fault_id));
+ logprintfl (EUCATRACE, "is_suppressed_eucafault() returning FALSE for %s.\n", fault_id);
return FALSE;
}
@@ -276,7 +276,7 @@ check_eucafault_suppression (const char *fault_id, const char *fault_file)
return is_suppressed_eucafault (fault_id);
} else {
if (is_suppressed_eucafault (fault_id)) {
- PRINTF (("Detected already-suppressed fault id %s\n", fault_id));
+ logprintfl (EUCATRACE, "Detected already-suppressed fault id %s\n", fault_id);
return TRUE;
}
struct stat st;
@@ -308,8 +308,8 @@ check_eucafault_suppression (const char *fault_id, const char *fault_file)
return FALSE;
}
}
- PRINTF (("check_eucafault_suppression() returning FALSE for %s, %s\n",
- fault_id, fault_file));
+ logprintfl (EUCATRACE, "check_eucafault_suppression() returning FALSE for %s, %s\n",
+ fault_id, fault_file);
return FALSE;
}
@@ -326,15 +326,15 @@ read_eucafault (const char *faultdir, const char *fault_id)
static int common_block_exists = 0;
snprintf (fault_file, PATH_MAX, "%s/%s%s", faultdir, fault_id, XML_SUFFIX);
- PRINTF (("Attempting to load file %s\n", fault_file));
+ logprintfl (EUCATRACE, "Attempting to load file %s\n", fault_file);
if (get_eucafault (fault_id, NULL) != NULL) {
- PRINTF (("Looks like fault %s already exists.\n", fault_id));
+ logprintfl (EUCATRACE, "Looks like fault %s already exists.\n", fault_id);
return NULL;
}
if (check_eucafault_suppression (fault_id, fault_file)) {
- PRINTF (("Looks like fault %s is being deliberately suppressed.\n",
- fault_id));
+ logprintfl (EUCATRACE, "Looks like fault %s is being deliberately suppressed.\n",
+ fault_id);
return NULL;
}
my_doc = xmlParseFile (fault_file);
@@ -344,15 +344,15 @@ read_eucafault (const char *faultdir, const char *fault_id)
fault_file);
return NULL;
} else {
- PRINTF1 (("Successfully parsed file %s in read_eucafault()\n",
- fault_file));
+ logprintfl (EUCATRACE, "Successfully parsed file %s in read_eucafault()\n",
+ fault_file);
}
if (get_eucafault (fault_id, my_doc) != NULL) {
- PRINTF (("Found fault id %s in %s\n", fault_id, fault_file));
+ logprintfl (EUCATRACE, "Found fault id %s in %s\n", fault_id, fault_file);
} else if (get_common_block (my_doc) != NULL) {
- PRINTF (("Found <%s> block in %s\n", COMMON_PREFIX, fault_file));
+ logprintfl (EUCATRACE, "Found <%s> block in %s\n", COMMON_PREFIX, fault_file);
if (common_block_exists++) {
- PRINTF (("<%s> block already exists--skipping.\n", COMMON_PREFIX));
+ logprintfl (EUCATRACE, "<%s> block already exists--skipping.\n", COMMON_PREFIX);
xmlFreeDoc (my_doc);
return NULL;
}
@@ -374,7 +374,7 @@ static boolean
add_eucafault (const xmlDoc *new_doc)
{
if (xmlDocGetRootElement (ef_doc) == NULL) {
- PRINTF1 (("Creating new document.\n"));
+ logprintfl (EUCATRACE, "Creating new document.\n");
ef_doc = xmlCopyDoc ((xmlDoc *)new_doc, 1); /* 1 == recursive copy */
if (ef_doc == NULL) {
@@ -382,7 +382,7 @@ add_eucafault (const xmlDoc *new_doc)
return FALSE;
}
} else {
- PRINTF1 (("Appending to existing document.\n"));
+ logprintfl (EUCATRACE, "Appending to existing document.\n");
if (xmlAddNextSibling (xmlFirstElementChild (xmlDocGetRootElement (ef_doc)),
xmlFirstElementChild (xmlDocGetRootElement ((xmlDoc *)new_doc))) == NULL) {
logprintfl (EUCAERROR, "Problem adding fault to existing registry.\n");
@@ -432,7 +432,7 @@ get_common_block (const xmlDoc *doc)
if (node->type == XML_ELEMENT_NODE) {
if (!strcasecmp ((const char *)node->name, COMMON_PREFIX)) {
- PRINTF1 (("Found <%s> block.\n", COMMON_PREFIX));
+ logprintfl (EUCATRACE, "Found <%s> block.\n", COMMON_PREFIX);
return node;
}
}
@@ -506,7 +506,7 @@ initialize_faultlog (const char *fileprefix)
snprintf (faultlogpath, PATH_MAX, EUCALYPTUS_LOG_DIR "/%s"
FAULT_LOGFILE_SUFFIX, euca_base, fileprefix);
}
- PRINTF (("Initializing faultlog using %s\n", faultlogpath));
+ logprintfl (EUCATRACE, "Initializing faultlog using %s\n", faultlogpath);
faultlog = fopen (faultlogpath, "a+");
if (faultlog == NULL) {
@@ -541,7 +541,7 @@ init_eucafaults (char *fileprefix)
pthread_mutex_lock (&fault_mutex);
if (faults_loaded) {
- PRINTF1 (("Attempt to reinitialize fault registry? Skipping...\n"));
+ logprintfl (EUCATRACE, "Attempt to reinitialize fault registry? Skipping...\n");
pthread_mutex_unlock (&fault_mutex);
return -faults_loaded; // Negative return because already loaded.
}
@@ -553,7 +553,7 @@ init_eucafaults (char *fileprefix)
}
initialize_faultlog (fileprefix);
- PRINTF (("Initializing fault registry directories.\n"));
+ logprintfl (EUCATRACE, "Initializing fault registry directories.\n");
if ((locale = getenv (LOCALIZATION_ENV_VAR)) == NULL) {
logprintfl (EUCAINFO,
@@ -595,10 +595,10 @@ init_eucafaults (char *fileprefix)
int numfaults = scandir (faultdirs[i], &namelist, &scandir_filter,
alphasort);
if (numfaults == 0) {
- PRINTF (("No faults found in %s\n", faultdirs[i]));
+ logprintfl (EUCADEBUG, "No faults found in %s\n", faultdirs[i]);
} else {
- PRINTF (("Found %d %s files in %s\n", numfaults, XML_SUFFIX,
- faultdirs[i]));
+ logprintfl (EUCADEBUG, "Found %d %s files in %s\n", numfaults, XML_SUFFIX,
+ faultdirs[i]);
while (numfaults--) {
xmlDoc *new_fault = read_eucafault (faultdirs[i], str_trim_suffix (namelist[numfaults]->d_name, XML_SUFFIX));
free (namelist[numfaults]);
@@ -609,7 +609,7 @@ init_eucafaults (char *fileprefix)
}
xmlFreeDoc (new_fault);
} else {
- PRINTF1 (("Not adding new fault--mismatch or already exists...?\n"));
+ logprintfl (EUCATRACE, "Not adding new fault--mismatch or already exists...?\n");
}
}
free (namelist);
@@ -856,7 +856,7 @@ log_eucafault_map (const char *fault_id, const char_map **map)
{
int load = init_eucafaults (NULL);
- PRINTF1 (("init_eucafaults() returned %d\n", load));
+ logprintfl (EUCATRACE, "init_eucafaults() returned %d\n", load);
if (is_suppressed_eucafault (fault_id)) {
logprintfl (EUCADEBUG, "Fault %s detected, but it is being actively suppressed.\n", fault_id);
@@ -883,7 +883,7 @@ log_eucafault (const char *fault_id, ...)
int count = 0;
int load = init_eucafaults (NULL);
- PRINTF1 (("init_eucafaults() returned %d\n", load));
+ logprintfl (EUCATRACE, "init_eucafaults() returned %d\n", load);
va_start (argv, fault_id);
while ((token[count % 2] = va_arg (argv, char *)) != NULL) {
@@ -898,7 +898,7 @@ log_eucafault (const char *fault_id, ...)
logprintfl (EUCAWARN, "log_eucafault() called with an odd (unmatched) number of substitution parameters: %d\n", count);
}
if (!log_eucafault_map (fault_id, (const char_map **)m)) {
- PRINTF (("log_eucafault_map() returned FALSE inside log_eucafault()\n"));
+ logprintfl (EUCADEBUG, "log_eucafault_map() returned FALSE inside log_eucafault()\n");
count *= -1;
}
c_varmap_free (m);
@@ -956,14 +956,14 @@ main (int argc, char **argv)
// logfile.
opt = init_eucafaults (NULL);
- PRINTF (("init_eucafaults() returned %d\n", opt));
+ logprintfl (EUCADEBUG, "init_eucafaults() returned %d\n", opt);
if (optind < argc) {
char_map **m = c_varmap_alloc (NULL, "daemon", "Balrog");
m = c_varmap_alloc (m, "hostIp", "127.0.0.1");
m = c_varmap_alloc (m, "brokerIp", "127.0.0.2");
m = c_varmap_alloc (m, "endpointIp", "127.0.0.3");
- PRINTF1 (("argv[1st of %d]: %s\n", argc - optind, argv[optind]));
+ logprintfl (EUCATRACE, "argv[1st of %d]: %s\n", argc - optind, argv[optind]);
log_eucafault_map (argv[optind], (const char_map **)m);
c_varmap_free (m);
@@ -976,15 +976,15 @@ main (int argc, char **argv)
"brokerIp", "127.0.0.2",
"endpointIp", "127.0.0.3",
"unmatched!", NULL);
- PRINTF (("log_eucafault args returned: %d\n", opt));
+ logprintfl (EUCADEBUG, "log_eucafault args returned: %d\n", opt);
// This allows substitution-argument pairs for unit test to be
// passed in on command line.
m = NULL;
for (opt = optind + 1; opt < argc; opt++) {
- PRINTF1 (("argv[opt]: %s\n", argv[opt]));
+ logprintfl (EUCATRACE, "argv[opt]: %s\n", argv[opt]);
if ((opt - optind + 1) % 2) {
- PRINTF1 (("...now have two, calling c_varmap_alloc()\n"));
+ logprintfl (EUCATRACE, "...now have two, calling c_varmap_alloc()\n");
m = c_varmap_alloc (m, argv[opt - 1], argv[opt]);
}
}
View
40 util/ipc.c
@@ -154,12 +154,19 @@ sem * sem_alloc_posix (sem_t * external_lock)
return s;
}
-int sem_p (sem * s)
+// Semaphore increment (aka lock acquisition) function.
+// The second parameter tells it not to log the event
+// (useful for avoiding infinite recursion when locking
+// from the logging code).
+int sem_prolaag (sem * s, boolean do_log)
{
int rc;
-
- if (s)
- logprintfl (EUCADEBUG2, "sem_p() %s\n", (s->name)?(s->name):(""));
+
+ if (s && do_log) {
+ char addr [24];
+ snprintf (addr, sizeof (addr), "%lx", (unsigned long)s);
+ logprintfl (EUCAEXTREME, "%s locking\n", (s->name)?(s->name):(addr));
+ }
if (s && s->usemutex) {
rc = pthread_mutex_lock(&(s->mutex));
@@ -185,12 +192,25 @@ int sem_p (sem * s)
return -1;
}
-int sem_v (sem * s)
+// The semaphore increment (aka lock acquisition) function used throughout.
+int sem_p (sem * s)
+{
+ return sem_prolaag (s, TRUE);
+}
+
+// Semaphore decrement (aka lock release) function.
+// The second parameter tells it not to log the event
+// (useful for avoiding infinite recursion when unlocking
+// from the logging code).
+int sem_verhogen (sem * s, boolean do_log)
{
int rc;
- if (s)
- logprintfl (EUCADEBUG2, "sem_v() %s\n", (s->name)?(s->name):(""));
+ if (s && do_log) {
+ char addr [24];
+ snprintf (addr, sizeof (addr), "%lx", (unsigned long)s);
+ logprintfl (EUCAEXTREME, "%s unlocking\n", (s->name)?(s->name):(addr));
+ }
if (s && s->usemutex) {
rc = pthread_mutex_lock(&(s->mutex));
@@ -214,6 +234,12 @@ int sem_v (sem * s)
return -1;
}
+// The semaphore decrement (aka lock release) function used throughout.
+int sem_v (sem * s)
+{
+ return sem_verhogen (s, TRUE);
+}
+
void sem_free (sem * s)
{
DECLARE_ARG;
View
4 util/ipc.h
@@ -68,6 +68,8 @@
#include <semaphore.h>
#include <pthread.h>
+#include "misc.h" // boolean
+
typedef struct sem_struct {
int sysv;
sem_t * posix;
@@ -81,7 +83,9 @@ typedef struct sem_struct {
sem * sem_realloc (const int val, const char * name, const int flags);
sem * sem_alloc (const int val, const char * name);
sem * sem_alloc_posix (sem_t * external_lock);
+int sem_prolaag (sem * s, boolean do_log);
int sem_p (sem * s);
+int sem_verhogen (sem * s, boolean do_log);
int sem_v (sem * s);
void sem_free (sem * s);
View
444 util/log.c
@@ -77,19 +77,42 @@
#include "eucalyptus.h"
#include "log.h"
-
-#define BUFSIZE 1024
-
-static int timelog=0; /* change to 1 for TIMELOG entries */
-static int logging=0;
-static FILE *LOGFH=NULL;
-static char logFile[EUCA_MAX_PATH];
-
-#define DEFAULT_LOG_LEVEL EUCADEBUG
+#include "misc.h" // TRUE/FALSE
+#include "ipc.h" // semaphores
+
+#define LOGLINEBUF 101024 // enough for a log line, hopefully
+#define MAX_FIELD_LENGTH 100 // any prefix value beyond this will be truncated, even if in spec
+#define DEFAULT_LOG_LEVEL 3 // log level if none is specified (3==DEBUG)
+#define LOGFH_DEFAULT stdout // without a file, this is where log output goes
+
+// the log file stream that will remain open:
+// - unless do_close_fd==TRUE
+// - unless log file is moved or removed
+// - unless log file becomes too big and rolls over
+static FILE * LOGFH = NULL;
+static ino_t log_ino = -1; // the current inode
+
+// parameters, for now unmodifiable
+static const boolean timelog = FALSE; // change to TRUE for 'TIMELOG' entries
+static const boolean do_close_fd = FALSE; // whether to close log fd after each message
+static const boolean do_stat_log = TRUE; // whether to monitor file for changes
+
+// these can be modified through setters
static int log_level=DEFAULT_LOG_LEVEL;
static int log_roll_number=4;
static long log_max_size_bytes=MAXLOGFILESIZE;
-
+static char log_file_path [EUCA_MAX_PATH] = "";
+static char log_custom_prefix [34] = ""; // non-empty if a custom prefix was specified
+static sem * log_sem = NULL; // if set, the semaphore will be used when logging & rotating logs
+
+// these are set by _EUCA_CONTEXT_SETTER, which is included in log-level macros, such as EUCAWARN
+__thread const char * _log_curr_method = "";
+__thread const char * _log_curr_file = "";
+__thread int _log_curr_line = 0;
+
+// returns log level as integer given the name or
+// -1 if the name is not valid
+// (used for parsing the setting in the config file)
int log_level_int (const char * level)
{
for (int l=0; l<=EUCAOFF; l++) {
@@ -100,64 +123,117 @@ int log_level_int (const char * level)
return -1;
}
-// log getter, which implements log rotation logic
-FILE * get_file (void)
+// Log FILE pointer getter, which implements log rotation logic
+// and tries to recover from log file being moved away, perhaps
+// by an external log rotation tool.
+//
+// The log file gets re-opened if it is currently closed or if
+// reopening is explicitly requested (do_reopen==TRUE). In case
+// of failure, returns NULL.
+//
+// To avoid unpredictable behavior due to concurrency,
+// this function should be called while holding a lock.
+static FILE * get_file (boolean do_reopen)
{
- FILE *file = LOGFH;
- int fd = fileno(file);
- if (fd < 1)
- return file;
-
+ // no log file has been set
+ if (strlen (log_file_path) == 0)
+ return LOGFH_DEFAULT;
+
+ int fd = -1;
+ if (LOGFH != NULL) { // apparently the stream is still open
+ boolean file_changed = FALSE;
+ if (! do_reopen && do_stat_log) { // we are not reopening for every write
+ struct stat statbuf;
+ int err = stat (log_file_path, &statbuf);
+ if (err == -1) { // probably file does not exist, perhaps because it was renamed
+ file_changed = TRUE;
+ } else if (log_ino != statbuf.st_ino) { // inode change, reopen just in case
+ file_changed = TRUE;
+ }
+ }
+ fd = fileno (LOGFH); // try to get the file descriptor
+ if (file_changed || do_reopen || fd < 0) {
+ fclose (LOGFH);
+ LOGFH = NULL;
+ }
+ }
+
+ retry:
+
+ // open unless it is already is open
+ if (LOGFH == NULL) {
+ LOGFH = fopen (log_file_path, "a+");
+ if (LOGFH == NULL) {
+ return NULL;
+ }
+ fd = fileno (LOGFH);
+ if (fd < 0) {
+ fclose (LOGFH);
+ LOGFH = NULL;
+ return NULL;
+ }
+ }
+
+ // see if it is time to rotate the log
struct stat statbuf;
- int rc = fstat(fd, &statbuf);
- if (!rc && ((int)statbuf.st_size > log_max_size_bytes)) {
- int i;
- char oldFile[EUCA_MAX_PATH], newFile[EUCA_MAX_PATH];
-
- rc = stat(logFile, &statbuf);
- if (!rc && ((int)statbuf.st_size > log_max_size_bytes)) {
- for (i=log_roll_number-1; i>=0; i--) {
- snprintf(oldFile, EUCA_MAX_PATH, "%s.%d", logFile, i);
- snprintf(newFile, EUCA_MAX_PATH, "%s.%d", logFile, i+1);
+ int rc = fstat (fd, &statbuf);
+ if (!rc) {
+ log_ino = statbuf.st_ino; // record the inode number of the currently opened log
+
+ if (((long)statbuf.st_size > log_max_size_bytes) && (log_roll_number > 0)) {
+ char oldFile[EUCA_MAX_PATH], newFile[EUCA_MAX_PATH];
+ for (int i=log_roll_number-1; i>0; i--) {
+ snprintf(oldFile, EUCA_MAX_PATH, "%s.%d", log_file_path, i-1);
+ snprintf(newFile, EUCA_MAX_PATH, "%s.%d", log_file_path, i);
rename(oldFile, newFile);
}
- snprintf(oldFile, EUCA_MAX_PATH, "%s", logFile);
- snprintf(newFile, EUCA_MAX_PATH, "%s.%d", logFile, 0);
+ snprintf(oldFile, EUCA_MAX_PATH, "%s", log_file_path);
+ snprintf(newFile, EUCA_MAX_PATH, "%s.%d", log_file_path, 0);
rename(oldFile, newFile);
- }
- fclose(LOGFH);
- LOGFH = fopen(logFile, "a");
- if (LOGFH) {
- file = LOGFH;
- } else {
- file = stdout;
+ fclose (LOGFH);
+ LOGFH = NULL;
+ goto retry;
}
}
- return file;
+ return LOGFH;
+}
+
+// Log FILE pointer release. Should be called with a lock
+// held in multi-threaded context.
+static void release_file (void)
+{
+ if (do_close_fd && LOGFH != NULL) {
+ fclose (LOGFH);
+ LOGFH = NULL;
+ }
}
// setter for logging parameters except file path
void log_params_set(int log_level_in, int log_roll_number_in, long log_max_size_bytes_in)
{
+ // update the log level
if (log_level_in >= EUCAALL && log_level_in <= EUCAOFF) {
log_level = log_level_in;
} else {
log_level = DEFAULT_LOG_LEVEL;
}
- if (log_roll_number_in > 0 &&
- log_roll_number_in < 100 &&
+ // update the roll number limit
+ if (log_roll_number_in >= 0 && // sanity check
+ log_roll_number_in < 1000 && // sanity check
log_roll_number != log_roll_number_in) {
log_roll_number = log_roll_number_in;
}
-
+
+ // update the max size for any file
if (log_max_size_bytes_in > 0 &&
log_max_size_bytes != log_max_size_bytes_in) {
log_max_size_bytes = log_max_size_bytes_in;
- get_file(); // that will rotate log files if needed
+ if (get_file(FALSE)) // that will rotate log files if needed
+ release_file();
}
}
@@ -171,23 +247,48 @@ void log_params_get(int *log_level_out, int *log_roll_number_out, long *log_max_
int log_file_set(const char * file)
{
- logging = 0;
+ if (file==NULL) { // NULL means standard output
+ log_file_path [0] = '\0';
+ return 0;
+ }
+
+ if (strcmp (log_file_path, file) == 0) // hasn't changed
+ return 0;
- if (LOGFH != NULL) {
- fclose(LOGFH);
+ strncpy (log_file_path, file, EUCA_MAX_PATH);
+ if (get_file (TRUE) == NULL) {
+ return 1;
}
+ release_file();
+ return 0;
+}
- if (file == NULL) {
- LOGFH = NULL;
- } else {
- snprintf(logFile, EUCA_MAX_PATH, "%s", file);
- LOGFH = fopen(file, "a");
- if (LOGFH) {
- logging=1;
+int log_prefix_set (const char * log_spec)
+{
+ if (log_spec==NULL)
+ log_custom_prefix [0] = '\0';
+ else
+ strncpy (log_custom_prefix, log_spec, sizeof (log_custom_prefix));
+ return 0;
+}
+
+int log_sem_set (sem * s)
+{
+ if (s==NULL)
+ return 1;
+
+ if (log_sem!=NULL) {
+ sem * old_log_sem = log_sem;
+ sem_p (old_log_sem);
+ if (log_sem != s) {
+ log_sem = s;
}
+ sem_v (old_log_sem);
+ } else {
+ log_sem = s;
}
-
- return (1-logging);
+
+ return 0;
}
int logfile(char *file, int log_level_in, int log_roll_number_in) // TODO: legacy function, to be removed when no longer in use
@@ -196,101 +297,212 @@ int logfile(char *file, int log_level_in, int log_roll_number_in) // TODO: legac
return log_file_set (file);
}
-// print timestamp in YYYY-MM-DD HH:MM:SS format
-static void print_timestamp (FILE * file)
+// Print timestamp in YYYY-MM-DD HH:MM:SS format.
+// Returns number of characters that it took up or
+// 0 on error.
+static int fill_timestamp (char * buf, int buf_size)
{
time_t t = time (NULL);
struct tm tm;
- gmtime_r(&t, &tm);
- char buf[27];
- if (strftime (buf, sizeof(buf), "%F %T", &tm)) {
- fprintf(file, "%s ", buf);
- }
+ localtime_r(&t, &tm);
+ return strftime (buf, buf_size, "%F %T", &tm);
}
-int logprintf(const char *format, ...)
+// This is the function that ultimately dumps a buffer into a log.
+static int log_line (const char * line)
{
- va_list ap;
- int rc;
- char buf[27], *eol;
- time_t t;
- FILE *file;
+ int rc = 1;
+
+ if (log_sem)
+ sem_prolaag (log_sem, FALSE);
+
+ FILE * file = get_file (FALSE);
+ if (file != NULL) {
+ fprintf(file, "%s", line);
+ fflush(file);
+ release_file();
+ rc = 0;
+ }
+
+ if (log_sem)
+ sem_verhogen (log_sem, FALSE);
- rc = 1;
- va_start(ap, format);
+ return rc;
+}
- if (logging) {
- file = LOGFH;
- } else {
- file = stdout;
- }
+// Log-printing function without a specific log level.
+// It is essentially printf() that will go verbatim,
+// with just timestamp as prefix and at any log level,
+// into the current log or stdout, if no log was open.
+int logprintf (const char *format, ...)
+{
+ char buf [LOGLINEBUF];
- print_timestamp (file);
- rc = vfprintf(file, format, ap);
- fflush(file);
+ // start with current timestamp
+ int offset = fill_timestamp (buf, sizeof (buf));
+ // append the log message passed via va_list
+ va_list ap;
+ va_start(ap, format);
+ int rc = vsnprintf (buf + offset, sizeof (buf) - offset - 1, format, ap);
va_end(ap);
- return(rc);
+ if (rc<0)
+ return rc;
+
+ return log_line (buf);
}
-int logprintfl(int level, const char *format, ...)
+static int print_field_truncated (char ** log_spec, char * buf, int left, const char * field)
{
- va_list ap;
- int rc, fd;
- FILE *file;
-
- if (level < log_level) {
- return (0);
+ boolean left_justify = FALSE;
+ int in_field_len = strlen (field);
+ int out_field_len = MAX_FIELD_LENGTH;
+ if (in_field_len < out_field_len) {
+ out_field_len = in_field_len; // unless specified, we'll use length of the field or max
}
- rc = 1;
- va_start(ap, format);
+ // first, look ahead down s[] to see if we have length
+ // and alignment specified (leading '-' means left-justified)
+ char * nstart = (* log_spec) + 1;
+ if (* nstart == '-') { // a leading zero
+ left_justify = TRUE;
+ nstart++;
+ }
+ char * nend;
+ int i = (int) strtoll (nstart, &nend, 10);
+ if (nstart != nend) { // we have some digits
+ * log_spec = nend - 1; // move the pointer ahead so caller will skip digits
+ if (i > 1 && i <100) { // sanity check
+ out_field_len = i;
+ }
+ }
- if (logging) {
- file = get_file();
- } else {
- file = stderr;
+ // create a format string that would truncate the field
+ // to len and then print the field into 's'
+ if (left < (out_field_len + 1)) { // not enough room left
+ return -1;
}
- print_timestamp (file);
+ // when right-justifying, we want to truncate the field on the left
+ // (when left-justifying the snprintf below will truncate on the right)
+ int offset = 0;
+ if (left_justify == FALSE) {
+ offset = in_field_len - out_field_len;
+ if (offset < 0)
+ offset = 0;
+ }
+ char format [10];
+ snprintf (format, sizeof (format), "%%%s%ds", (left_justify) ? "-" : "", out_field_len);
+ if (snprintf (buf, (out_field_len + 1), format, field + offset) < out_field_len)
+ return -1; // error in snprintf
+
+ return out_field_len;
+}
- // log level, a 5-char field, indented to the right
- if (level == EUCATRACE) { fprintf (file, "%s", "TRACE");}
- else if (level == EUCADEBUG3) { fprintf (file, "%s", "DBUG3");}
- else if (level == EUCADEBUG2) { fprintf (file, "%s", "DBUG2");}
- else if (level == EUCADEBUG) { fprintf (file, "%s", "DEBUG");}
- else if (level == EUCAINFO) { fprintf (file, "%s", " INFO");}
- else if (level == EUCAWARN) { fprintf (file, "%s", " WARN");}
- else if (level == EUCAERROR) { fprintf (file, "%s", "ERROR");}
- else if (level == EUCAFATAL) { fprintf (file, "%s", "FATAL");}
- else { fprintf (file, "%s", "?????");}
+// Main log-printing function, which will dump a line into
+// a log, with a prefix appropriate for the log level, given
+// that the log level is above the threshold.
+int logprintfl (int level, const char *format, ...)
+{
+ // return if level is invalid or below the threshold
+ if (level < log_level) {
+ return 0;
+ } else if (level < 0 || level > EUCAOFF) {
+ return -1; // unexpected log level
+ }
- // the PID and thread ID
- fprintf (file, " %06d:%06d", getpid(), (pid_t) syscall (SYS_gettid));
+ char buf [LOGLINEBUF];
+ int offset = 0;
+
+ // go over prefix format for the log level (defined in log.h)
+ for (char * prefix_spec = (strlen(log_custom_prefix) > 0) ? log_custom_prefix : log_level_prefix [log_level];
+ * prefix_spec != '\0';
+ prefix_spec++) {
+
+ char * s = buf + offset;
+ int left = sizeof (buf) - offset - 1;
+ if (left < 1) {
+ return -1; // not enough room in internal buffer for a prefix
+ }
+
+ int size = 0;
+ switch (* prefix_spec) {
+ case 'T': // timestamp
+ size = fill_timestamp (s, left);
+ break;
- // last thing - the separator from free-form part of the log message
- fprintf (file, " | ");
+ case 'L': { // log-level
+ char l [6];
+ safe_strncpy (l, log_level_names [level], 6); // we want hard truncation
+ size = snprintf (s, left, "%5s", l);
+ break;
+ }
+ case 'p': { // process ID
+ char p [11];
+ snprintf (p, sizeof (p), "%010d", getpid()); // 10 chars is enough for max 32-bit unsigned integer
+ size = print_field_truncated (&prefix_spec, s, left, p);
+ break;
+ }
+ case 't': { // thread ID
+ char t [21];
+ snprintf (t, sizeof (t), "%020d", (pid_t) syscall (SYS_gettid)); // 20 chars is enough for max 64-bit unsigned integer
+ size = print_field_truncated (&prefix_spec, s, left, t);
+ break;
+ }
+ case 'm': // method
+ size = print_field_truncated (&prefix_spec, s, left, _log_curr_method);
+ break;
- rc = vfprintf(file, format, ap);
- fflush(file);
+ case 'F': { // file-and-line
+ char file_and_line [64];
+ snprintf (file_and_line, sizeof (file_and_line), "%s:%d", _log_curr_file, _log_curr_line);
+ size = print_field_truncated (&prefix_spec, s, left, file_and_line);
+ break;
+ }
+ case '?':
+ s [0] = '?'; // not supported currently
+ s [1] = '\0';
+ size = 1;
+ break;
+ default:
+ s [0] = * prefix_spec;
+ s [1] = '\0';
+ size = 1;
+ }
+
+ if (size < 0) {
+ logprintf ("error in prefix construction in logprintfl()\n");
+ return -1; // something went wrong in the snprintf()s above
+ }
+ offset += size;
+ }
+
+ // append the log message passed via va_list
+ va_list ap;
+ va_start(ap, format);
+ int rc = vsnprintf (buf + offset, sizeof (buf) - offset - 1, format, ap);
va_end(ap);
- return(rc);
+ if (rc<0)
+ return rc;
+
+ return log_line (buf);
}
-/* prints contents of a file with logprintf */
-int logcat (int debug_level, const char * file_name)
+// prints contents of an arbitrary file (at file_path)
+// using logprintfl, thus dumping its contents into a log
+int logcat (int debug_level, const char * file_path)
{
int got = 0;
- char buf [BUFSIZE];
+ char buf [LOGLINEBUF];
- FILE *fp = fopen (file_name, "r");
+ FILE *fp = fopen (file_path, "r");
if (!fp) return got;
- while ( fgets (buf, BUFSIZE, fp) ) {
+ while ( fgets (buf, LOGLINEBUF, fp) ) {
int l = strlen (buf);
if ( l<0 )
break;
- if ( l+1<BUFSIZE && buf[l-1]!='\n' ) {
+ if ( l+1<LOGLINEBUF && buf[l-1]!='\n' ) {
buf [l++] = '\n';
buf [l] = '\0';
}
@@ -298,9 +510,13 @@ int logcat (int debug_level, const char * file_name)
got += l;
}
fclose (fp);
+
return got;
}
+// eventlog() was used for some timing measurements, almost exclusively from
+// server-marshal.c, where SOAP requests are getting unmarshalled and mashalled.
+// May be considered a legacy function, given no current need for the measurements.
void eventlog(char *hostTag, char *userTag, char *cid, char *eventTag, char *other)
{
double ts;
View
56 util/log.h
@@ -66,24 +66,28 @@
#ifndef LOG_H
#define LOG_H
-enum {
- EUCAALL=0,
- EUCATRACE,
- EUCADEBUG3,
- EUCADEBUG2,
- EUCADEBUG,
- EUCAINFO,
- EUCAWARN,
- EUCAERROR,
- EUCAFATAL,
- EUCAOFF
-};
+extern __thread const char * _log_curr_method;
+extern __thread const char * _log_curr_file;
+extern __thread int _log_curr_line;
+
+#define _EUCA_CONTEXT_SETTER (_log_curr_method=__FUNCTION__,\
+ _log_curr_file=__FILE__,\
+ _log_curr_line=__LINE__)
+
+#define EUCAALL 0
+#define EUCAEXTREME (_EUCA_CONTEXT_SETTER, 1)
+#define EUCATRACE (_EUCA_CONTEXT_SETTER, 2)
+#define EUCADEBUG (_EUCA_CONTEXT_SETTER, 3)
+#define EUCAINFO (_EUCA_CONTEXT_SETTER, 4)
+#define EUCAWARN (_EUCA_CONTEXT_SETTER, 5)
+#define EUCAERROR (_EUCA_CONTEXT_SETTER, 6)
+#define EUCAFATAL (_EUCA_CONTEXT_SETTER, 7)
+#define EUCAOFF 8
static char * log_level_names [] = {
"ALL",
+ "EXTREME",
"TRACE",
- "DEBUG3",
- "DEBUG2",
"DEBUG",
"INFO",
"WARN",
@@ -92,6 +96,29 @@ static char * log_level_names [] = {
"OFF"
};
+/////////////////////// prefix format
+// T = timestamp
+// L = loglevel
+// p = PID
+// t = thread id (same as PID in CC)
+// m = method
+// F = file:line_no
+//
+// p,t,m,F may be followed by (-)NNN,
+// '-' means left-justified
+// and NNN is max field size
+/////////////////////////////////////
+static char * log_level_prefix [] = {
+ "",
+ "T L t9 m-24 | ",
+ "T L t9 m-24 | ",
+ "T L t9 m-24 | ",
+ "T L | ",
+ "T L | ",
+ "T L | ",
+ ""
+};
+
#ifdef DEBUG
#define PRINTF(a) logprintf a
#else
@@ -114,6 +141,7 @@ int log_level_int(const char *level);
void log_params_set(int log_level_in, int log_roll_number_in, long log_max_size_bytes_in);
void log_params_get(int *log_level_out, int *log_roll_number_out, long *log_max_size_bytes_out);
int log_file_set(const char * file);
+int log_prefix_set (const char * log_spec);
int logfile(char *file, int in_loglevel, int in_logrollnumber);
int logprintf(const char *format, ...);
int logprintfl(int level, const char *format, ...);
View
10 util/misc.c
@@ -183,9 +183,9 @@ int verify_helpers (char **helpers, char **helpers_path, int num_helpers)
if (!done) {
missing_helpers++;
- logprintfl (EUCADEBUG2, "did not find '%s' in path\n", helpers[i]);
+ logprintfl (EUCATRACE, "did not find '%s' in path\n", helpers[i]);
} else {
- logprintfl (EUCADEBUG2, "found '%s' at '%s'\n", helpers[i], tmp_helpers_path[i]);
+ logprintfl (EUCATRACE, "found '%s' at '%s'\n", helpers[i], tmp_helpers_path[i]);
}
}
@@ -614,7 +614,7 @@ char * fp2str (FILE * fp)
memset(new_buf+buf_current, 0, INCREMENT * sizeof(char));
buf = new_buf;
- logprintfl (EUCADEBUG3, "fp2str: enlarged buf to %d\n", buf_max);
+ logprintfl (EUCAEXTREME, "fp2str: enlarged buf to %d\n", buf_max);
do { // read in until EOF or buffer is full
last_read = fgets (buf+buf_current, buf_max-buf_current, fp);
@@ -627,7 +627,7 @@ char * fp2str (FILE * fp)
return NULL;
}
}
- logprintfl (EUCADEBUG3, "fp2str: read %d characters so far (max=%d, last=%s)\n", buf_current, buf_max, last_read?"no":"yes");
+ logprintfl (EUCAEXTREME, "fp2str: read %d characters so far (max=%d, last=%s)\n", buf_current, buf_max, last_read?"no":"yes");
} while ( last_read && buf_max > buf_current+1 ); // +1 is needed for fgets() to put \0
buf_max += INCREMENT; // in case it is full
@@ -644,7 +644,7 @@ char * system_output (char * shell_command )
FILE * fp;
/* forks off command (this doesn't fail if command doesn't exist */
- logprintfl (EUCADEBUG2, "system_output(): [%s]\n", shell_command);
+ logprintfl (EUCATRACE, "system_output(): [%s]\n", shell_command);
if ( (fp=popen(shell_command, "r")) == NULL)
return NULL; /* caller can check errno */
buf = fp2str (fp);
Please sign in to comment.
Something went wrong with that request. Please try again.