[tl-append] / tl-append-test.c

#define _POSIX_C_SOURCE 2
#define _XOPEN_SOURCE
#define _GNU_SOURCE
#include <assert.h>
#include <ctype.h>
#include <errno.h>
#include <fcntl.h>
#include <limits.h>
#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/file.h>
#include <time.h>
#include <unistd.h>

#include "common.h"

const size_t TIMESTAMP_LEN = 19;

typedef struct expectation {
  time_t a, b;
  const char *message;
} ex_t;

const ex_t END = {((time_t)-1), ((time_t)-1), NULL};
const ex_t CONSUMED = {((time_t)-2), ((time_t)-2), NULL};
static int is_end(ex_t exp) {
  return exp.a == END.a && exp.b == END.b && exp.message == END.message;
}
static int is_consumed(ex_t exp) {
  return exp.a == CONSUMED.a && exp.b == CONSUMED.b &&
         exp.message == CONSUMED.message;
}
static ex_t expectation(time_t a, time_t b, const char *message) {
  ex_t exp;
  exp.a = a;
  exp.b = b;
  exp.message = message;
  return exp;
}

static void remove_logfile() {
  if (remove(FILENAME) != 0) {
    if (errno != ENOENT) {
      die_err("Error removing log file");
    }
  }
}

static ex_t write_to_tl_append(const char *content) {
  FILE *p = popen("./tl-append", "w");
  if (p == NULL)
    die_err("Couldn't run tl-append");
  time_t start = time(NULL);
  if (fputs(content, p) == EOF)
    die("Couldn't write to pipe");
  int status = pclose(p);
  time_t end = time(NULL);
  if (status < 0)
    die_err("Error closing pipe");
  if (status != 0)
    die("tl-append exited abnormally");
  return expectation(start, end, content);
}

static char *timestamp_problem(const ex_t *ex, const char *line) {
  struct tm tm;

  /* localtime_r to set tm's timezone */
  time_t now_time = time(NULL);
  if (localtime_r(&now_time, &tm) == NULL)
    return "Can't unpack current time?";

  const char *strptime_result = strptime(line, "%Y %m %d %H %M %S", &tm);
  if (strptime_result == NULL || strptime_result != &line[TIMESTAMP_LEN])
    return "Wrong contents in log file: Couldn't parse timestamp";
  time_t t = mktime(&tm);
  int t_in_range = ex->a <= t && t <= ex->b;
  if (!t_in_range)
    return "Wrong contents in log file: Wrong time";
  return NULL;
}

static char *line_problem(const ex_t *ex, const char *line) {
  size_t line_len = strlen(line);
  if (line_len < TIMESTAMP_LEN + 1)
    return "Wrong contents in log file: Line too short";
  char *trouble = timestamp_problem(ex, line);
  if (trouble)
    return trouble;
  if (line[TIMESTAMP_LEN] != ' ')
    return "Wrong contents in log file: Bad format";
  if (strncmp(ex->message, &line[TIMESTAMP_LEN + 1], strlen(ex->message) + 1) !=
      0)
    return "Wrong contents in log file";
  return NULL;
}

static void verify_line(const ex_t *ex, const char *line) {
  char *trouble = line_problem(ex, line);
  if (trouble)
    die(trouble);
}

static void verify_log_contents(const ex_t exps[]) {
  FILE *f = fopen(FILENAME, "r");
  if (f == NULL)
    die_err("Error opening log file");
  for (size_t i = 0; !is_end(exps[i]); i++) {
    size_t len = TIMESTAMP_LEN + 1 + strlen(exps[i].message);
    if (len > INT_MAX - 1)
      die("message too long");
    char *buf = (char *)malloc(len + 2);
    if (fgets(buf, len + 1, f) == NULL)
      die("Error reading log file");
    if (ferror(f))
      die("Error reading log file");
    verify_line(&exps[i], buf);
    free(buf);
  }
  if (fclose(f) != 0)
    die_err("Error closing log file");
}

static void consume_expectation(ex_t exps[], const char *line) {
  for (size_t i = 0; !is_end(exps[i]); i++) {
    if (line_problem(&exps[i], line) == NULL) {
      exps[i] = CONSUMED;
      return;
    }
  }
  die("Wrong contents in log file: Line didn't match any expectation");
}

