Multi thread access a log file

[myaegean]

Recently I created a logging functionality for multiple threads. I also used mutex lock to control multiple access on logging file. I met a issue when testing the logging functionality.
If I create multiple threads in a loop with parameters as bellow, the mutex lock seems take no effective.
err = pthread_create(&ntid[iLoop], NULL, thr_fn, &param);
while when I create thread using NULL parameter, the logging functinality works well.
err = pthread_create(&ntid[iLoop], NULL, thr_fn, NULL);

The following is the 2 source files:

/********************************************************/
/* thread_main.c */

#include <stdio.h>
#include <pthread.h>
#include <string.h>
#include <sys/types.h>
#include <unistd.h>
#include "Util.h"

#define MAX_THREAD_NUM 10
#define MAX_COUNT_NUM 8000

pthread_t ntid[MAX_THREAD_NUM];

typedef struct tagThrParams_t
{
char szThrName[16];
int iLogNum;
} ThrParams_t;

void *thr_fn(void *arg)
{
int i;
#ifdef ENABLE_PARM
ThrParams_t *param = (ThrParams_t*)arg;
for(i = 0; i < param->iLogNum; i ++)
{
logging(LOG_INFOR, "[%s]pid=%u tid=%u loop=%d/%d\n", param->szThrName, getpid(), pthread_self(), i, param->iLogNum);
}
#else
for(i = 0; i < MAX_COUNT_NUM; i ++)
{
logging(LOG_INFOR, "pid=%u tid=%u loop=%d\n", getpid(), pthread_self(), i);
}
#endif
return ((void *)0);
}

int thread_gen(int iLoop)
{
int err;
#ifdef ENABLE_PARM
ThrParams_t param;

memset(&param, 0x00, sizeof(param));
sprintf(param.szThrName, "THR%03d", iLoop);
param.iLogNum = MAX_COUNT_NUM;

err = pthread_create(&ntid[iLoop], NULL, thr_fn, &param);
#else
err = pthread_create(&ntid[iLoop], NULL, thr_fn, NULL);
#endif
if(err != 0)
{
printf("can't create thread: %s\n", strerror(err));
return 1;
}

logging(LOG_INFOR, "thread_gen:thread(%u) is created.\n", ntid[iLoop]);

return 0;
}

int main()
{
int i;

log_init();

for(i = 0; i < MAX_THREAD_NUM; i++)
{
thread_gen(i);
}

for(i = 0; i < MAX_THREAD_NUM; i++)
{
logging(LOG_INFOR, "main: thread(%u) is terminated.\n", ntid[i]);
pthread_join(ntid[i], NULL);
}

log_close();
return 0;
}

/*********************************************************/
/* Util.c */

#include <stdio.h>
#include <stdarg.h>
#include <string.h>
#include<time.h>
#include <pthread.h>
#include "Util.h"

#define MAX_LINE_NUM 1000000

FILE * g_pFile = NULL;
char * g_pDirName = "./";
char * g_pFileName = "TestLog";
static unsigned int g_file_num = 0;
static unsigned int g_line_count = 0;

//pthread_mutex_t *g_mutex = PTHREAD_MUTEX_INITIALIZER;
static pthread_mutex_t g_mutex;

static void get_time(char *buf)
{
time_t now;
struct tm *tm_now;

if (NULL == buf)
{
return;
}


time(&now);
tm_now = localtime(&now);
sprintf(buf, "%d%02d%02d%02d%02d%02d", tm_now->tm_year + 1900, tm_now->tm_mon, tm_now->tm_mday, tm_now->tm_hour, tm_now->tm_min, tm_now->tm_sec);

return;
}

static void get_timestamp(char *buf)
{
time_t now;
struct tm *tm_now;

if (NULL == buf)
{
return;
}


time(&now);
tm_now = localtime(&now);
sprintf(buf, "%d-%02d-%02d %02d:%02d:%02d", tm_now->tm_year + 1900, tm_now->tm_mon, tm_now->tm_mday, tm_now->tm_hour, tm_now->tm_min, tm_now->tm_sec);

return;
}

