src/tests/logprint \
src/tests/logger \
src/tests/logutil \
+ src/tests/critical_log \
src/tests/filters
check_CFLAGS = $(AM_CFLAGS) -O0 -fprofile-arcs -ftest-coverage -DUNIT_TEST \
src_tests_pipe_message_CFLAGS = $(check_CFLAGS)
src_tests_pipe_message_LDFLAGS = $(AM_LDFLAGS)
+src_tests_critical_log_SOURCES = src/tests/critical_log.c \
+ src/libdlog/log.c \
+ src/libdlog/loglimiter.c \
+ src/libdlog/dynamic_config.c \
+ src/shared/logcommon.c \
+ src/shared/logconfig.c \
+ src/shared/parsers.c
+src_tests_critical_log_CFLAGS = $(check_CFLAGS) -pthread
+src_tests_critical_log_LDFLAGS = $(AM_LDFLAGS) -lpthread -Wl,--wrap=getpid,--wrap=syscall,--wrap=execv,--wrap=fork,--wrap=clock_gettime
+
src_tests_filters_SOURCES = src/tests/filters.c src/shared/ptrs_list.c src/shared/logcommon.c src/shared/logprint.c
src_tests_filters_CFLAGS = $(check_CFLAGS)
src_tests_filters_LDFLAGS = $(AM_LDFLAGS)
__dlog_sec_print(id, prio, tag, "%s: %s(%d) > [SECURE_LOG] " fmt, __MODULE__, __func__, __LINE__, ##arg); \
} while (0); })
+// no SLOGE etc. variantes here because maybe people using CRITICAL logs should be paying attention
+#undef CRITICAL_LOG_
+#define CRITICAL_LOG_(id, prio, tag, fmt, arg...) \
+ ({ do { \
+ __dlog_critical_print(id, prio, tag, "%s: %s(%d) > " fmt, __MODULE__, __func__, __LINE__, ##arg); \
+ } while (0); })
+
// ---------------------------------------------------------------------
/**
* @internal
*/
int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...) __attribute__((format(printf, 4, 5)));
+int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...) __attribute__((format(printf, 4, 5)));
+
/**
* @internal
* @brief Send log with va_list.
return ret;
}
+int __critical_log_append_timestamp(char *buf, size_t buflen)
+{
+ /* NB: the timestamp may slightly differ from the one that gets
+ * added onto the copy that goes into the regular buffer, and
+ * timestamp acquisition is duplicated. This would ideally be
+ * solved, but timestamps are currently added fairly deep in
+ * backend-specific functions so for now this will have to do.
+ * Also, since we're the sender, there is just this one set of
+ * timestamps, i.e. the send timestamp! The usual alternative
+ * set of receive timestamps will never have the opportunity
+ * to get added to the entry since this log is supposed to end
+ * up straight in the file (there's potentially the trusted
+ * writer binary but we're trying to keep the set of actions
+ * it needs to do to the minimum and those timestamps would
+ * in practice be the same anyway). */
+
+ struct timespec ts;
+ clock_gettime(CLOCK_REALTIME, &ts);
+ const time_t tt = ts.tv_sec;
+ const long int real_millisec = ts.tv_nsec / 1000000;
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+#ifdef HAVE_LOCALTIME_R
+ struct tm tmBuf;
+ struct tm *const ptm = localtime_r(&tt, &tmBuf);
+#else
+ struct tm *const ptm = localtime(&tt);
+#endif
+ assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
+
+ int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
+ assert(len != 0);
+
+ int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
+ assert(tmp_len > 0);
+ assert(tmp_len < buflen - len);
+ len += tmp_len;
+
+ tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
+ assert(tmp_len != 0);
+ len += tmp_len;
+
+ tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
+ assert(tmp_len > 0);
+ assert(tmp_len < buflen - len);
+ len += tmp_len;
+
+ return len;
+}
+
+int __critical_log_build_msg(char *buf, size_t buflen, pid_t main_pid, pid_t main_tid, log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
+{
+ int len = __critical_log_append_timestamp(buf, buflen);
+ const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
+ main_pid,
+ main_tid,
+ log_name_by_id(log_id),
+ filter_pri_to_char(prio),
+ tag ?: "CRITICAL_NO_TAG");
+ assert(metadata_len > 0);
+ if (metadata_len >= buflen - len)
+ return buflen - 1; // can genuinely happen with an exceedingly large tag
+ len += metadata_len;
+
+ const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
+ assert(content_len >= 0); // 0 is legit with format == ""
+ if (content_len >= buflen - len)
+ return buflen - 1;
+ len += content_len;
+
+ return len;
+}
+
+void __critical_log_child(pid_t main_pid, pid_t main_tid, log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
+{
+ char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
+ const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
+ buf[len] = '\n';
+ buf[len + 1] = '\0';
+
+ static const char *const path = "/usr/libexec/dlog-log-critical";
+ execl(path, path /* argv[0] convention */, buf, (char *) NULL);
+
+#ifndef UNIT_TEST
+ /* Compilers are sometimes smart enough to recognize `_exit`
+ * and can put some code behind the call that makes absolutely
+ * sure the program dies. This seems to happen even in case
+ * `_exit` is replaced with something that doesn't actually
+ * abort the program, so we can't use `_exit` in tests. */
+
+ _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
+#endif
+}
+
+void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
+{
+ /* Critical log functionality is mostly done in a separate binary
+ * to handle security correctly (else every process would have to
+ * possess the necessary privilege to write onto that file, which
+ * would be opening a fairly nasty can of worms from the security
+ * point of view). Our use of exec() is why a simple thread would
+ * not suffice and we're resorting to a fork. */
+
+ const pid_t main_pid = getpid();
+ const pid_t main_tid = gettid();
+ const int child_pid = fork();
+ if (child_pid < 0)
+ return;
+ if (child_pid != 0)
+ return;
+
+ __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
+}
+
/**
* @brief Print log
* @details Print a log line
return ret;
}
+int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ __critical_log(log_id, prio, tag, fmt, ap);
+ va_end(ap);
+
+ va_start(ap, fmt);
+ int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+
int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
{
return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false);
--- /dev/null
+// DLog
+#include <dlog.h>
+#include <libdlog.h>
+#include <logcommon.h>
+
+// POSIX
+#include <time.h>
+#include <unistd.h>
+
+// C
+#include <assert.h>
+#include <string.h>
+
+bool fake_fork = false;
+pid_t fork_ret;
+pid_t __real_fork(void);
+pid_t __wrap_fork(void)
+{
+ return fake_fork ? fork_ret : __real_fork();
+}
+
+void __dlog_init_pipe(const struct log_config *conf) { }
+void __dlog_init_android(const struct log_config *conf) { }
+
+/* The actual code calls `execl`. The underlying syscall being wrapped around is `execve`.
+ * Don't ask difficult questions like "why aren't we wrapping either of those" */
+bool executed;
+bool message_ok;
+int __wrap_execv(const char *filename, char *const argv[], char *const envp[])
+{
+ executed = true;
+
+ assert(filename);
+ assert(!strcmp(filename, "/usr/libexec/dlog-log-critical"));
+
+ assert(argv[0]);
+ assert(!strcmp(filename, argv[0])); // argv[0] convention
+
+ assert(argv[1]);
+ assert(argv[1][strlen(argv[1]) - 1] == '\n');
+
+ message_ok = !strncmp(argv[1], "02-20 12:34:56.789", 18);
+ // skip timezone [18; 23), we don't wrap it and I don't trust the buildprocess that much
+ message_ok &= !strcmp(argv[1] + 23, " 1337.666 P 1729 T 2077 Bmain E/FHTAG : PHNGLUI MGLW'NAFH\n");
+
+ assert(!argv[2]);
+
+ return 0;
+}
+
+long __wrap_syscall(long number, long arg)
+{
+ assert(number == SYS_gettid);
+ return 2077;
+}
+
+pid_t __real_getpid();
+pid_t __wrap_getpid()
+{
+ return 1729;
+}
+
+int __wrap_clock_gettime(clockid_t clk_id, struct timespec *tp)
+{
+ if (clk_id == CLOCK_REALTIME) {
+ tp->tv_sec = 1014208496;
+ tp->tv_nsec = 789000000;
+ } else {
+ tp->tv_sec = 1337;
+ tp->tv_nsec = 666000000;
+ }
+ return 0;
+}
+
+bool called_atexit;
+void atexit_f(void)
+{
+ called_atexit = true;
+}
+
+int main()
+{
+ fake_fork = true;
+ called_atexit = false;
+ assert(!atexit(atexit_f));
+
+ fork_ret = -1;
+ __dlog_critical_print(LOG_ID_MAIN, DLOG_ERROR, "TAG", "%s", "YOU'RE IT");
+ assert(!executed);
+
+ fork_ret = 17;
+ __dlog_critical_print(LOG_ID_MAIN, DLOG_ERROR, "MONTAG", "%s%d", "F", 451);
+ assert(!executed);
+
+ fork_ret = 0;
+ message_ok = false;
+ __dlog_critical_print(LOG_ID_MAIN, DLOG_ERROR, "FHTAG", "PHNGLUI MGLW'NAFH");
+ assert(executed);
+ assert(message_ok);
+
+ // Exceedingly huge string that, when used as the tag, doesn't leave any space for the message
+ static const char big_str[] = "- Tak wiec, Mariusie, w koncu cie odnalazlem.\n- Tyrael! Tak... tak, teraz... teraz Cie poznaje. Powinienem byl sie domyslic, ze bedziesz podrozowal w przebraniu. Oni... oni zawsze obserwuja...\n- Od dawna cie szukalem, Mariusie. Zaczalem juz nawet myslec, ze NIE CHCESZ, by cie znaleziono.\n- Och, wybacz mi, Tyraelu... To nie moja wina...\n- Nie twoja?! Wyjasnij mi, Mariusie, jak to nie twoja wina.\n- Wedrowiec! Tak, to byl on... to byl wedrowiec.\n\nDni, ktore spedzilem w cytadeli Lotrzyc wydaja sie tak odlegle. Tam, wysoko w gorach, za wschodnimi wrotami, wsrod innych wyrzutkow znalazlem schronienie przed nawiedzajacymi mnie wspomnieniami. Och, kazdej nocy walczylem ze snem - bo kiedy snilem, wracaly wspomnienia... wspomnienia klasztoru i zla, ktore go opanowalo. Sny... wspomnienia... nie widze juz miedzy nimi roznicy!... Czy zlo z moich koszmarow caly czas bylo tuz za mna? Jak on mnie tu odnalazl? Jak ten wrak czlowieka, ledwo zdolny uniesc ciezar wlasnego miecza, mogl wzbudzac taka groze, ze musialem sie tu przed nim ukrywac? Sprawial wrazenie, jakby walczyl z wlasnymi demonami... i przegrywal te walke. Gdy na to patrzylem, myslalem ze kompletnie oszalalem. Groza! Zniszczenie! Zlo, ktorego bylem swiadkiem - jak inaczej moglem je wyjasnic? Czy byly to demony z moich snow? Czy tez zrodzil je Wedrowiec? Dlaczego za nim poszedlem? Nie wiem - dlaczego wszystko dzieje sie jak we snie? Wiem tylko, ze gdy na mnie wskazal, musialem za nim podazyc. Od tamtej chwili podrozowalismy razem. Na Wschod. ZAWSZE na Wschod.\n\nPodrozowalismy na Wschod, przez gory i rozlegle pustynie zniszczonych krain. Dni mijaly, a moj towarzysz w koncu opowiedzial mi o sobie - ze byl kiedys wielkim wojownikiem, i ze dreczy go ponura tajemnica. Przez cala wiecznosc podrozowalismy przez jalowe pustkowia - jak dlugo? Nie mam pojecia. I zawsze, gdzies na horyzoncie, ponury oblok podazal za nami. W koncu wedrowka zakonczyla sie - przeszlismy ostatnie wzniesienie. Przed nami byl cel naszej wedrowki: Lut Gholein, lsniacy klejnot u stop wielkiego morza. Tej ostatniej nocy rozbilismy obozowisko; usnalem, po raz pierwszy od wielu tygodni. Moze byla to zasluga ciepla pustyni, albo szumu oceanu. Sny powrocily, ale z pewnoscia nie moje! Ujrzalem obraz wielkiego maga - Tal Rasha. (Ty tez tam byles, Tyraelu - pamietam, ze widzialem Cie w moim snie.) Jego bracia scigali wielkiego demona - Baala, Pana Zniszczenia - ktory swobodnie kroczyl po ziemi. Probowali uwiezic go wewnatrz uswieconego kamienia. Ich proby nie powiodly sie. Wtedy Tal Rasha z wlasnej woli oglosil, ze uwiezi demona w sobie: tak powstaloby wiezienie. Nakazal swym braciom, by zamkneli go w grobowcu. Tam, gleboko pod piaskami, przez cala wiecznosc zmagac sie bedzie z demonem! \"Teraz wiesz, czego szukam\". Nastepnego ranka przeszlismy przez wzgorza w strone Lut Gholein. Nie mialem wtedy pojecia, jaka groza tam na mnie czeka...\n\nMoj towarzysz zaglebil sie w wilgotne, zimne powietrze grobowca. To go jakby... wzmocnilo! Stanalem w drzwiach miedzy swiatlem a ciemnoscia. Resztki zdrowego rozsadku blagaly mnie, bym tam nie wchodzil... ale ten glos byl juz tylko szeptem. Gdy tak schodzilismy w dol krypty, coraz glebiej i glebiej, zauwazylem zmiane zachodzaca w moim towarzyszu. Wygladalo na to, ze odzyskuje sily! Ja niewiele widzialem w polmroku, ale zdalo mi sie, ze on zna droge. W koncu dotarlismy do wielkiej komnaty... wlasnie wtedy zrozumialem, ze caly czas sie mylilem! Moj towarzysz nie odzyskiwal sil - on tracil resztki swego czlowieczenstwa. Poruszal sie demonicznie szybko i wtedy... Ty sie pojawiles, Tyraelu.\n- Stoj! Zamknieta tutaj bestia nie moze zostac uwolniona - nawet przez ciebie!\n- Patrz, co ze mna zrobili! Uwolnij mnie, pomoz! Szybciej, prosze, szybciej!\n- *NIE*! NIE CZYN TEGO!... - GLUPCZE! Wlasnie sprowadziles na ten swiat zaglade - nie jestes w stanie wyobrazic sobie nawet, co dzis obudziles! Idz do Swiatyni Swiatla we wschodnim miescie Kurast; tam znajdziesz otwarte przed toba wrota Piekla. Muszisz zdobyc sie na odwage i je przekroczyc, Mariusie! Zabierz ten kamien do Piekielej Kuzni - tam zostanie zniszczony; a teraz biegnij, zabierz kamien i BIEGNIJ!\n\nJaki mialem wybor? Pobieglem. Zrobilem, jak mi kazales, Tyraelu. Znalazlem swiatynie Zakarum. W najdalszym zakatku swiatyni trafilem na ponure zgromadzenie: mojego towarzysza, Wedrowca - Tal Rasha - i wielkie zlo, ktore musialo byc wcieleniem Pana Nienawisci, Mefista. Wtedy uslyszalem glos... byl jak *tysiac igiel* w moim sercu.\n\"Moi bracia, po dlugim oczekiwaniu znowu stoimy zjednoczeni. Piekielne Wrota zostaly przygotowane, a czas naszego ostatecznego zwyciestwa jest w zasiegu reki. Niech droga do Piekla stanie otworem! Zlo, ktore raz zostalo pokonane, powstanie na nowo; spowite w przebranie zwyklego czlowieka, kroczyc bedzie miedzy niewinnymi; a Groza pochlonie tych, co mieszkaja na ziemi! Niebiosa zaplacza plomiennymi lzami; prawi upadna przed niegodziwcami, i cale stworzenie zadrzy na widok plonacych sztandarow Piekiel!\" (To, co widzialem, nie bylo przeznaczone dla oczu smiertelnika.) \"A teraz ruszaj, moj bracie - jestes zwiastunem naszego powrotu. Diablo, niech twa groza powroci!\"\n\nPozniej uslyszalem, ze zostal pokonany w Piekle, a Kamienie Dusz zniszczono w Piekielnej Kuzni. Oprocz jednego... och, zawiodlem, Tyraelu, nie moglem zrobic tego, o co mnie prosiles... nie moglem przejsc przez brame... wybacz mi, Tyraelu. Wybacz mi!...\n- Mariusie, daj mi kamien, a wszystko zostanie wybaczone. Daj mi go, Mariusie.\n- Wez go, zabierz! Ciesze sie ze to juz sie skonczylo, Tyraelu. Zobacz, co ze mna zrobil ten kamien!...\n- Nie zawiodles, starcze. Zrobiles dokladnie to, co miales zrobic. Tylko widzisz!... Ja nie jestem Archaniolem Tyraelem.\n- Baal!... Nie, nie!.. Co uczynilem, zeby na to zasluzyc?!...\n- Dobrze sie spisales, Mariusie. Mysle, ze powinienes teraz otrzymac swoja nagrode!";
+ assert(sizeof big_str > LOG_MAX_PAYLOAD_SIZE);
+
+ // No content checks needed, it just needs not to explode
+ executed = false;
+ __dlog_critical_print(LOG_ID_MAIN, DLOG_ERROR, big_str, "stuff");
+ assert(executed);
+ executed = false;
+ __dlog_critical_print(LOG_ID_MAIN, DLOG_ERROR, "stuff", big_str);
+ assert(executed);
+
+ assert(!called_atexit);
+ fake_fork = false;
+ return 0;
+}
projects / platform / core / system / dlog.git / commitdiff