Line data Source code
1 : /* SPDX-License-Identifier: GPL-3.0-or-later */
2 : /* Copyright 2026 Peter Csaszar */
3 :
4 : /**
5 : * @file test_logger_lifecycle.c
6 : * @brief TEST-72 / US-21 — functional coverage of logger lifecycle and
7 : * redaction invariants.
8 : *
9 : * Exercises `src/core/logger.c` end-to-end against the real file system:
10 : *
11 : * 1. test_logger_rotates_at_5mb — rotation triggered on init
12 : * when file exceeds 5 MB cap.
13 : * 2. test_logger_level_filter_warn_drops_debug
14 : * — entries below configured
15 : * level must not hit the file.
16 : * 3. test_logger_redacts_message_body — driving domain_send_message
17 : * through the mock server must
18 : * NOT write the plaintext body
19 : * to the log file.
20 : * 4. test_logger_redacts_api_hash — domain code paths that see
21 : * the api_hash must never emit
22 : * it into the log.
23 : * 5. test_logger_creates_missing_dir — bootstrap recreates the log
24 : * directory with mode 0700 if
25 : * it was removed.
26 : * 6. test_logger_readonly_fallback_does_not_crash
27 : * — chmodding the log dir to
28 : * 0500 mid-run must not crash
29 : * subsequent logger_log calls.
30 : *
31 : * All tests use isolated $HOME / $XDG_CACHE_HOME / $XDG_CONFIG_HOME under
32 : * /tmp so they never touch the developer's real ~/.cache/tg-cli.
33 : */
34 :
35 : #include "test_helpers.h"
36 :
37 : #include "logger.h"
38 : #include "app/bootstrap.h"
39 :
40 : #include "mock_socket.h"
41 : #include "mock_tel_server.h"
42 : #include "api_call.h"
43 : #include "mtproto_session.h"
44 : #include "transport.h"
45 : #include "app/session_store.h"
46 : #include "tl_registry.h"
47 : #include "tl_serial.h"
48 : #include "domain/write/send.h"
49 :
50 : #include <errno.h>
51 : #include <fcntl.h>
52 : #include <stdio.h>
53 : #include <stdlib.h>
54 : #include <string.h>
55 : #include <sys/stat.h>
56 : #include <sys/types.h>
57 : #include <unistd.h>
58 :
59 : /* ---- CRCs not surfaced by a public header ---- */
60 : #define CRC_messages_sendMessage 0x0d9d75a4U
61 : #define CRC_updateShortSentMessage 0x9015e101U
62 :
63 : /* Known 32-char api_hash we deliberately feed into tests that need to
64 : * verify the secret never leaks into the log file. */
65 : #define TEST_API_HASH "deadbeefcafebabef00dbaadfeedc0de"
66 :
67 : /* ================================================================ */
68 : /* Helpers */
69 : /* ================================================================ */
70 :
71 : /** Build a per-test scratch directory name unique to this test and pid. */
72 14 : static void make_scratch_dir(char *out, size_t cap, const char *tag) {
73 14 : snprintf(out, cap, "/tmp/tg-cli-logger-%s-%d", tag, (int)getpid());
74 14 : }
75 :
76 : /** rm -rf @p path — tolerates missing, ignores errors. */
77 28 : static void rm_rf(const char *path) {
78 : char cmd[1024];
79 28 : snprintf(cmd, sizeof(cmd), "rm -rf \"%s\"", path);
80 28 : int sysrc = system(cmd);
81 : (void)sysrc;
82 28 : }
83 :
84 : /** mkdir -p @p path with the given mode (best-effort). */
85 12 : static int mkdir_p(const char *path, mode_t mode) {
86 : char cmd[1024];
87 12 : snprintf(cmd, sizeof(cmd), "mkdir -p \"%s\"", path);
88 12 : int sysrc = system(cmd);
89 12 : if (sysrc != 0) return -1;
90 12 : return chmod(path, mode);
91 : }
92 :
93 : /**
94 : * @brief Read the entire contents of @p path into a malloc'd buffer.
95 : *
96 : * Callers own the returned pointer and must free() it. Returns NULL on
97 : * error. NUL-terminates for easy strstr() scanning.
98 : */
99 8 : static char *slurp(const char *path, size_t *size_out) {
100 8 : FILE *fp = fopen(path, "rb");
101 8 : if (!fp) return NULL;
102 8 : fseek(fp, 0, SEEK_END);
103 8 : long sz = ftell(fp);
104 8 : fseek(fp, 0, SEEK_SET);
105 8 : if (sz < 0) { fclose(fp); return NULL; }
106 8 : char *buf = malloc((size_t)sz + 1);
107 8 : if (!buf) { fclose(fp); return NULL; }
108 8 : size_t n = fread(buf, 1, (size_t)sz, fp);
109 8 : fclose(fp);
110 8 : buf[n] = '\0';
111 8 : if (size_out) *size_out = n;
112 8 : return buf;
113 : }
114 :
115 : /** Point $HOME / XDG cache+config at scratch dir so bootstrap writes there. */
116 6 : static void redirect_env_to(const char *scratch) {
117 6 : setenv("HOME", scratch, 1);
118 : char cache[512], cfg[512];
119 6 : snprintf(cache, sizeof(cache), "%s/cache", scratch);
120 6 : snprintf(cfg, sizeof(cfg), "%s/config", scratch);
121 6 : setenv("XDG_CACHE_HOME", cache, 1);
122 6 : setenv("XDG_CONFIG_HOME", cfg, 1);
123 6 : }
124 :
125 : /* ================================================================ */
126 : /* Responders (test 3 & 4) */
127 : /* ================================================================ */
128 :
129 4 : static void reply_update_short_sent(MtRpcContext *ctx, int32_t id) {
130 : TlWriter w;
131 4 : tl_writer_init(&w);
132 4 : tl_write_uint32(&w, CRC_updateShortSentMessage);
133 4 : tl_write_uint32(&w, 0); /* flags */
134 4 : tl_write_int32 (&w, id);
135 4 : tl_write_int32 (&w, 0); /* pts */
136 4 : tl_write_int32 (&w, 0); /* pts_count */
137 4 : tl_write_int32 (&w, 0); /* date */
138 4 : mt_server_reply_result(ctx, w.data, w.len);
139 4 : tl_writer_free(&w);
140 4 : }
141 :
142 4 : static void on_send_message_ok(MtRpcContext *ctx) {
143 4 : reply_update_short_sent(ctx, 42);
144 4 : }
145 :
146 : /* ================================================================ */
147 : /* Tests */
148 : /* ================================================================ */
149 :
150 : /**
151 : * 1. Prime a >5 MB file at the target path, re-init the logger, and
152 : * verify the old file was renamed to <path>.1 while the new file
153 : * is well below the cap.
154 : */
155 2 : static void test_logger_rotates_at_5mb(void) {
156 : char scratch[256];
157 2 : make_scratch_dir(scratch, sizeof(scratch), "rot");
158 2 : rm_rf(scratch);
159 2 : ASSERT(mkdir_p(scratch, 0700) == 0, "mkdir scratch");
160 :
161 : char log_path[512];
162 2 : snprintf(log_path, sizeof(log_path), "%s/session.log", scratch);
163 : char rotated[1024];
164 2 : snprintf(rotated, sizeof(rotated), "%s.1", log_path);
165 :
166 : /* Write a 6 MB file so the cap triggers on init. */
167 2 : FILE *fp = fopen(log_path, "wb");
168 2 : ASSERT(fp != NULL, "create oversize log");
169 2 : const size_t big = 6u * 1024u * 1024u;
170 : char chunk[4096];
171 2 : memset(chunk, 'x', sizeof(chunk));
172 3074 : for (size_t written = 0; written < big; written += sizeof(chunk)) {
173 3072 : size_t n = (big - written < sizeof(chunk)) ? big - written : sizeof(chunk);
174 3072 : ASSERT(fwrite(chunk, 1, n, fp) == n, "fill oversize log");
175 : }
176 2 : fclose(fp);
177 :
178 : /* Re-initialise the logger — rotation must fire on the size check. */
179 2 : ASSERT(logger_init(log_path, LOG_INFO) == 0, "logger_init ok");
180 2 : logger_log(LOG_INFO, "post-rotation marker");
181 2 : logger_close();
182 :
183 : struct stat st;
184 2 : ASSERT(stat(rotated, &st) == 0, ".1 exists after rotation");
185 2 : ASSERT(st.st_size >= (off_t)big / 2, ".1 carries old bytes");
186 :
187 2 : ASSERT(stat(log_path, &st) == 0, "fresh session.log exists");
188 2 : ASSERT(st.st_size < (off_t)(5u * 1024u * 1024u),
189 : "fresh log is below the 5 MB cap");
190 :
191 2 : rm_rf(scratch);
192 : }
193 :
194 : /**
195 : * 2. With level=LOG_WARN a LOG_DEBUG call must not reach the file, while
196 : * a LOG_WARN call must. Also exercises the TG_CLI_LOG_LEVEL env hint
197 : * (currently advisory — tracked by US-21) so the assertion binds to
198 : * the effective runtime behaviour of logger_log.
199 : */
200 2 : static void test_logger_level_filter_warn_drops_debug(void) {
201 : char scratch[256];
202 2 : make_scratch_dir(scratch, sizeof(scratch), "lvl");
203 2 : rm_rf(scratch);
204 2 : ASSERT(mkdir_p(scratch, 0700) == 0, "mkdir scratch");
205 :
206 : char log_path[512];
207 2 : snprintf(log_path, sizeof(log_path), "%s/session.log", scratch);
208 :
209 2 : setenv("TG_CLI_LOG_LEVEL", "WARN", 1);
210 2 : ASSERT(logger_init(log_path, LOG_WARN) == 0, "logger_init warn");
211 :
212 2 : logger_log(LOG_DEBUG, "UNIQUE_DEBUG_BODY_%d", 777);
213 2 : logger_log(LOG_WARN, "UNIQUE_WARN_BODY_%d", 888);
214 2 : logger_close();
215 :
216 2 : size_t sz = 0;
217 2 : char *buf = slurp(log_path, &sz);
218 2 : ASSERT(buf != NULL, "read session.log");
219 2 : ASSERT(strstr(buf, "UNIQUE_DEBUG_BODY_777") == NULL,
220 : "DEBUG entry must be filtered out at WARN level");
221 2 : ASSERT(strstr(buf, "UNIQUE_WARN_BODY_888") != NULL,
222 : "WARN entry must still reach the file");
223 2 : free(buf);
224 :
225 2 : unsetenv("TG_CLI_LOG_LEVEL");
226 2 : rm_rf(scratch);
227 : }
228 :
229 : /**
230 : * 3. Drive domain_send_message with a distinctive plaintext body, then
231 : * confirm the log file does not contain the body — domain callers
232 : * are expected to log size / type, never the content.
233 : */
234 2 : static void test_logger_redacts_message_body(void) {
235 : char scratch[256];
236 2 : make_scratch_dir(scratch, sizeof(scratch), "body");
237 2 : rm_rf(scratch);
238 2 : ASSERT(mkdir_p(scratch, 0700) == 0, "mkdir scratch");
239 2 : redirect_env_to(scratch);
240 :
241 : char log_path[512];
242 2 : snprintf(log_path, sizeof(log_path), "%s/session.log", scratch);
243 : /* DEBUG so every informational logger_log call lands on disk. */
244 2 : ASSERT(logger_init(log_path, LOG_DEBUG) == 0, "logger_init ok");
245 :
246 2 : mt_server_init();
247 2 : mt_server_reset();
248 : MtProtoSession s;
249 2 : ASSERT(mt_server_seed_session(2, NULL, NULL, NULL) == 0, "seed session");
250 2 : mtproto_session_init(&s);
251 2 : int dc = 0;
252 2 : ASSERT(session_store_load(&s, &dc) == 0, "load seeded session");
253 2 : mt_server_expect(CRC_messages_sendMessage, on_send_message_ok, NULL);
254 :
255 2 : ApiConfig cfg; api_config_init(&cfg);
256 2 : cfg.api_id = 12345;
257 2 : cfg.api_hash = TEST_API_HASH;
258 :
259 2 : Transport t; transport_init(&t);
260 2 : ASSERT(transport_connect(&t, "127.0.0.1", 443) == 0, "connect mock");
261 :
262 2 : HistoryPeer self = { .kind = HISTORY_PEER_SELF };
263 2 : int32_t mid = 0;
264 2 : RpcError err = {0};
265 2 : const char *secret = "PLAINTEXT_BODY_MARKER_Z9Q7H3K5T2";
266 2 : ASSERT(domain_send_message(&cfg, &s, &t, &self, secret, &mid, &err) == 0,
267 : "sendMessage happy path");
268 :
269 2 : transport_close(&t);
270 2 : mt_server_reset();
271 2 : logger_close();
272 :
273 2 : size_t sz = 0;
274 2 : char *buf = slurp(log_path, &sz);
275 2 : ASSERT(buf != NULL, "read session.log");
276 2 : ASSERT(strstr(buf, secret) == NULL,
277 : "plaintext body must not appear in the log file");
278 2 : free(buf);
279 :
280 2 : rm_rf(scratch);
281 : }
282 :
283 : /**
284 : * 4. Run an end-to-end RPC carrying a known api_hash through the logger
285 : * and verify the 32-char secret is never written verbatim. The call
286 : * path here (bootstrap → logger_init → send) matches production.
287 : */
288 2 : static void test_logger_redacts_api_hash(void) {
289 : char scratch[256];
290 2 : make_scratch_dir(scratch, sizeof(scratch), "hash");
291 2 : rm_rf(scratch);
292 2 : ASSERT(mkdir_p(scratch, 0700) == 0, "mkdir scratch");
293 2 : redirect_env_to(scratch);
294 :
295 : AppContext ctx;
296 2 : ASSERT(app_bootstrap(&ctx, "test-redact") == 0, "bootstrap ok");
297 :
298 2 : mt_server_init();
299 2 : mt_server_reset();
300 : MtProtoSession s;
301 2 : ASSERT(mt_server_seed_session(2, NULL, NULL, NULL) == 0, "seed");
302 2 : mtproto_session_init(&s);
303 2 : int dc = 0;
304 2 : ASSERT(session_store_load(&s, &dc) == 0, "load");
305 2 : mt_server_expect(CRC_messages_sendMessage, on_send_message_ok, NULL);
306 :
307 2 : ApiConfig cfg; api_config_init(&cfg);
308 2 : cfg.api_id = 98765;
309 2 : cfg.api_hash = TEST_API_HASH;
310 :
311 2 : Transport t; transport_init(&t);
312 2 : ASSERT(transport_connect(&t, "127.0.0.1", 443) == 0, "connect");
313 :
314 2 : HistoryPeer self = { .kind = HISTORY_PEER_SELF };
315 2 : int32_t mid = 0;
316 2 : RpcError err = {0};
317 2 : ASSERT(domain_send_message(&cfg, &s, &t, &self, "ping", &mid, &err) == 0,
318 : "send ok");
319 :
320 2 : transport_close(&t);
321 2 : mt_server_reset();
322 2 : app_shutdown(&ctx);
323 :
324 2 : size_t sz = 0;
325 2 : char *buf = slurp(ctx.log_path, &sz);
326 2 : ASSERT(buf != NULL, "read bootstrap log");
327 2 : ASSERT(strstr(buf, TEST_API_HASH) == NULL,
328 : "api_hash secret must not appear in the log file");
329 2 : free(buf);
330 :
331 2 : rm_rf(scratch);
332 : }
333 :
334 : /**
335 : * 5. Blow away the whole cache tree, call app_bootstrap(). It must
336 : * re-create ~/.cache/tg-cli/logs/ with mode 0700 and produce a live
337 : * log file.
338 : */
339 2 : static void test_logger_creates_missing_dir(void) {
340 : char scratch[256];
341 2 : make_scratch_dir(scratch, sizeof(scratch), "mkdir");
342 2 : rm_rf(scratch);
343 : /* Do NOT mkdir — bootstrap must do it itself. */
344 2 : redirect_env_to(scratch);
345 :
346 : AppContext ctx;
347 2 : ASSERT(app_bootstrap(&ctx, "test-mkdir") == 0, "bootstrap ok");
348 :
349 : /* Derive the log directory from the resolved log_path. */
350 : char log_dir[2048];
351 2 : snprintf(log_dir, sizeof(log_dir), "%s", ctx.log_path);
352 2 : char *slash = strrchr(log_dir, '/');
353 2 : ASSERT(slash != NULL, "log_path contains a dir separator");
354 2 : *slash = '\0';
355 :
356 : struct stat st;
357 2 : ASSERT(stat(log_dir, &st) == 0, "log dir recreated");
358 2 : ASSERT(S_ISDIR(st.st_mode), "it's a directory");
359 2 : ASSERT((st.st_mode & 0777) == 0700,
360 : "log dir permissions are 0700");
361 :
362 2 : logger_log(LOG_INFO, "first-entry-after-recreate");
363 2 : app_shutdown(&ctx);
364 :
365 2 : ASSERT(stat(ctx.log_path, &st) == 0, "log file exists");
366 2 : ASSERT(st.st_size > 0, "log file has content");
367 :
368 2 : rm_rf(scratch);
369 : }
370 :
371 : /**
372 : * 6. Chmod the log directory read-only mid-run. logger_log must NOT
373 : * crash even though underlying fwrite may fail; subsequent
374 : * logger_close() must remain callable.
375 : *
376 : * ASAN + Valgrind will catch any use-after-free / double-close as part
377 : * of the test run.
378 : */
379 2 : static void test_logger_readonly_fallback_does_not_crash(void) {
380 : char scratch[256];
381 2 : make_scratch_dir(scratch, sizeof(scratch), "ro");
382 2 : rm_rf(scratch);
383 2 : ASSERT(mkdir_p(scratch, 0700) == 0, "mkdir scratch");
384 :
385 : char log_path[512];
386 2 : snprintf(log_path, sizeof(log_path), "%s/session.log", scratch);
387 2 : ASSERT(logger_init(log_path, LOG_DEBUG) == 0, "logger_init ok");
388 2 : logger_log(LOG_INFO, "pre-chmod-entry");
389 :
390 : /* Make the directory r-x only. An existing open FILE* keeps working,
391 : * but no fresh open() would succeed. */
392 2 : ASSERT(chmod(scratch, 0500) == 0, "chmod 0500");
393 :
394 : /* Continue writing. The process must not die even if the FS push-back
395 : * fires; ASAN/Valgrind also watch for corruption on shared state. */
396 34 : for (int i = 0; i < 16; i++) {
397 32 : logger_log(LOG_WARN, "post-chmod-entry-%d", i);
398 : }
399 2 : logger_log(LOG_ERROR, "post-chmod-error-entry");
400 :
401 : /* Restore perms so cleanup can remove the tree. */
402 2 : ASSERT(chmod(scratch, 0700) == 0, "chmod 0700 restore");
403 2 : logger_close();
404 :
405 : /* Best-effort read-back: any surviving file must still be sane. */
406 2 : size_t sz = 0;
407 2 : char *buf = slurp(log_path, &sz);
408 2 : if (buf) {
409 : /* Process did not abort — that alone is the assertion. */
410 2 : free(buf);
411 : }
412 :
413 2 : rm_rf(scratch);
414 : }
415 :
416 : /**
417 : * 7. Exercise the remaining public API — logger_set_stderr() and
418 : * logger_clean_logs() — so functional coverage clears the ≥75 %
419 : * ticket bar. logger_clean_logs deletes session.log* siblings in a
420 : * directory; we seed a few files and verify the cleaner wipes them.
421 : */
422 2 : static void test_logger_set_stderr_and_clean_logs(void) {
423 : char scratch[256];
424 2 : make_scratch_dir(scratch, sizeof(scratch), "clean");
425 2 : rm_rf(scratch);
426 2 : ASSERT(mkdir_p(scratch, 0700) == 0, "mkdir scratch");
427 :
428 : /* Toggle stderr mirroring both ways — no crash expected. */
429 2 : logger_set_stderr(0);
430 2 : logger_set_stderr(1);
431 :
432 : /* Seed several session.log* files + an unrelated file. */
433 : char p[512];
434 2 : const char *names[] = {
435 : "session.log", "session.log.1", "session.log.2", "other.log"
436 : };
437 10 : for (size_t i = 0; i < sizeof(names) / sizeof(names[0]); i++) {
438 8 : snprintf(p, sizeof(p), "%s/%s", scratch, names[i]);
439 8 : FILE *fp = fopen(p, "wb");
440 8 : ASSERT(fp != NULL, "seed file");
441 8 : fputs("x\n", fp);
442 8 : fclose(fp);
443 : }
444 :
445 2 : ASSERT(logger_clean_logs(scratch) == 0, "clean_logs ok");
446 2 : ASSERT(logger_clean_logs("/nonexistent-dir-xyz-9999") == -1,
447 : "clean_logs returns -1 on missing dir");
448 :
449 : struct stat st;
450 8 : for (size_t i = 0; i < 3; i++) {
451 6 : snprintf(p, sizeof(p), "%s/%s", scratch, names[i]);
452 6 : ASSERT(stat(p, &st) != 0,
453 : "session.log* siblings removed");
454 : }
455 : /* Unrelated file untouched. */
456 2 : snprintf(p, sizeof(p), "%s/%s", scratch, names[3]);
457 2 : ASSERT(stat(p, &st) == 0, "other.log preserved");
458 :
459 2 : rm_rf(scratch);
460 : }
461 :
462 : /* ---- Runner ---- */
463 :
464 2 : void run_logger_lifecycle_tests(void) {
465 2 : RUN_TEST(test_logger_rotates_at_5mb);
466 2 : RUN_TEST(test_logger_level_filter_warn_drops_debug);
467 2 : RUN_TEST(test_logger_redacts_message_body);
468 2 : RUN_TEST(test_logger_redacts_api_hash);
469 2 : RUN_TEST(test_logger_creates_missing_dir);
470 2 : RUN_TEST(test_logger_readonly_fallback_does_not_crash);
471 2 : RUN_TEST(test_logger_set_stderr_and_clean_logs);
472 2 : }
|