static void verify_log_contents_unordered(ex_t exps[]) {
  FILE *f = fopen(FILENAME, "r");
  if (f == NULL)
    die_err("Error opening log file");
  for (;;) {
    const int MAX_LEN = 9999;
    char buf[MAX_LEN];
    if (fgets(buf, MAX_LEN, f) == NULL) {
      if (feof(f))
        break;
      die("Error reading log file");
    }
    if (ferror(f))
      die("Error reading log file");
    consume_expectation(exps, buf);
  }
  if (fclose(f) != 0)
    die_err("Error closing log file");
  for (size_t i = 0; !is_end(exps[i]); i++) {
    if (!is_consumed(exps[i]))
      die("Wrong contents in log file: Unconsumed expectation");
  }
}

static void test_encode_time() {
  /* localtime_r to set tm's timezone */
  time_t now_time = time(NULL);
  struct tm tm;
  if (localtime_r(&now_time, &tm) == NULL)
    die_err("Can't unpack current time?");

  const char *strptime_result = strptime("2011-12-13 14:15:16", "%F %T", &tm);
  if (strptime_result == NULL || *strptime_result != '\0')
    die("Couldn't parse time?");
  time_t tt = mktime(&tm);
  if (tt == (time_t)-1)
    die_err("Can't pack time?");

  const char *encoded = encode_time(tt);
  /* Loose check to allow for daylight savings time changes between the current
   * time and the target time.  :( */
  assert(encoded[0] == '2');
  assert(encoded[1] == '0');
  assert(encoded[2] == '1');
  assert(encoded[3] == '1');
  assert(encoded[4] == ' ');
  assert(encoded[5] == '1');
  assert(encoded[6] == '2');
  assert(encoded[7] == ' ');
  assert(encoded[8] == '1');
  assert(encoded[9] == '3');
  assert(encoded[10] == ' ');
  assert(encoded[11] == '1');
  assert(isdigit(encoded[12]));
  assert(encoded[13] == ' ');
  assert(isdigit(encoded[14]));
  assert(isdigit(encoded[15]));
  assert(encoded[16] == ' ');
  assert(encoded[17] == '1');
  assert(encoded[18] == '6');
  assert(encoded[19] == '\0');
}

static FILE *take_lock(FILE *f, char *lock_type) {
  int fd = fileno(f);
  if (fd == -1)
    die_err("Couldn't get file descriptor for locking");
  if (strcmp(lock_type, "fcntl") == 0) {
    if (fcntl(fd, F_SETLK,
              &(struct flock){.l_type = F_WRLCK,
                              .l_whence = SEEK_SET,
                              .l_start = 0,
                              .l_len = 0}) == -1)
      die_err("Couldn't take fcntl lock");
  } else if (strcmp(lock_type, "flock") == 0) {
    if (flock(fd, LOCK_EX) == -1)
      die_err("Couldn't take flock lock");
  } else {
    die("Bad lock type");
  }
  return f;
}

static void release_lock(FILE *f) {
  if (fclose(f) != 0)
    die_err("Error releasing lock");
}

static void *release_lock_after_delay(void *f) {
  sleep(1);
  release_lock((FILE *)f);
  return NULL;
}

static void *writer_thread(void *start_signal) {
  ex_t *ex = (ex_t *)malloc(sizeof(ex_t));
  if (ex == NULL)
    die_err("Couldn't allocate memory");
  char *message;
  if (asprintf(&message, "Hello from thread %lu\n", pthread_self()) == -1)
    die("Couldn't prepare message");
  pthread_rwlock_rdlock((pthread_rwlock_t *)start_signal);
  *ex = write_to_tl_append(message);
  return ex;
}

static void write_and_read_line() {
  remove_logfile();
  ex_t e = write_to_tl_append("foo\n");
  verify_log_contents((ex_t[]){e, END});
}

static void write_and_read_two_lines() {
  remove_logfile();
  ex_t e1 = write_to_tl_append("foo\n");
  ex_t e2 = write_to_tl_append("bar\n");
  verify_log_contents((ex_t[]){e1, e2, END});
}