int log_init()
{
char fileFullName[50];
int ret = -1;

memset(fileFullName, 0x00, 50);
sprintf(fileFullName, "%s%s.txt", g_pDirName, g_pFileName);
g_pFile = fopen(fileFullName, "w+");
if (NULL == g_pFile)
{
printf("Error, failed to open file %s.\n", fileFullName);
return -1;
}

/* Mutex lcok initialize */
ret = pthread_mutex_init(&g_mutex, NULL);
if (0 != ret)
{
printf("Error, failed to call pthread_mutex_init()\n");
return -1;
}

return 0;
}

void logging(int level, char * format, ...)
{
char msg_buf[MAX_BUF_LEN + 1];
char msg_date[50];
char msg[MAX_BUF_LEN + 21];
char msg_level[4][15] = { "[INFOR] ", "[WARNING] ", "[ERROR] ", "[INFOR] "};

char fileNewName[100];
char fileOldName[100];


va_list list;
va_start(list, format);

memset(msg_buf, 0x00, MAX_BUF_LEN + 1);

vsnprintf(msg_buf, MAX_BUF_LEN + 1, format, list);

memset(msg_date, 0x00, 50);
get_timestamp(msg_date);

memset(msg, 0x00, MAX_BUF_LEN + 21);
sprintf(msg, "%s %s %s", msg_date, msg_level[level], msg_buf);

pthread_mutex_lock(&g_mutex);

/* Output the error log directly to screen. */
if (level == LOG_ERROR || level == LOG_SCREEN)
{
printf(msg);
}

if (g_line_count >= MAX_LINE_NUM)
{
fclose(g_pFile);

memset(msg_date, 0x00, 50);
get_time(msg_date);

memset(fileOldName, 0x00, 100);
sprintf(fileOldName, "%s%s.txt", g_pDirName, g_pFileName);

memset(fileNewName, 0x00, 100);
sprintf(fileNewName, "%s%s_%s_%04d.txt", g_pDirName, g_pFileName, msg_date, g_file_num);

rename(fileOldName, fileNewName);

log_init();

g_line_count = 0;
g_file_num++;
}

fputs(msg, g_pFile);

g_line_count ++;

va_end(list);

pthread_mutex_unlock(&g_mutex);

return;
}

void log_close()
{
char msg_date[50];
char fileOldName[100];
char fileNewName[100];
int ret = -1;

if(NULL == g_pFile)
{
return;
}

fclose(g_pFile);

memset(msg_date, 0x00, 50);
get_time(msg_date);

memset(fileOldName, 0x00, 100);
sprintf(fileOldName, "%s%s.txt", g_pDirName, g_pFileName);

memset(fileNewName, 0x00, 100);
sprintf(fileNewName, "%s%s_%s_%04d.txt", g_pDirName, g_pFileName, msg_date, g_file_num);
rename(fileOldName, fileNewName);

g_pFile = NULL;

ret = pthread_mutex_destroy(&g_mutex);
if (0 != ret)
{
printf("Error, failed to call pthread_mutex_destroy().\n");
return;
}

return;
}
/*****************************************************/

[htirwin]

You can copy and paste, and then surround with code tags. There is a button to the right ,when editing your post, with <> inside that does this for you.

I suggest you edit your post to include snippets of your code including the function and the sections you are protecting with mutexes.

It wouldn't seam to make any sense at all that the parameter has any effect on the mutex.

[htirwin]

/********************************************************/
/* thread_main.c */

#include <stdio.h>
#include <pthread.h>
#include <string.h>
#include <sys/types.h>
#include <unistd.h>
#include "Util.h"

#define MAX_THREAD_NUM 10
#define MAX_COUNT_NUM 8000

pthread_t ntid[MAX_THREAD_NUM];

typedef struct tagThrParams_t {
    char szThrName[16];
    int iLogNum;
} ThrParams_t;

void *thr_fn(void *arg)
{
    int i;
#ifdef ENABLE_PARM
    ThrParams_t *param = (ThrParams_t *)arg;
    for (i = 0; i < param->iLogNum; i ++) {
        logging(LOG_INFOR, "[%s]pid=%u tid=%u loop=%d/%d\n", param->szThrName, getpid(), pthread_self(), i, param->iLogNum);
    }
#else
    for (i = 0; i < MAX_COUNT_NUM; i ++) {
        logging(LOG_INFOR, "pid=%u tid=%u loop=%d\n", getpid(), pthread_self(), i);
    }
#endif
    return ((void *)0);
}

