aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
Diffstat
-rw-r--r--ChangeLog.txt3
-rw-r--r--pseudo.h8
-rw-r--r--pseudo_client.c16
-rw-r--r--pseudo_server.c5
-rw-r--r--pseudo_util.c196
-rw-r--r--pseudo_wrappers.c2
6 files changed, 207 insertions, 23 deletions
diff --git a/ChangeLog.txt b/ChangeLog.txt
index 1a9656b..c426847 100644
--- a/ChangeLog.txt
+++ b/ChangeLog.txt
@@ -1,3 +1,6 @@
+2016-02-23:
+ * (seebs) event logger initial implementation
+
2016-02-16:
* (seebs) don't try to force pseudo's debug fd to fd 2 in clients.
Also, don't allow server to end up with a client on fd 2, whether
diff --git a/pseudo.h b/pseudo.h
index eb8d3da..a39b3b3 100644
--- a/pseudo.h
+++ b/pseudo.h
@@ -38,10 +38,16 @@ extern void pseudo_debug_set(char *);
extern void pseudo_debug_clear(char *);
extern void pseudo_debug_flags_finalize(void);
extern unsigned long pseudo_util_debug_flags;
+extern unsigned long pseudo_util_evlog_flags;
extern int pseudo_util_debug_fd;
extern int pseudo_disabled;
extern int pseudo_allow_fsync;
extern int pseudo_diag(char *, ...) __attribute__ ((format (printf, 1, 2)));
+extern int pseudo_evlog_internal(char *, ...) __attribute__ ((format (printf, 1, 2)));
+#define pseudo_evlog(x, ...) do { \
+ if (pseudo_util_evlog_flags & (x)) { pseudo_evlog_internal(__VA_ARGS__); } \
+} while (0)
+extern void pseudo_evlog_dump(void);
#ifndef NDEBUG
#define pseudo_debug(x, ...) do { \
if ((x) & PDBGF_VERBOSE) { \
@@ -82,7 +88,7 @@ extern char *pseudo_get_prefix(char *);
extern char *pseudo_get_bindir(void);
extern char *pseudo_get_libdir(void);
extern char *pseudo_get_localstatedir(void);
-extern int pseudo_logfile(char *defname, int prefer_fd);
+extern int pseudo_debug_logfile(char *defname, int prefer_fd);
extern ssize_t pseudo_sys_path_max(void);
extern ssize_t pseudo_path_max(void);
#define PSEUDO_PWD_MAX 4096
diff --git a/pseudo_client.c b/pseudo_client.c
index b02657f..5437b71 100644
--- a/pseudo_client.c
+++ b/pseudo_client.c
@@ -944,11 +944,18 @@ client_spawn_server(void) {
pseudo_diag("couldn't fork server: %s\n", strerror(errno));
return 1;
}
+ pseudo_evlog(PDBGF_CLIENT, "spawned new server, pid %d\n", server_pid);
pseudo_debug(PDBGF_CLIENT | PDBGF_SERVER, "spawned server, pid %d\n", server_pid);
/* wait for the child process to terminate, indicating server
* is ready
*/
waitpid(server_pid, &status, 0);
+ if (WIFEXITED(status)) {
+ pseudo_evlog(PDBGF_CLIENT, "server exited status %d\n", WEXITSTATUS(status));
+ }
+ if (WIFSIGNALED(status)) {
+ pseudo_evlog(PDBGF_CLIENT, "server exited from signal %d\n", WTERMSIG(status));
+ }
server_pid = -2;
pseudo_pidfile = pseudo_localstatedir_path(PSEUDO_PIDFILE);
fp = fopen(pseudo_pidfile, "r");
@@ -1193,6 +1200,7 @@ pseudo_client_setup(void) {
}
if (!server_pid) {
if (client_spawn_server()) {
+ pseudo_evlog(PDBGF_CLIENT, "no pid, and client_spawn_server failed.\n");
return 1;
}
}
@@ -1202,13 +1210,16 @@ pseudo_client_setup(void) {
pseudo_debug(PDBGF_CLIENT, "server seems to be gone, trying to restart\n");
if (client_spawn_server()) {
+ pseudo_evlog(PDBGF_CLIENT, "attempted respawn, failed.\n");
pseudo_debug(PDBGF_CLIENT, "failed to spawn server, waiting for retry.\n");
return 1;
} else {
+ pseudo_evlog(PDBGF_CLIENT, "restarted, new pid %d\n", server_pid);
pseudo_debug(PDBGF_CLIENT, "restarted, new pid %d\n", server_pid);
if (!client_connect() && !client_ping()) {
return 0;
}
+ pseudo_evlog(PDBGF_CLIENT, "server spawn seemed okay, but failed on connect/ping.\n");
}
pseudo_debug(PDBGF_CLIENT, "couldn't get or spawn a server.\n");
return 1;
@@ -1230,6 +1241,7 @@ pseudo_client_request(pseudo_msg_t *msg, size_t len, const char *path) {
* client may have done it.
*/
for (tries = 0; tries < PSEUDO_RETRIES; ++tries) {
+ pseudo_evlog(PDBGF_CLIENT, "try %d, connect fd is %d\n", tries, connect_fd);
pseudo_debug(PDBGF_CLIENT | PDBGF_VERBOSE, "sending a message: ino %llu\n",
(unsigned long long) msg->ino);
rc = pseudo_msg_send(connect_fd, msg, len, path);
@@ -1245,6 +1257,7 @@ pseudo_client_request(pseudo_msg_t *msg, size_t len, const char *path) {
if (pseudo_client_setup()) {
int ms = (getpid() % 5) + 3 + tries;
struct timespec delay = { .tv_sec = 0, .tv_nsec = ms * 1000000 };
+ pseudo_evlog(PDBGF_CLIENT, "setup failed, delaying %d ms.\n", ms);
nanosleep(&delay, NULL);
}
continue;
@@ -1271,7 +1284,10 @@ pseudo_client_request(pseudo_msg_t *msg, size_t len, const char *path) {
}
}
pseudo_diag("pseudo: server connection persistently failed, aborting.\n");
+ pseudo_evlog_dump();
+ pseudo_diag("event log dumped, aborting.\n");
abort();
+ pseudo_diag("aborted.\n");
return 0;
}
diff --git a/pseudo_server.c b/pseudo_server.c
index 7127082..f785c44 100644
--- a/pseudo_server.c
+++ b/pseudo_server.c
@@ -165,7 +165,7 @@ pseudo_server_start(int daemonize) {
pseudo_new_pid();
fclose(stdin);
fclose(stdout);
- pseudo_logfile(PSEUDO_LOGFILE, 2);
+ pseudo_debug_logfile(PSEUDO_LOGFILE, 2);
} else {
/* Write the pid if we don't daemonize */
pseudo_server_write_pid(getpid());
@@ -511,6 +511,9 @@ pseudo_server_loop(void) {
(double) message_time.tv_sec +
(double) message_time.tv_usec / 1000000.0);
close(clients[0].fd);
+ /* This is a good place to insert a delay for
+ * debugging race conditions during startup. */
+ /* sleep(1); */
exit(0);
}
FD_ZERO(&reads);
diff --git a/pseudo_util.c b/pseudo_util.c
index 9d24362..6f8f6e8 100644
--- a/pseudo_util.c
+++ b/pseudo_util.c
@@ -29,6 +29,7 @@
#include <sys/stat.h>
#include <regex.h>
#include <time.h>
+#include <sys/time.h>
#include <unistd.h>
#include <limits.h>
@@ -69,9 +70,26 @@ static struct pseudo_variables pseudo_env[] = {
#ifdef PSEUDO_PROFILING
{ "PSEUDO_PROFILE_PATH", 19, NULL },
#endif
+ { "PSEUDO_EVLOG", 12, NULL },
+ { "PSEUDO_EVLOG_FILE", 17, NULL },
{ NULL, 0, NULL } /* Magic terminator */
};
+typedef struct {
+ struct timeval stamp;
+ int len;
+ char *data;
+} pseudo_evlog_entry;
+
+#define PSEUDO_EVLOG_ENTRIES 50
+#define PSEUDO_EVLOG_LENGTH 256
+static pseudo_evlog_entry event_log[PSEUDO_EVLOG_ENTRIES];
+static char *pseudo_evlog_buffer;
+static int pseudo_evlog_next_entry = 0;
+static void pseudo_evlog_set(char *);
+static void pseudo_evlog_flags_finalize(void);
+static unsigned long pseudo_debug_flags_in(char *);
+
/* -1 - init hasn't been run yet
* 0 - init has been run
* 1 - init is running
@@ -115,7 +133,7 @@ pseudo_has_unload(char * const *envp) {
if (pseudo_util_initted == -1)
pseudo_init_util();
while (pseudo_env[i].key && strcmp(pseudo_env[i].key, unload))
- ++i;
+ ++i;
if (pseudo_env[i].key && pseudo_env[i].value)
return 1;
@@ -205,9 +223,9 @@ pseudo_init_util(void) {
/* Somewhere we have to set the debug level.. */
env = pseudo_get_value("PSEUDO_DEBUG");
- if (env) {
+ if (env) {
int i;
- int level = atoi(env);
+ int level = atoi(env);
if (level > 0) {
for (i = 0; i < level; ++i) {
pseudo_debug_verbose();
@@ -216,12 +234,20 @@ pseudo_init_util(void) {
pseudo_debug_set(env);
}
pseudo_debug_flags_finalize();
- }
- free(env);
+ }
+ free(env);
+ env = pseudo_get_value("PSEUDO_EVLOG");
+ if (env) {
+ pseudo_evlog_set(env);
+ pseudo_evlog_flags_finalize();
+ }
+ free(env);
}
unsigned long pseudo_util_debug_flags = 0;
+unsigned long pseudo_util_evlog_flags = 0;
int pseudo_util_debug_fd = 2;
+int pseudo_util_evlog_fd = 2;
static int debugged_newline = 1;
static char pid_text[32];
static size_t pid_len;
@@ -389,30 +415,52 @@ pseudo_debug_verbose(void) {
}
}
+void
+pseudo_debug_set(char *s) {
+ pseudo_util_debug_flags = pseudo_debug_flags_in(s);
+}
+
+static void
+pseudo_evlog_set(char *s) {
+ pseudo_util_evlog_flags = pseudo_debug_flags_in(s);
+}
+
/* This exists because we don't want to allocate a bunch of strings
* and free them immediately if you have several flags set.
*/
-void
-pseudo_debug_flags_finalize(void) {
+static void
+pseudo_flags_finalize(unsigned long flags, char *value) {
char buf[PDBG_MAX + 1] = "", *s = buf;
for (int i = 0; i < PDBG_MAX; ++i) {
- if (pseudo_util_debug_flags & (1 << i)) {
+ if (flags & (1 << i)) {
*s++ = pseudo_debug_type_symbolic(i);
}
}
- pseudo_set_value("PSEUDO_DEBUG", buf);
+ pseudo_set_value(value, buf);
}
void
-pseudo_debug_set(char *s) {
+pseudo_debug_flags_finalize(void) {
+ pseudo_flags_finalize(pseudo_util_debug_flags, "PSEUDO_DEBUG");
+}
+
+void
+pseudo_evlog_flags_finalize(void) {
+ pseudo_flags_finalize(pseudo_util_evlog_flags, "PSEUDO_EVLOG");
+}
+
+static unsigned long
+pseudo_debug_flags_in(char *s) {
+ unsigned long flags = 0;
if (!s)
- return;
+ return flags;
for (; *s; ++s) {
int id = pseudo_debug_type_symbolic_id(*s);
if (id > 0) {
- pseudo_util_debug_flags |= (1 << id);
+ flags |= (1 << id);
}
}
+ return flags;
}
void
@@ -454,6 +502,89 @@ pseudo_diag(char *fmt, ...) {
return wrote;
}
+void
+pseudo_evlog_dump(void) {
+ char scratch[256], firstdate[64], lastdate[64];
+ time_t first = 0, last = 0;
+ int len;
+ int entries = 0;
+ struct tm first_tm, last_tm;
+ int wrote; /* ignoring write errors because there's nothing we can do */
+
+ for (int i = 0; i < PSEUDO_EVLOG_ENTRIES; ++i) {
+ pseudo_evlog_entry *e = &event_log[i];
+ if (!e->data || e->len < 0 || e->stamp.tv_sec == 0)
+ continue;
+ ++entries;
+ if (!first || e->stamp.tv_sec < first)
+ first = e->stamp.tv_sec;
+ if (!last || e->stamp.tv_sec > last)
+ last = e->stamp.tv_sec;
+ }
+ localtime_r(&first, &first_tm);
+ localtime_r(&last, &last_tm);
+ strftime(firstdate, 64, "%Y-%M-%D %H:%M:%S", &first_tm);
+ strftime(lastdate, 64, "%Y-%M-%D %H:%M:%S", &last_tm);
+
+ len = snprintf(scratch, 256, "event log for pid %d [%d entries]\n",
+ getpid(), entries);
+ if (len > 256)
+ len = 256;
+ wrote = write(pseudo_util_evlog_fd, scratch, len);
+ len = snprintf(scratch, 256, " first entry %s\n", firstdate);
+ wrote = write(pseudo_util_evlog_fd, scratch, len);
+ len = snprintf(scratch, 256, " last entry %s\n", lastdate);
+ wrote = write(pseudo_util_evlog_fd, scratch, len);
+
+ for (int i = 0; i < PSEUDO_EVLOG_ENTRIES; ++i) {
+ int entry = (pseudo_evlog_next_entry + i) % PSEUDO_EVLOG_ENTRIES;
+ pseudo_evlog_entry *ev = &event_log[entry];
+ if (!ev->data || ev->len <= 0)
+ continue;
+ localtime_r(&ev->stamp.tv_sec, &first_tm);
+ len = strftime(firstdate, 64, "%M:%S", &first_tm);
+ if (len) {
+ len = snprintf(scratch, 256, "%s.%03d: ", firstdate,
+ (int) (ev->stamp.tv_usec / 1000));
+ wrote = write(pseudo_util_evlog_fd, scratch, len);
+ } else {
+ wrote = write(pseudo_util_evlog_fd, "no timestamp: ", 14);
+ }
+ wrote = write(pseudo_util_evlog_fd, ev->data, ev->len);
+ }
+ (void) wrote;
+}
+
+int
+pseudo_evlog_internal(char *fmt, ...) {
+ va_list ap;
+ pseudo_evlog_entry *ev = &event_log[pseudo_evlog_next_entry++];
+
+ pseudo_evlog_next_entry %= PSEUDO_EVLOG_ENTRIES;
+
+ if (!ev->data) {
+ pseudo_evlog_buffer = malloc(PSEUDO_EVLOG_ENTRIES * PSEUDO_EVLOG_LENGTH);
+ if (pseudo_evlog_buffer) {
+ for (int i = 0; i < PSEUDO_EVLOG_ENTRIES; ++i) {
+ event_log[i].data = pseudo_evlog_buffer + (PSEUDO_EVLOG_LENGTH * i);
+ }
+ } else {
+ pseudo_diag("fatal: can't allocate event log storage.\n");
+ }
+ }
+
+ va_start(ap, fmt);
+ ev->len = vsnprintf(ev->data, PSEUDO_EVLOG_LENGTH, fmt, ap);
+ va_end(ap);
+ if (ev->len > PSEUDO_EVLOG_LENGTH) {
+ strcpy(ev->data + PSEUDO_EVLOG_LENGTH - 5, "...\n");
+ ev->len = PSEUDO_EVLOG_LENGTH - 1;
+ }
+ gettimeofday(&ev->stamp, NULL);
+
+ return ev->len;
+}
+
/* store pid in text form for prepending to messages */
void
pseudo_new_pid() {
@@ -749,14 +880,14 @@ pseudo_setupenv() {
free(pseudo_get_libdir());
free(pseudo_get_localstatedir());
- while (pseudo_env[i].key) {
+ while (pseudo_env[i].key) {
if (pseudo_env[i].value) {
setenv(pseudo_env[i].key, pseudo_env[i].value, 0);
pseudo_debug(PDBGF_ENV | PDBGF_VERBOSE, "pseudo_env: %s => %s\n",
pseudo_env[i].key, pseudo_env[i].value);
}
- i++;
- }
+ i++;
+ }
const char *ld_library_path = getenv(PRELINK_PATH);
char *libdir_path = pseudo_libdir_path(NULL);
@@ -846,9 +977,9 @@ pseudo_setupenvp(char * const *envp) {
++env_count;
}
- for (i = 0; pseudo_env[i].key; i++) {
+ for (i = 0; pseudo_env[i].key; i++) {
size_pseudoenv++;
- }
+ }
env_count += size_pseudoenv; /* We're going to over allocate */
@@ -1312,10 +1443,9 @@ pseudo_etc_file(const char *file, char *realname, int flags, const char **search
}
/* set up a log file */
-int
-pseudo_logfile(char *defname, int prefer_fd) {
+static int
+pseudo_logfile(char *filename, char *defname, int prefer_fd) {
char *pseudo_path;
- char *filename = pseudo_get_value("PSEUDO_DEBUG_FILE");
char *s;
#if PSEUDO_PORT_LINUX
extern char *program_invocation_short_name; /* glibcism */
@@ -1424,6 +1554,32 @@ pseudo_logfile(char *defname, int prefer_fd) {
return 0;
}
+int
+pseudo_debug_logfile(char *defname, int prefer_fd) {
+ char *filename = pseudo_get_value("PSEUDO_DEBUG_FILE");
+ int fd;
+
+ fd = pseudo_logfile(filename, defname, prefer_fd);
+ if (fd > -1) {
+ pseudo_util_debug_fd = fd;
+ return 0;
+ }
+ return 1;
+}
+
+int
+pseudo_evlog_logfile(char *defname, int prefer_fd) {
+ char *filename = pseudo_get_value("PSEUDO_EVLOG_FILE");
+ int fd;
+
+ fd = pseudo_logfile(filename, defname, prefer_fd);
+ if (fd > -1) {
+ pseudo_util_evlog_fd = fd;
+ return 0;
+ }
+ return 1;
+}
+
void
pseudo_stat32_from64(struct stat *buf32, const struct stat64 *buf) {
buf32->st_dev = buf->st_dev;
diff --git a/pseudo_wrappers.c b/pseudo_wrappers.c
index ba8b52d..353a5a4 100644
--- a/pseudo_wrappers.c
+++ b/pseudo_wrappers.c
@@ -182,7 +182,7 @@ pseudo_init_wrappers(void) {
/* Once the wrappers are setup, we can now use open... so
* setup the logfile, if necessary...
*/
- pseudo_logfile(NULL, -1);
+ pseudo_debug_logfile(NULL, -1);
pseudo_magic();
pseudo_droplock();
generated by cgit 1.2.3-korg (git 2.39.0) at 2024-04-18 18:14:05 +0000