static void write_to_locked_log(char *lock_types[]) {
  remove_logfile();
  ex_t e1 = write_to_tl_append("begin\n");
  FILE *f = fopen(FILENAME, "ae");
  if (f == NULL)
    die_err("Couldn't open file for locking");
  for (int i = 0; lock_types[i]; i++)
    take_lock(f, lock_types[0]);
  pthread_t unlock_thread;
  int create_ret =
      pthread_create(&unlock_thread, NULL, &release_lock_after_delay, f);
  if (create_ret != 0) {
    errno = create_ret;
    die_err("Couldn't start thread");
  }
  ex_t e2 = write_to_tl_append("delayed\n");
  int join_ret = pthread_join(unlock_thread, NULL);
  if (join_ret != 0) {
    errno = join_ret;
    die_err("Couldn't join thread");
  }
  verify_log_contents((ex_t[]){e1, e2, END});
}

static void write_concurrently() {
  remove_logfile();
  const int PARALLELISM = 250;
  pthread_t threads[PARALLELISM];
  pthread_rwlock_t start_signal;
  pthread_rwlock_init(&start_signal, NULL);
  for (int i = 0; i < PARALLELISM; i++) {
    int create_ret =
        pthread_create(&threads[i], NULL, &writer_thread, &start_signal);
    if (create_ret != 0) {
      errno = create_ret;
      die_err("Couldn't start thread");
    }
  }
  pthread_rwlock_unlock(&start_signal);
  ex_t results[PARALLELISM + 1];
  for (int i = 0; i < PARALLELISM; i++) {
    ex_t *ex;
    int join_ret = pthread_join(threads[i], (void **)&ex);
    if (join_ret != 0) {
      errno = join_ret;
      die_err("Couldn't join thread");
    }
    results[i] = *ex;
    free(ex);
  }
  results[PARALLELISM] = END;
  verify_log_contents_unordered(results);
}

int main() {
  test_encode_time();
  write_and_read_line();
  write_and_read_two_lines();
  write_to_locked_log((char *[]){NULL});
  write_to_locked_log((char *[]){"fcntl", NULL});
  write_to_locked_log((char *[]){"flock", NULL});
  write_to_locked_log((char *[]){"flock", "fcntl", NULL}); /* Deadlock risk! */
  write_to_locked_log((char *[]){"fcntl", "flock", NULL});
  write_concurrently();
}
Commit	Line	Data
b3d5ed96	1	#define _POSIX_C_SOURCE 2
bab98a3a	2	#define _XOPEN_SOURCE
8559ce11	3	#define _GNU_SOURCE
bab98a3a SW	4	#include <assert.h>
bab98a3a SW	5	#include <ctype.h>
27dfbfeb	6	#include <errno.h>
8559ce11	7	#include <fcntl.h>
90df84eb	8	#include <limits.h>
8559ce11	9	#include <pthread.h>
b3d5ed96 SW	10	#include <stdio.h>
	11	#include <stdlib.h>
	12	#include <string.h>
a1160bb5	13	#include <sys/file.h>
853b83c4	14	#include <time.h>
8559ce11	15	#include <unistd.h>
b3d5ed96	16
d522116b SW	17	#include "common.h"
d522116b SW	18
2998af81 SW	19	const size_t TIMESTAMP_LEN = 19;
2998af81 SW	20
71a7e5c5	21	typedef struct expectation {
853b83c4	22	time_t a, b;
eaaa0046	23	const char *message;
71a7e5c5	24	} ex_t;
eaaa0046	25
853b83c4	26	const ex_t END = {((time_t)-1), ((time_t)-1), NULL};
8559ce11	27	const ex_t CONSUMED = {((time_t)-2), ((time_t)-2), NULL};
853b83c4 SW	28	static int is_end(ex_t exp) {
	29	return exp.a == END.a && exp.b == END.b && exp.message == END.message;
	30	}
8559ce11 SW	31	static int is_consumed(ex_t exp) {
	32	return exp.a == CONSUMED.a && exp.b == CONSUMED.b &&
	33	exp.message == CONSUMED.message;
	34	}
853b83c4	35	static ex_t expectation(time_t a, time_t b, const char *message) {
71a7e5c5	36	ex_t exp;
853b83c4 SW	37	exp.a = a;
853b83c4 SW	38	exp.b = b;
eaaa0046 SW	39	exp.message = message;
	40	return exp;
	41	}
	42
