aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorPeter Seebach <peter.seebach@windriver.com>2016-02-24 16:37:50 -0600
committerPeter Seebach <peter.seebach@windriver.com>2016-02-24 16:37:50 -0600
commit00e66ef8792f832776cabb6d0108505d51b96fe7 (patch)
treefc528095cf881fd8c965fd9b9f4afb03f81d2953
parent2a7591e2931c893e6d1a635d2df5dd6120bf9952 (diff)
downloadpseudo-00e66ef8792f832776cabb6d0108505d51b96fe7.tar.gz
pseudo-00e66ef8792f832776cabb6d0108505d51b96fe7.tar.bz2
pseudo-00e66ef8792f832776cabb6d0108505d51b96fe7.zip
Various logging and cleanup
Improve event logging a little bit more, increase default event log size, reduce retries (we shouldn't need that many if nothing's wrong), and make the server log timestamps during database cleanup, since I'm suspicious of that as a possible source of delays. Also cause server to emit a useful exit status if it can't get a lock, and client to check server exit status when spawning server.
-rw-r--r--ChangeLog.txt4
-rw-r--r--pseudo.c2
-rw-r--r--pseudo_client.c48
-rw-r--r--pseudo_db.c22
-rw-r--r--pseudo_server.c3
-rw-r--r--pseudo_util.c4
6 files changed, 62 insertions, 21 deletions
diff --git a/ChangeLog.txt b/ChangeLog.txt
index c426847..cc2f379 100644
--- a/ChangeLog.txt
+++ b/ChangeLog.txt
@@ -1,3 +1,7 @@
+2016-02-24:
+ * (seebs) event logger cleanup, improved diagnostics for client
+ spawning, server exit cleanup.
+
2016-02-23:
* (seebs) event logger initial implementation
diff --git a/pseudo.c b/pseudo.c
index 4451992..9ae1ab8 100644
--- a/pseudo.c
+++ b/pseudo.c
@@ -482,7 +482,7 @@ main(int argc, char *argv[]) {
} else {
pseudo_diag("pseudo: Error obtaining lock: %s\n", strerror(errno));
}
- exit(0);
+ exit(1);
} else {
pseudo_debug(PDBGF_SERVER, "Acquired lock.\n");
}
diff --git a/pseudo_client.c b/pseudo_client.c
index 5437b71..ee831d1 100644
--- a/pseudo_client.c
+++ b/pseudo_client.c
@@ -957,21 +957,28 @@ client_spawn_server(void) {
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");
- if (fp) {
- if (fscanf(fp, "%d", &server_pid) != 1) {
- pseudo_debug(PDBGF_CLIENT, "Opened server PID file, but didn't get a pid.\n");
+ if (WIFEXITED(status) && WEXITSTATUS(status) == 0) {
+ pseudo_evlog(PDBGF_CLIENT, "server reports successful startup, reading pid.\n");
+ pseudo_pidfile = pseudo_localstatedir_path(PSEUDO_PIDFILE);
+ fp = fopen(pseudo_pidfile, "r");
+ if (fp) {
+ if (fscanf(fp, "%d", &server_pid) != 1) {
+ pseudo_debug(PDBGF_CLIENT, "Opened server PID file, but didn't get a pid.\n");
+ }
+ fclose(fp);
+ } else {
+ pseudo_debug(PDBGF_CLIENT, "no pid file (%s): %s\n",
+ pseudo_pidfile, strerror(errno));
}
- fclose(fp);
+ pseudo_debug(PDBGF_CLIENT, "read new pid file: %d\n", server_pid);
+ free(pseudo_pidfile);
+ /* at this point, we should have a new server_pid */
+ return 0;
} else {
- pseudo_debug(PDBGF_CLIENT, "no pid file (%s): %s\n",
- pseudo_pidfile, strerror(errno));
+ pseudo_evlog(PDBGF_CLIENT, "server startup apparently unsuccessful. setting server pid to -1.\n");
+ server_pid = -1;
+ return 1;
}
- pseudo_debug(PDBGF_CLIENT, "read new pid file: %d\n", server_pid);
- free(pseudo_pidfile);
- /* at this point, we should have a new server_pid */
- return 0;
} else {
char *base_args[] = { NULL, NULL, NULL };
char **argv;
@@ -1129,8 +1136,11 @@ client_connect(void) {
connect_fd = socket(PF_UNIX, SOCK_STREAM, 0);
connect_fd = pseudo_fd(connect_fd, MOVE_FD);
+ pseudo_evlog(PDBGF_CLIENT, "creating socket %s.\n", sun.sun_path);
if (connect_fd == -1) {
- pseudo_diag("Can't create socket: %s (%s)\n", sun.sun_path, strerror(errno));
+ char *e = strerror(errno);
+ pseudo_diag("Can't create socket: %s (%s)\n", sun.sun_path, e);
+ pseudo_evlog(PDBGF_CLIENT, "failed to create socket: %s\n", e);
return 1;
}
@@ -1152,7 +1162,9 @@ client_connect(void) {
return 1;
}
if (connect(connect_fd, (struct sockaddr *) &sun, sizeof(sun)) == -1) {
- pseudo_debug(PDBGF_CLIENT, "Can't connect socket to pseudo.socket: (%s)\n", strerror(errno));
+ char *e = strerror(errno);
+ pseudo_debug(PDBGF_CLIENT, "Can't connect socket to pseudo.socket: (%s)\n", e);
+ pseudo_evlog(PDBGF_CLIENT, "connect failed: %s\n", e);
close(connect_fd);
if (fchdir(cwd_fd) == -1) {
pseudo_diag("return to previous directory failed: %s\n",
@@ -1167,6 +1179,7 @@ client_connect(void) {
strerror(errno));
}
close(cwd_fd);
+ pseudo_evlog(PDBGF_CLIENT, "socket connect OK.\n");
pseudo_debug(PDBGF_CLIENT | PDBGF_VERBOSE, "connected socket.\n");
return 0;
}
@@ -1225,7 +1238,7 @@ pseudo_client_setup(void) {
return 1;
}
-#define PSEUDO_RETRIES 50
+#define PSEUDO_RETRIES 20
static pseudo_msg_t *
pseudo_client_request(pseudo_msg_t *msg, size_t len, const char *path) {
pseudo_msg_t *response = 0;
@@ -1246,6 +1259,7 @@ pseudo_client_request(pseudo_msg_t *msg, size_t len, const char *path) {
(unsigned long long) msg->ino);
rc = pseudo_msg_send(connect_fd, msg, len, path);
if (rc != 0) {
+ pseudo_evlog(PDBGF_CLIENT, "msg_send failed [%d].\n", rc);
pseudo_debug(PDBGF_CLIENT | PDBGF_VERBOSE, "msg_send: %d%s\n",
rc,
rc == -1 ? " (sigpipe)" :
@@ -1255,10 +1269,12 @@ pseudo_client_request(pseudo_msg_t *msg, size_t len, const char *path) {
* retry.
*/
if (pseudo_client_setup()) {
- int ms = (getpid() % 5) + 3 + tries;
+ 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);
+ } else {
+ pseudo_evlog(PDBGF_CLIENT, "setup apparently successful, retrying message immediately.\n");
}
continue;
}
diff --git a/pseudo_db.c b/pseudo_db.c
index c387cb5..c8b04cb 100644
--- a/pseudo_db.c
+++ b/pseudo_db.c
@@ -23,6 +23,7 @@
#include <sys/stat.h>
#include <sys/xattr.h>
#include <time.h>
+#include <sys/time.h>
#include <unistd.h>
#include <sqlite3.h>
@@ -537,17 +538,36 @@ make_tables(sqlite3 *db,
/* registered with atexit */
static void
cleanup_db(void) {
- pseudo_debug(PDBGF_SERVER, "server exiting\n");
+ char datebuf[64];
+ struct tm stamp_tm;
+ struct timeval stamp;
+
+ gettimeofday(&stamp, NULL);
+ localtime_r(&stamp.tv_sec, &stamp_tm);
+ strftime(datebuf, 64, "%H:%M:%S", &stamp_tm);
+
+ pseudo_diag("db cleanup for server shutdown, %s.%03d\n",
+ datebuf, (int) (stamp.tv_usec / 1000));
#ifdef USE_MEMORY_DB
if (real_file_db) {
pdb_backup();
sqlite3_close(real_file_db);
}
+ gettimeofday(&stamp, NULL);
+ localtime_r(&stamp.tv_sec, &stamp_tm);
+ strftime(datebuf, 64, "%H:%M:%S", &stamp_tm);
+ pseudo_diag("memory-to-file backup complete, %s.%03d.\n",
+ datebuf, (int) (stamp.tv_usec / 1000));
#endif
if (file_db)
sqlite3_close(file_db);
if (log_db)
sqlite3_close(log_db);
+ gettimeofday(&stamp, NULL);
+ localtime_r(&stamp.tv_sec, &stamp_tm);
+ strftime(datebuf, 64, "%H:%M:%S", &stamp_tm);
+ pseudo_diag("db cleanup finished, %s.%03d\n",
+ datebuf, (int) (stamp.tv_usec / 1000));
}
/* This function has been rewritten and I no longer hate it. I just feel
diff --git a/pseudo_server.c b/pseudo_server.c
index f785c44..34d1d54 100644
--- a/pseudo_server.c
+++ b/pseudo_server.c
@@ -510,10 +510,11 @@ pseudo_server_loop(void) {
getpid(), messages,
(double) message_time.tv_sec +
(double) message_time.tv_usec / 1000000.0);
+ /* and at this point, we'll start refusing connections */
close(clients[0].fd);
/* This is a good place to insert a delay for
* debugging race conditions during startup. */
- /* sleep(1); */
+ /* usleep(300000); */
exit(0);
}
FD_ZERO(&reads);
diff --git a/pseudo_util.c b/pseudo_util.c
index 6f8f6e8..6e6345f 100644
--- a/pseudo_util.c
+++ b/pseudo_util.c
@@ -81,7 +81,7 @@ typedef struct {
char *data;
} pseudo_evlog_entry;
-#define PSEUDO_EVLOG_ENTRIES 50
+#define PSEUDO_EVLOG_ENTRIES 250
#define PSEUDO_EVLOG_LENGTH 256
static pseudo_evlog_entry event_log[PSEUDO_EVLOG_ENTRIES];
static char *pseudo_evlog_buffer;
@@ -542,7 +542,7 @@ pseudo_evlog_dump(void) {
if (!ev->data || ev->len <= 0)
continue;
localtime_r(&ev->stamp.tv_sec, &first_tm);
- len = strftime(firstdate, 64, "%M:%S", &first_tm);
+ len = strftime(firstdate, 64, "%H:%M:%S", &first_tm);
if (len) {
len = snprintf(scratch, 256, "%s.%03d: ", firstdate,
(int) (ev->stamp.tv_usec / 1000));