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