27dfbfeb	43	static void remove_logfile() {
d522116b	44	if (remove(FILENAME) != 0) {
27dfbfeb SW	45	if (errno != ENOENT) {
	46	die_err("Error removing log file");
	47	}
	48	}
	49	}
	50
71a7e5c5	51	static ex_t write_to_tl_append(const char *content) {
b3d5ed96 SW	52	FILE *p = popen("./tl-append", "w");
	53	if (p == NULL)
	54	die_err("Couldn't run tl-append");
d753115a	55	time_t start = time(NULL);
aacfb261	56	if (fputs(content, p) == EOF)
b3d5ed96 SW	57	die("Couldn't write to pipe");
b3d5ed96 SW	58	int status = pclose(p);
d753115a	59	time_t end = time(NULL);
b3d5ed96 SW	60	if (status < 0)
	61	die_err("Error closing pipe");
	62	if (status != 0)
	63	die("tl-append exited abnormally");
d753115a	64	return expectation(start, end, content);
aacfb261 SW	65	}
aacfb261 SW	66
8559ce11	67	static char timestamp_problem(const ex_t ex, const char *line) {
2998af81 SW	68	struct tm tm;
	69
	70	/* localtime_r to set tm's timezone */
	71	time_t now_time = time(NULL);
	72	if (localtime_r(&now_time, &tm) == NULL)
8559ce11	73	return "Can't unpack current time?";
2998af81 SW	74
	75	const char *strptime_result = strptime(line, "%Y %m %d %H %M %S", &tm);
	76	if (strptime_result == NULL \|\| strptime_result != &line[TIMESTAMP_LEN])
8559ce11	77	return "Wrong contents in log file: Couldn't parse timestamp";
2998af81 SW	78	time_t t = mktime(&tm);
	79	int t_in_range = ex->a <= t && t <= ex->b;
	80	if (!t_in_range)
8559ce11 SW	81	return "Wrong contents in log file: Wrong time";
8559ce11 SW	82	return NULL;
2998af81 SW	83	}
2998af81 SW	84
8559ce11	85	static char line_problem(const ex_t ex, const char *line) {
2998af81 SW	86	size_t line_len = strlen(line);
2998af81 SW	87	if (line_len < TIMESTAMP_LEN + 1)
8559ce11 SW	88	return "Wrong contents in log file: Line too short";
	89	char *trouble = timestamp_problem(ex, line);
	90	if (trouble)
	91	return trouble;
2998af81	92	if (line[TIMESTAMP_LEN] != ' ')
8559ce11	93	return "Wrong contents in log file: Bad format";
2998af81 SW	94	if (strncmp(ex->message, &line[TIMESTAMP_LEN + 1], strlen(ex->message) + 1) !=
2998af81 SW	95	0)
8559ce11 SW	96	return "Wrong contents in log file";
8559ce11 SW	97	return NULL;
83acbf7e SW	98	}
83acbf7e SW	99
8559ce11 SW	100	static void verify_line(const ex_t ex, const char line) {
	101	char *trouble = line_problem(ex, line);
	102	if (trouble)
	103	die(trouble);
	104	}
b3d5ed96	105
8559ce11	106	static void verify_log_contents(const ex_t exps[]) {
d522116b	107	FILE *f = fopen(FILENAME, "r");
b3d5ed96 SW	108	if (f == NULL)
b3d5ed96 SW	109	die_err("Error opening log file");
71a7e5c5	110	for (size_t i = 0; !is_end(exps[i]); i++) {
2998af81	111	size_t len = TIMESTAMP_LEN + 1 + strlen(exps[i].message);
90df84eb SW	112	if (len > INT_MAX - 1)
90df84eb SW	113	die("message too long");
71a7e5c5 SW	114	char buf = (char )malloc(len + 2);
	115	if (fgets(buf, len + 1, f) == NULL)
	116	die("Error reading log file");
	117	if (ferror(f))
	118	die("Error reading log file");
83acbf7e	119	verify_line(&exps[i], buf);
71a7e5c5 SW	120	free(buf);
71a7e5c5 SW	121	}
b3d5ed96 SW	122	if (fclose(f) != 0)
	123	die_err("Error closing log file");
	124	}
	125