int thread_gen(int iLoop)
{
    int err;
#ifdef ENABLE_PARM
    ThrParams_t param;

    memset(&param, 0x00, sizeof(param));
    sprintf(param.szThrName, "THR%03d", iLoop);
    param.iLogNum = MAX_COUNT_NUM;

    err = pthread_create(&ntid[iLoop], NULL, thr_fn, &param);
#else
    err = pthread_create(&ntid[iLoop], NULL, thr_fn, NULL);
#endif
    if (err != 0) {
        printf("can't create thread: %s\n", strerror(err));
        return 1;
    }

    logging(LOG_INFOR, "thread_gen:thread(%u) is created.\n", ntid[iLoop]);

    return 0;
}

int main()
{
    int i;

    log_init();

    for (i = 0; i < MAX_THREAD_NUM; i++) {
        thread_gen(i);
    }

    for (i = 0; i < MAX_THREAD_NUM; i++) {
        logging(LOG_INFOR, "main: thread(%u) is terminated.\n", ntid[i]);
        pthread_join(ntid[i], NULL);
    }

    log_close();
    return 0;
}

/*********************************************************/
/* Util.c */

#include <stdio.h>
#include <stdarg.h>
#include <string.h>
#include<time.h>
#include <pthread.h>
#include "Util.h"

#define MAX_LINE_NUM 1000000

FILE *g_pFile = NULL;
char *g_pDirName = "./";
char *g_pFileName = "TestLog";
static unsigned int g_file_num = 0;
static unsigned int g_line_count = 0;

//pthread_mutex_t *g_mutex = PTHREAD_MUTEX_INITIALIZER;
static pthread_mutex_t g_mutex;

static void get_time(char *buf)
{
    time_t now;
    struct tm *tm_now;

    if (NULL == buf) {
        return;
    }


    time(&now);
    tm_now = localtime(&now);
    sprintf(buf, "%d%02d%02d%02d%02d%02d", tm_now->tm_year + 1900, tm_now->tm_mon, tm_now->tm_mday, tm_now->tm_hour, tm_now->tm_min, tm_now->tm_sec);

    return;
}

static void get_timestamp(char *buf)
{
    time_t now;
    struct tm *tm_now;

    if (NULL == buf) {
        return;
    }


    time(&now);
    tm_now = localtime(&now);
    sprintf(buf, "%d-%02d-%02d %02d:%02d:%02d", tm_now->tm_year + 1900, tm_now->tm_mon, tm_now->tm_mday, tm_now->tm_hour, tm_now->tm_min, tm_now->tm_sec);

    return;
}

int log_init()
{
    char fileFullName[50];
    int ret = -1;

    memset(fileFullName, 0x00, 50);
    sprintf(fileFullName, "%s%s.txt", g_pDirName, g_pFileName);
    g_pFile = fopen(fileFullName, "w+");
    if (NULL == g_pFile) {
        printf("Error, failed to open file %s.\n", fileFullName);
        return -1;
    }

    /* Mutex lcok initialize */
    ret = pthread_mutex_init(&g_mutex, NULL);
    if (0 != ret) {
        printf("Error, failed to call pthread_mutex_init()\n");
        return -1;
    }

    return 0;
}

void logging(int level, char *format, ...)
{
    char msg_buf[MAX_BUF_LEN + 1];
    char msg_date[50];
    char msg[MAX_BUF_LEN + 21];
    char msg_level[4][15] = { "[INFOR] ", "[WARNING] ", "[ERROR] ", "[INFOR] "};

    char fileNewName[100];
    char fileOldName[100];


    va_list list;
    va_start(list, format);

    memset(msg_buf, 0x00, MAX_BUF_LEN + 1);

    vsnprintf(msg_buf, MAX_BUF_LEN + 1, format, list);

    memset(msg_date, 0x00, 50);
    get_timestamp(msg_date);

    memset(msg, 0x00, MAX_BUF_LEN + 21);
    sprintf(msg, "%s %s %s", msg_date, msg_level[level], msg_buf);

    pthread_mutex_lock(&g_mutex);

    /* Output the error log directly to screen. */
    if (level == LOG_ERROR || level == LOG_SCREEN) {
        printf(msg);
    }

    if (g_line_count >= MAX_LINE_NUM) {
        fclose(g_pFile);

        memset(msg_date, 0x00, 50);
        get_time(msg_date);

        memset(fileOldName, 0x00, 100);
        sprintf(fileOldName, "%s%s.txt", g_pDirName, g_pFileName);

        memset(fileNewName, 0x00, 100);
        sprintf(fileNewName, "%s%s_%s_%04d.txt", g_pDirName, g_pFileName, msg_date, g_file_num);

        rename(fileOldName, fileNewName);

        log_init();

        g_line_count = 0;
        g_file_num++;
    }

    fputs(msg, g_pFile);

    g_line_count ++;

    va_end(list);

    pthread_mutex_unlock(&g_mutex);

    return;
}

