Sometimes deadlocks on tlog_exit() in threaded app

[gocowim]

Right now I can only tell that my application sometimes doesn't end because tlog_exit() doesn't return.

If I find a simple code to reproduce it, I will add it here, of course...

The simplified pseudo code looks like that:

void signal_handler( signal ) {case {SIGINT, SIGTERM: server_stop = 1;} }
void *thread() { while (server_stop != 1) { do stuff; tlog(somtehing); }
main() {
    signal(SIGINT, handle_signal);
    signal(SIGTERM, handle_signal);

    tlog_init(logfile, 1M, 4, 0, TLOG_SCREEN_COLOR);
    for (i = 0 .. N) {
        pthread_create(thread);
    }

   while (server_stop != 1) { do something; sleep() }

    for (i = 0 .. N) {
        pthread_join(thread);
    }
    tlog("DONE");
    tlog_exit();
}

lsof -t /path/to/logfile shows that the process still has the file open.

[pymumu]

#include "tlog.h"
#include <pthread.h>
#include <signal.h>
#include <stdio.h>
#include <unistd.h>

int server_stop = 0;

void signal_handler(int sig)
{
    switch (sig) {
    case SIGINT:
    case SIGTERM:
        server_stop = 1;
        tlog(TLOG_INFO, "Received signal %d, stopping server", sig);
        break;
    default:
        break;
    }
}
void *thread_func(void *arg)
{
    int thread_id = (int)(long)arg;
    tlog(TLOG_INFO, "Thread %d started", thread_id);
    while (server_stop != 1) {
        tlog(TLOG_INFO, "Thread %d is running", thread_id);
        sleep(1);
    }

    return NULL;
}

int main(int argc, char *argv[])
{
#define N (3)
    long i = 0;
    pthread_t thread[N];
    signal(SIGINT, signal_handler);
    signal(SIGTERM, signal_handler);

    tlog_init("1.log", 1024 * 1024, 4, 0, TLOG_SCREEN_COLOR);
    for (i = 0; i < N; i++) {
        pthread_create(&thread[i], NULL, thread_func, (void *)i);
    }

    while (server_stop != 1) {
        sleep(1);
    }

    for (i = 0; i < N; i++) {
        pthread_join(thread[i], NULL);
    }
    tlog(TLOG_INFO, "DONE");
    tlog_exit();
}

tested, works fine.

[2025-06-27 08:07:37,525][ INFO][      example.cpp:24  ] Thread 0 started
[2025-06-27 08:07:37,525][ INFO][      example.cpp:26  ] Thread 0 is running
[2025-06-27 08:07:37,525][ INFO][      example.cpp:24  ] Thread 1 started
[2025-06-27 08:07:37,525][ INFO][      example.cpp:24  ] Thread 2 started
[2025-06-27 08:07:37,525][ INFO][      example.cpp:26  ] Thread 2 is running
[2025-06-27 08:07:37,525][ INFO][      example.cpp:26  ] Thread 1 is running
[2025-06-27 08:07:37,993][ INFO][      example.cpp:15  ] Received signal 2, stopping server
[2025-06-27 08:07:38,525][ INFO][      example.cpp:53  ] DONE

[gocowim]

It works fine until it doesn't ... ;-)

That's the issue with deadlocks. It depends on the state at the moment when the signal is handled. Which is different every time. So you have to run it 1000 times and send the signal 1000 times... and then maybe you get a deadlock a few times.

It happend with my app two of the maybe 300 times I run it so far.

[pymumu]

I use this log component on smartdns and other large-scale programs, and I have not encountered log deadlock problems.
Is there any other scenario that may cause this?

Or if you find a deadlock, use gdb to output the deadlock call stack

[pymumu]

In addition, DO NOT use tlog functions in signal handler, these functions are not signal safe.

[gocowim]

These are litreally the last few lines of my program:

    if(ecode == EXIT_SUCCESS) {
        tlog_info("FiasProxy shutdown complete");
    } else {
        tlog_error("FiasProxy shutdown with errors");
    }
    tlog_exit();

    cfg_free(cfg); // Free the main configuration object

    return ecode;

It prints the line "FiasProxy shutdown complete" but doesn't end. cfg_free() comes from libconfuse - I can't imagine a way that this would block. And the fact that the logfile is still open by the process also tells me that tlog_exit() didn't end the writer.

Of course I will do some more digging... But at the moment I don't have any idea of another scenario causing this.

Thanks for the hint. My signal handler uses only write(STDERR_FILENO, ...) - this should be async-signal-safe...

[gocowim]

I forgot to mention that I also block a few signals in main(),

Could this be an issue?

    signal(SIGPIPE, SIG_IGN); // Ignore SIGPIPE to prevent crashes on broken pipes
    signal(SIGUSR1, SIG_IGN); // Ignore SIGUSR1 to prevent unexpected behavior
    signal(SIGUSR2, SIG_IGN); // Ignore SIGUSR2 to prevent unexpected behavior
    signal(SIGCHLD, SIG_IGN); // Ignore SIGCHLD to prevent zombie processes

[pymumu]

signal(SIGCHLD, SIG_IGN); // Ignore SIGCHLD to prevent zombie processes

this may cause issue, tlog starts a child process to compress log files.

[gocowim]

Ah yes I see it in the code. The compressing is triggered by _tlog_write_ext(). So if something blocks the compression process during program shutdown, _tlog_write_ext() might never return?

I.e. in my code the last tlog_info() never returns and tlog_exit() is not called at all.

I will disable compressing for now. Maybe this solves the issue.

[gocowim]

I changed a few parameters to print logs more often, and also change the max. file size to 2k, to trigger the compression more often,
I also added the SIG_IGNs:

#include "tlog.h"
#include <pthread.h>
#include <signal.h>
#include <stdio.h>
#include <unistd.h>

int server_stop = 0;

void signal_handler(int sig)
{
    switch (sig) {
    case SIGINT:
    case SIGTERM:
        server_stop = 1;
        tlog(TLOG_INFO, "Received signal %d, stopping server", sig);
        break;
    default:
        break;
    }
}
void *thread_func(void *arg)
{
    int thread_id = (int)(long)arg;
    tlog(TLOG_INFO, "Thread %d started", thread_id);
    while (server_stop != 1) {
        tlog(TLOG_INFO, "Thread %d is running", thread_id);
        usleep(50000);
    }

    tlog(TLOG_INFO, "Thread %d ended", thread_id);
    return NULL;
}

int main(int argc, char *argv[])
{
#define N (6)
    long i = 0;
    pthread_t thread[N];
    signal(SIGINT, signal_handler);
    signal(SIGTERM, signal_handler);
    signal(SIGPIPE, SIG_IGN); // Ignore SIGPIPE to prevent crashes on broken pipes
    signal(SIGUSR1, SIG_IGN); // Ignore SIGUSR1 to prevent unexpected behavior
    signal(SIGUSR2, SIG_IGN); // Ignore SIGUSR2 to prevent unexpected behavior
    signal(SIGCHLD, SIG_IGN); // Ignore SIGCHLD to prevent zombie processes

    tlog_init("1.log", 4 * 1024, 4, 0, TLOG_SCREEN_COLOR);
    for (i = 0; i < N; i++) {
        pthread_create(&thread[i], NULL, thread_func, (void *)i);
    }

    while (server_stop != 1) {
        usleep(20000);
    }

    for (i = 0; i < N; i++) {
        pthread_join(thread[i], NULL);
    }
    tlog(TLOG_INFO, "DONE");
    tlog_exit();
} 

With these settings, deadlocking occurs immediately!

[pymumu]

Fixed

[gocowim]

Thanks! I can confirm that it fixed the issue.