8559ce11 SW	126	static void consume_expectation(ex_t exps[], const char *line) {
	127	for (size_t i = 0; !is_end(exps[i]); i++) {
	128	if (line_problem(&exps[i], line) == NULL) {
	129	exps[i] = CONSUMED;
	130	return;
	131	}
	132	}
	133	die("Wrong contents in log file: Line didn't match any expectation");
	134	}
	135
	136	static void verify_log_contents_unordered(ex_t exps[]) {
	137	FILE *f = fopen(FILENAME, "r");
	138	if (f == NULL)
	139	die_err("Error opening log file");
	140	for (;;) {
	141	const int MAX_LEN = 9999;
	142	char buf[MAX_LEN];
	143	if (fgets(buf, MAX_LEN, f) == NULL) {
	144	if (feof(f))
	145	break;
	146	die("Error reading log file");
	147	}
	148	if (ferror(f))
	149	die("Error reading log file");
	150	consume_expectation(exps, buf);
	151	}
	152	if (fclose(f) != 0)
	153	die_err("Error closing log file");
	154	for (size_t i = 0; !is_end(exps[i]); i++) {
	155	if (!is_consumed(exps[i]))
	156	die("Wrong contents in log file: Unconsumed expectation");
	157	}
	158	}
	159
bab98a3a SW	160	static void test_encode_time() {
	161	/* localtime_r to set tm's timezone */
	162	time_t now_time = time(NULL);
	163	struct tm tm;
	164	if (localtime_r(&now_time, &tm) == NULL)
	165	die_err("Can't unpack current time?");
	166
	167	const char *strptime_result = strptime("2011-12-13 14:15:16", "%F %T", &tm);
	168	if (strptime_result == NULL \|\| *strptime_result != '\0')
	169	die("Couldn't parse time?");
	170	time_t tt = mktime(&tm);
	171	if (tt == (time_t)-1)
	172	die_err("Can't pack time?");
	173
	174	const char *encoded = encode_time(tt);
	175	/* Loose check to allow for daylight savings time changes between the current
	176	* time and the target time. :( */
	177	assert(encoded[0] == '2');
	178	assert(encoded[1] == '0');
	179	assert(encoded[2] == '1');
	180	assert(encoded[3] == '1');
	181	assert(encoded[4] == ' ');
	182	assert(encoded[5] == '1');
	183	assert(encoded[6] == '2');
	184	assert(encoded[7] == ' ');
	185	assert(encoded[8] == '1');
	186	assert(encoded[9] == '3');
	187	assert(encoded[10] == ' ');
	188	assert(encoded[11] == '1');
	189	assert(isdigit(encoded[12]));
	190	assert(encoded[13] == ' ');
	191	assert(isdigit(encoded[14]));
	192	assert(isdigit(encoded[15]));
	193	assert(encoded[16] == ' ');
	194	assert(encoded[17] == '1');
	195	assert(encoded[18] == '6');
	196	assert(encoded[19] == '\0');
	197	}
	198
a1160bb5	199	static FILE take_lock(FILE f, char *lock_type) {
8559ce11 SW	200	int fd = fileno(f);
	201	if (fd == -1)
	202	die_err("Couldn't get file descriptor for locking");
a1160bb5 SW	203	if (strcmp(lock_type, "fcntl") == 0) {
	204	if (fcntl(fd, F_SETLK,
	205	&(struct flock){.l_type = F_WRLCK,
	206	.l_whence = SEEK_SET,
	207	.l_start = 0,
	208	.l_len = 0}) == -1)
	209	die_err("Couldn't take fcntl lock");
	210	} else if (strcmp(lock_type, "flock") == 0) {
	211	if (flock(fd, LOCK_EX) == -1)
	212	die_err("Couldn't take flock lock");
	213	} else {
	214	die("Bad lock type");
	215	}
8559ce11 SW	216	return f;
	217	}
	218
	219	static void release_lock(FILE *f) {
	220	if (fclose(f) != 0)
	221	die_err("Error releasing lock");
	222	}
	223
	224	static void release_lock_after_delay(void f) {
a1160bb5	225	sleep(1);
8559ce11 SW	226	release_lock((FILE *)f);
	227	return NULL;
	228	}
	229
	230	static void writer_thread(void start_signal) {
	231	ex_t ex = (ex_t )malloc(sizeof(ex_t));
	232	if (ex == NULL)
	233	die_err("Couldn't allocate memory");
	234	char *message;
	235	if (asprintf(&message, "Hello from thread %lu\n", pthread_self()) == -1)
	236	die("Couldn't prepare message");
	237	pthread_rwlock_rdlock((pthread_rwlock_t *)start_signal);
	238	*ex = write_to_tl_append(message);
	239	return ex;
	240	}
	241