void log_close()
{
    char msg_date[50];
    char fileOldName[100];
    char fileNewName[100];
    int ret = -1;

    if (NULL == g_pFile) {
        return;
    }

    fclose(g_pFile);

    memset(msg_date, 0x00, 50);
    get_time(msg_date);

    memset(fileOldName, 0x00, 100);
    sprintf(fileOldName, "%s%s.txt", g_pDirName, g_pFileName);

    memset(fileNewName, 0x00, 100);
    sprintf(fileNewName, "%s%s_%s_%04d.txt", g_pDirName, g_pFileName, msg_date, g_file_num);
    rename(fileOldName, fileNewName);

    g_pFile = NULL;

    ret = pthread_mutex_destroy(&g_mutex);
    if (0 != ret) {
        printf("Error, failed to call pthread_mutex_destroy().\n");
        return;
    }

    return;
}
/*****************************************************/

[dhayden]

The problem is that the param you're passing to thr_fn is a local variable in thread_gen(). As soon as thread_gen exits, the memory is deallocated and gets used by Something Else. At that point, the value of param is undefined.

You need to pass a param that won't go away.

[myaegean]

Thanks for your reply. So If I store the contents of param which is local variable in thread_gen() to thr_fn() as bellow, the issue will be finally fixed, right?

void *thr_fn(void *arg)
{
    int i;
#ifdef ENABLE_PARM  
    ThrParams_t stParam;
    memset(&stParam, 0x00, sizeof(ThrParams_t));
    memcpy(&stParam, (ThrParams_t*)arg, sizeof(ThrParams_t)); // Store the contents of parameter which is local variable in thread_gen().

    for(i = 0; i < stParam.iLogNum; i ++) 
    {   
        logging(LOG_INFOR, "[%s]pid=%u tid=%u loop=%d/%d\n", stParam.szThrName, getpid(), pthread_self(), i, stParam.iLogNum);
    }   
#else
    for(i = 0; i < MAX_COUNT_NUM; i ++) 
    {   
        logging(LOG_INFOR, "pid=%u tid=%u loop=%d\n", getpid(), pthread_self(), i); 
    }   
#endif
    return ((void *)0);
}

[dhayden]

No, because you're assuming that the data in arg will be valid long enough for you to copy it. In fact, you have a race condition. Once you call pthread_create(), the two threads may run in whatever order the OS wants, for however long it wants. So the contents in param may be blown away before thr_fn() executes its first statement.

Note that you have already found that the code works. Don't be fooled, you're just getting lucky. The bug is really there.

I would make a copy of param on the heap before passing it to thr_fn. Then have thr_fn delete it when it exits:

In thread_gen():
err = pthread_create(&ntid[iLoop], NULL, thr_fn, new ThrParams_t(param));

and in thr_fn():

void *thr_fn(void *arg)
{
    int i;
#ifdef ENABLE_PARM
    ThrParams_t *param = (ThrParams_t *)arg;
    for (i = 0; i < param->iLogNum; i ++) {
        logging(LOG_INFOR, "[%s]pid=%u tid=%u loop=%d/%d\n", param->szThrName,
                    getpid(), pthread_self(), i, param->iLogNum);
    }
    delete param;
#else
    for (i = 0; i < MAX_COUNT_NUM; i ++) {
        logging(LOG_INFOR, "pid=%u tid=%u loop=%d\n", getpid(), pthread_self(), i);
    }
#endif
    return ((void *)0);
}

[myaegean]

Your solution is really nice, thank you!