diff --git a/src/os/tests/CMakeLists.txt b/src/os/tests/CMakeLists.txt index 18bcca7..93868df 100644 --- a/src/os/tests/CMakeLists.txt +++ b/src/os/tests/CMakeLists.txt @@ -24,7 +24,8 @@ set(sources "strtoll.c" "thread.c" "thread_cleanup.c" - "strcasecmp.c") + "strcasecmp.c" + "log.c") add_cunit_executable(abstraction ${sources}) target_link_libraries(abstraction OSAPI) diff --git a/src/os/tests/log.c b/src/os/tests/log.c new file mode 100644 index 0000000..8d3b6ee --- /dev/null +++ b/src/os/tests/log.c @@ -0,0 +1,364 @@ +/* + * Copyright(c) 2006 to 2018 ADLINK Technology Limited and others + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License v. 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0, or the Eclipse Distribution License + * v. 1.0 which is available at + * http://www.eclipse.org/org/documents/edl-v10.php. + * + * SPDX-License-Identifier: EPL-2.0 OR BSD-3-Clause + */ +#include +#include +#include +#include + +#ifdef __APPLE__ +#include +#endif /* __APPLE__ */ + +#include "CUnit/Test.h" +#include "os/os.h" + +static FILE *fh = NULL; + +#ifdef _WIN32 +#include +#include + +/* Windows does not support opening a stream to a buffer like fmemopen on + * Linux does. A temporary file that will never be flushed to disk is created + * instead. See the link below for more detail. + * + * https://blogs.msdn.microsoft.com/larryosterman/2004/04/19/its-only-temporary/ + */ + +FILE *fmemopen(void *buf, size_t size, const char *mode) +{ + int err = 0; + int fd = -1; + DWORD ret; + FILE *fh = NULL; + HANDLE hdl = INVALID_HANDLE_VALUE; + /* GetTempFileName will fail if the directory is be longer than MAX_PATH-14 + characters */ + char tmpdir[(MAX_PATH + 1) - 14]; + char tmpfile[MAX_PATH + 1]; + static const int max = 1000; + static const char pfx[] = "cyclone"; /* Up to first three are used. */ + + (void)buf; + (void)size; + + ret = GetTempPath(sizeof(tmpdir), tmpdir); + if (ret == 0) { + err = GetLastError(); + } else if (ret > sizeof(tmpdir)) { + err = ENOMEM; + } + + if (GetTempFileName(tmpdir, pfx, 0, tmpfile) == 0) { + err = GetLastError(); + assert(err != ERROR_BUFFER_OVERFLOW); + } else { + /* The combination of FILE_ATTRIBUTE_TEMPORARY and + FILE_FLAG_DELETE_ON_CLOSE hints to the filesystem that the file + should never be flushed to disk. */ + hdl = CreateFile( + tmpfile, + GENERIC_READ | GENERIC_WRITE, + 0, + NULL, + CREATE_ALWAYS, + FILE_FLAG_DELETE_ON_CLOSE | FILE_ATTRIBUTE_TEMPORARY, + NULL); + if (hdl == INVALID_HANDLE_VALUE) { + err = GetLastError(); + } + } + + if (err) { + errno = err; + } else { + if ((fd = _open_osfhandle((intptr_t)hdl, _O_APPEND)) == -1) { + /* errno set by _open_osfhandle. */ + CloseHandle(hdl); + } else if ((fh = fdopen(fd, mode)) == NULL) { + /* errno set by fdopen. */ + _close(fd); /* Automatically closes underlying handle. */ + } else { + return fh; + } + } + + return NULL; +} +#endif /* _WIN32 */ + +static void count(void *ptr, const dds_log_data_t *data) +{ + (void)data; + *(int *)ptr += 1; +} + +static void copy(void *ptr, const dds_log_data_t *data) +{ + *(char **)ptr = os_strdup(data->message); +} + +static void setup(void) +{ + fh = fmemopen(NULL, 1024, "wb+"); + CU_ASSERT_PTR_NOT_NULL_FATAL(fh); +} + +static void teardown(void) +{ + (void)fclose(fh); +} + +/* By default only DDS_LC_FATAL and DDS_LC_ERROR are set. This means setting a + trace sink should not have any effect, because no trace categories are + enabled. The message should end up in the log file. */ +CU_Test(dds_log, only_log_file, .init=setup, .fini=teardown) +{ + char buf[1024], *ptr; + int cnt = 0; + size_t nbytes; + + dds_set_log_file(fh); + dds_set_trace_sink(&count, &cnt); + DDS_ERROR("foo%s\n", "bar"); + (void)fseek(fh, 0L, SEEK_SET); + nbytes = fread(buf, 1, sizeof(buf) - 1, fh); + /* At least foobar should have been printed to the log file. */ + CU_ASSERT_FATAL(nbytes > 6); + buf[nbytes] = '\0'; + ptr = strstr(buf, "foobar\n"); + CU_ASSERT_PTR_NOT_NULL(ptr); + /* No trace categories are enabled by default, verify trace callback was + not invoked. */ + CU_ASSERT_EQUAL(cnt, 0); +} + +/* Messages must be printed to the trace file if at least one trace category + is enabled. Messages must not be written twice if the trace file is the + same as the log file. */ +CU_Test(dds_log, same_file, .init=setup, .fini=teardown) +{ + char buf[1024], *ptr; + size_t nbytes; + + dds_set_log_mask(DDS_LC_ALL); + dds_set_log_file(fh); + dds_set_trace_file(fh); + DDS_ERROR("foo%s\n", "bar"); + (void)fseek(fh, 0L, SEEK_SET); + nbytes = fread(buf, 1, sizeof(buf) - 1, fh); + /* At least foobar should have been written to the trace file. */ + CU_ASSERT_FATAL(nbytes > 6); + buf[nbytes] = '\0'; + ptr = strstr(buf, "foobar\n"); + CU_ASSERT_PTR_NOT_NULL_FATAL(ptr); + /* The message should only have been printed once, verify foobar does not + occur again. */ + ptr = strstr(ptr + 1, "foobar\n"); + CU_ASSERT_PTR_NULL(ptr); +} + +/* The sinks are considered to be the same only if the callback and userdata + both are an exact match. If the userdata is different, the function should + be called twice for log messages. */ +CU_Test(dds_log, same_sink_function) +{ + int log_cnt = 0, trace_cnt = 0; + + dds_set_log_mask(DDS_LC_ALL); + dds_set_log_sink(&count, &log_cnt); + dds_set_trace_sink(&count, &trace_cnt); + DDS_ERROR("foo%s\n", "bar"); + CU_ASSERT_EQUAL(log_cnt, 1); + CU_ASSERT_EQUAL(trace_cnt, 1); +} + +CU_Test(dds_log, exact_same_sink) +{ + int cnt = 0; + + dds_set_log_mask(DDS_LC_ALL); + dds_set_log_sink(&count, &cnt); + dds_set_trace_sink(&count, &cnt); + DDS_ERROR("foo%s\n", "bar"); + CU_ASSERT_EQUAL(cnt, 1); +} + +/* The log file must be restored if the sink is unregistered, verify the log + file is not used while the sink is registered. Verify use of the log file is + restored again when the sink is unregistered. */ +CU_Test(dds_log, no_sink, .init=setup, .fini=teardown) +{ + int ret; + char buf[1024], *ptr = NULL; + size_t cnt[2] = {0, 0}; + + /* Set the destination log file and verify the message is written. */ + dds_set_log_file(fh); + DDS_ERROR("foobar\n"); + ret = fseek(fh, 0L, SEEK_SET); + CU_ASSERT_EQUAL_FATAL(ret, 0); + buf[0] = '\0'; + cnt[0] = fread(buf, 1, sizeof(buf) - 1, fh); + buf[cnt[0]] = '\0'; + ptr = strstr(buf, "foobar\n"); + CU_ASSERT_PTR_NOT_NULL_FATAL(ptr); + + /* Register a custom sink and verify it receives the message. */ + ptr = NULL; + dds_set_log_sink(©, &ptr); + DDS_ERROR("foobaz\n"); + CU_ASSERT_PTR_NOT_NULL_FATAL(ptr); + CU_ASSERT(strcmp(ptr, "foobaz\n") == 0); + os_free(ptr); + ptr = NULL; + /* Verify it has not been written to the stream. */ + ret = fseek(fh, 0L, SEEK_SET); + CU_ASSERT_EQUAL_FATAL(ret, 0); + buf[0] = '\0'; + cnt[1] = fread(buf, 1, sizeof(buf) - 1, fh); + buf[cnt[1]] = '\0'; + ptr = strstr(buf, "foobaz\n"); + CU_ASSERT_PTR_NULL_FATAL(ptr); + + /* Unregister the custom sink and verify the default is restored. */ + dds_set_log_sink(0, NULL); + ret = fseek(fh, 0, SEEK_SET); + CU_ASSERT_EQUAL_FATAL(ret, 0); + ptr = NULL; + DDS_ERROR("foobaz\n"); + ret = fseek(fh, 0, SEEK_SET); + CU_ASSERT_PTR_NULL(ptr); + if (ptr != NULL) { + os_free(ptr); + ptr = NULL; + } + buf[0]= '\0'; + cnt[1] = fread(buf, 1, sizeof(buf) - 1, fh); +#ifdef _WIN32 + /* Write on Windows appends. */ + CU_ASSERT_EQUAL(cnt[1], cnt[0] * 2); +#else + CU_ASSERT_EQUAL(cnt[1], cnt[0]); +#endif + buf[cnt[1]] = '\0'; + ptr = strstr(buf, "foobaz\n"); + CU_ASSERT_PTR_NOT_NULL_FATAL(ptr); +} + +/* A newline terminates the message. Until that a newline is encountered, the + messages must be concatenated in the buffer. The newline is replaced by a + NULL byte if it is flushed to a sink. */ +CU_Test(dds_log, newline_terminates) +{ + char *msg = NULL; + + dds_set_log_sink(©, &msg); + DDS_ERROR("foo"); + CU_ASSERT_PTR_NULL_FATAL(msg); + DDS_ERROR("bar"); + CU_ASSERT_PTR_NULL_FATAL(msg); + DDS_ERROR("baz\n"); + CU_ASSERT_PTR_NOT_NULL_FATAL(msg); + CU_ASSERT(strcmp(msg, "foobarbaz\n") == 0); + os_free(msg); +} + +/* Nothing must be written unless a category is enabled. */ +CU_Test(dds_log, disabled_categories_discarded) +{ + char *msg = NULL; + + dds_set_log_sink(©, &msg); + DDS_INFO("foobar\n"); + CU_ASSERT_PTR_NULL_FATAL(msg); + dds_set_log_mask(DDS_LC_FATAL | DDS_LC_ERROR | DDS_LC_INFO); + DDS_INFO("foobar\n"); + CU_ASSERT_PTR_NOT_NULL_FATAL(msg); + CU_ASSERT(strcmp(msg, "foobar\n") == 0); + os_free(msg); +} + + +static os_cond cond; +static os_mutex mutex; + +struct arg { + os_cond *cond; + os_mutex *mutex; + os_time stamp; + os_time pause; +}; + +static void dummy(void *ptr, const dds_log_data_t *data) +{ + (void)ptr; + (void)data; +} + +static void block(void *ptr, const dds_log_data_t *data) +{ + (void)data; + struct arg *arg = (struct arg *)ptr; + os_mutexLock(arg->mutex); + arg->stamp = os_timeGet(); + os_condBroadcast(arg->cond); + os_mutexUnlock(arg->mutex); + + os_nanoSleep(arg->pause); +} + +static uint32_t run(void *ptr) +{ + (void)ptr; + + DDS_ERROR("foobar\n"); + + return 0; +} + +/* Log and trace sinks can be changed at runtime. However, the operation must + be synchronous! Verify the dds_set_log_sink blocks while other threads + reside in the log or trace sinks. */ +CU_Test(dds_log, synchronous_sink_changes) +{ + struct arg arg; + os_time diff, stamp; + os_threadId tid; + os_threadAttr tattr; + os_result res; + + os_mutexInit(&mutex); + os_condInit(&cond, &mutex); + (void)memset(&arg, 0, sizeof(arg)); + arg.mutex = &mutex; + arg.cond = &cond; + arg.pause.tv_sec = 0; + arg.pause.tv_nsec = 1000000; + + os_mutexLock(&mutex); + dds_set_log_sink(&block, &arg); + os_threadAttrInit(&tattr); +#ifdef __APPLE__ + tattr.schedPriority = sched_get_priority_min(SCHED_OTHER); +#endif /* __APPLE__ */ + + res = os_threadCreate(&tid, "foobar", &tattr, &run, &arg); + CU_ASSERT_EQUAL_FATAL(res, os_resultSuccess); + os_condWait(&cond, &mutex); + dds_set_log_sink(dummy, NULL); + stamp = os_timeGet(); + + CU_ASSERT(os_timeCompare(arg.stamp, stamp) == -1); + diff = os_timeSub(stamp, arg.stamp); + CU_ASSERT(os_timeCompare(arg.pause, diff) == -1); +}