aacfb261	242	static void write_and_read_line() {
27dfbfeb	243	remove_logfile();
71a7e5c5 SW	244	ex_t e = write_to_tl_append("foo\n");
71a7e5c5 SW	245	verify_log_contents((ex_t[]){e, END});
aacfb261 SW	246	}
aacfb261 SW	247
27dfbfeb SW	248	static void write_and_read_two_lines() {
27dfbfeb SW	249	remove_logfile();
71a7e5c5 SW	250	ex_t e1 = write_to_tl_append("foo\n");
	251	ex_t e2 = write_to_tl_append("bar\n");
	252	verify_log_contents((ex_t[]){e1, e2, END});
27dfbfeb SW	253	}
27dfbfeb SW	254
a1160bb5	255	static void write_to_locked_log(char *lock_types[]) {
8559ce11 SW	256	remove_logfile();
8559ce11 SW	257	ex_t e1 = write_to_tl_append("begin\n");
d212cd99	258	FILE *f = fopen(FILENAME, "ae");
a1160bb5 SW	259	if (f == NULL)
	260	die_err("Couldn't open file for locking");
	261	for (int i = 0; lock_types[i]; i++)
	262	take_lock(f, lock_types[0]);
8559ce11 SW	263	pthread_t unlock_thread;
8559ce11 SW	264	int create_ret =
a1160bb5	265	pthread_create(&unlock_thread, NULL, &release_lock_after_delay, f);
8559ce11 SW	266	if (create_ret != 0) {
	267	errno = create_ret;
	268	die_err("Couldn't start thread");
	269	}
	270	ex_t e2 = write_to_tl_append("delayed\n");
	271	int join_ret = pthread_join(unlock_thread, NULL);
	272	if (join_ret != 0) {
	273	errno = join_ret;
	274	die_err("Couldn't join thread");
	275	}
	276	verify_log_contents((ex_t[]){e1, e2, END});
	277	}
	278
	279	static void write_concurrently() {
	280	remove_logfile();
	281	const int PARALLELISM = 250;
	282	pthread_t threads[PARALLELISM];
	283	pthread_rwlock_t start_signal;
	284	pthread_rwlock_init(&start_signal, NULL);
	285	for (int i = 0; i < PARALLELISM; i++) {
	286	int create_ret =
	287	pthread_create(&threads[i], NULL, &writer_thread, &start_signal);
	288	if (create_ret != 0) {
	289	errno = create_ret;
	290	die_err("Couldn't start thread");
	291	}
	292	}
	293	pthread_rwlock_unlock(&start_signal);
	294	ex_t results[PARALLELISM + 1];
	295	for (int i = 0; i < PARALLELISM; i++) {
	296	ex_t *ex;
	297	int join_ret = pthread_join(threads[i], (void **)&ex);
	298	if (join_ret != 0) {
	299	errno = join_ret;
	300	die_err("Couldn't join thread");
	301	}
	302	results[i] = *ex;
	303	free(ex);
	304	}
	305	results[PARALLELISM] = END;
	306	verify_log_contents_unordered(results);
	307	}
	308
27dfbfeb	309	int main() {
bab98a3a	310	test_encode_time();
27dfbfeb SW	311	write_and_read_line();
27dfbfeb SW	312	write_and_read_two_lines();
a1160bb5 SW	313	write_to_locked_log((char *[]){NULL});
	314	write_to_locked_log((char *[]){"fcntl", NULL});
	315	write_to_locked_log((char *[]){"flock", NULL});
d212cd99	316	write_to_locked_log((char []){"flock", "fcntl", NULL}); / Deadlock risk! */
a1160bb5	317	write_to_locked_log((char *[]){"fcntl", "flock", NULL});
8559ce11	318	write_concurrently();
27dfbfeb	319	}