Problem in C--double writing to file

zaichik · 08-18-2005, 10:02 PM

Hello all,

I have written a function that is to do the logging for a program. It takes as parameters the message to log, and the file to which the message is logged. It prepends time/date info and then appends to the file.

It writes the message perfectly. The problem is, it writes the same message twice. Always. Without exception. I am going nuts trying to solve this. I have run through the code with gdb, and I can attest that one of the following is true:

1) The function is being called once and only once for each message; or
2) I have completely lost my mind.

Let's start with just the function, I am sure the problem is here (or I am crazy, also a possibility):

Code:

int logEntry( const char *message, const char *file ) {
printf( "Entering logEntry()\n" );
        FILE *out;
        char *time_buffer;
        time_t current_time;
        struct tm *local_time;
        char *entry;
        int length;
        int MAX_TIME_BUFFER = 256;
        int MAX_LOG_ENTRY = MAX_SIZE_MSG + MAX_TIME_BUFFER;

        /*  Get time/date and create string */
        time_buffer = ( char * ) malloc( MAX_TIME_BUFFER );
        if( time_buffer == NULL ) {
                fprintf( stderr, "%s: Out of memory in logEntry() ln 368.\n", myName );
                exit( -1 );
        }
        current_time = time( NULL );
        local_time = localtime( &current_time );
        strcpy( time_buffer, asctime( local_time ));
        length = strlen( time_buffer );

        if( time_buffer[ length - 1 ] == '\n' )
                time_buffer[ length - 1 ] = ' ';
        entry = ( char * ) malloc( MAX_LOG_ENTRY );
        if( entry == NULL ) {
                fprintf( stderr, "%s: Out of memory in logEntry() ln 380.\n", myName );
                free( time_buffer );
                exit( -1 );
        }

        strcat( entry, time_buffer );
        free( time_buffer );
        strcat( entry, message );

        if(( out = fopen( file, "a" )) == NULL ) {
                fprintf( stderr, "Could not open %s for append.\n", file );
                free( entry );
		return( -1 );
        }
printf( "Message about to be logged is: %s\n", entry );
        fprintf( out, "%s", entry );
        free( entry );
printf( "Leaving logEntry()\n" );
        return( 0 );
}

The printf of the string "entry" near the end there shows each time that the message I want logged is correct and there is only one "copy" of it in the string "entry".

Is it something about the way I am using fopen()? Everything is getting passed into the function properly and everything. And seriously, I ran gdb and set a break for the first line of this function, and then stepped all the way through, and back to calling function...and again, the function only gets called once, and gdb print statements are showing that just before the message is written, the string "entry" contains the exact message I want to log, and only one "copy" of it.

I'm out of ideas, and welcome yours, however wild they may seem. Please help me brainstorm! TIA.

sind · 08-18-2005, 10:58 PM

I tested your function using this code:

Code:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <string.h>

#define MAX_SIZE_MSG 64
#define myName "test"

int logEntry( const char *message, const char *file ) {
printf( "Entering logEntry()\n" );
        FILE *out;
        char *time_buffer;
        time_t current_time;
        struct tm *local_time;
        char *entry;
        int length;
        int MAX_TIME_BUFFER = 256;
        int MAX_LOG_ENTRY = MAX_SIZE_MSG + MAX_TIME_BUFFER;

        /*  Get time/date and create string */
        time_buffer = ( char * ) malloc( MAX_TIME_BUFFER );
        if( time_buffer == NULL ) {
                fprintf( stderr, "%s: Out of memory in logEntry() ln 368.\n", myName );
                exit( -1 );
        }
        current_time = time( NULL );
        local_time = localtime( &current_time );
        strcpy( time_buffer, asctime( local_time ));
        length = strlen( time_buffer );

        if( time_buffer[ length - 1 ] == '\n' )
                time_buffer[ length - 1 ] = ' ';
        entry = ( char * ) malloc( MAX_LOG_ENTRY );
        if( entry == NULL ) {
                fprintf( stderr, "%s: Out of memory in logEntry() ln 380.\n", myName );
                free( time_buffer );
                exit( -1 );
        }

        strcat( entry, time_buffer );
        free( time_buffer );
        strcat( entry, message );

        if(( out = fopen( file, "a" )) == NULL ) {
                fprintf( stderr, "Could not open %s for append.\n", file );
                free( entry );
		return( -1 );
        }
printf( "Message about to be logged is: %s\n", entry );
        fprintf( out, "%s", entry );
        free( entry );
printf( "Leaving logEntry()\n" );
        return( 0 );
}

int main(int argc, char **argv)
{
	logEntry("Hello, World!!!", "test.out");
	
	return 0;
}

There was a bit of string corruption, which I fixed by changing

Code:

strcat( entry, time_buffer );

to

Code:

strcpy( entry, time_buffer );

Apart from that small problem, it worked fine. Only one entry was put into the file.

To avoid buffer overflows, it might be worth looking at using strncpy and strncat, and/or checking the length of the "message" string.

BTW, you could do away with the "entry" string altogether by writing the time to the file with a seperate call to fprintf(). I don't think that that would affect the performance, due to buffering.

I should also mention that asctime() returns a string of length 26 bytes; so allocating 256 bytes might be a slight overkill.

HTH in some way,

~sind

zaichik · 08-19-2005, 09:35 AM

Hi sind,

Thanks so much for the reply. It doesn't solve my double-entry problem, but at least you have helped me confirm that the function itself is not at fault.

I do have some questions for you about your comments:

Quote:

To avoid buffer overflows, it might be worth looking at using strncpy and strncat, and/or checking the length of the "message" string.

I read the man page for strncpy and that makes sense to me. If I understand correctly, strncpy( entry, msg, n ) would copy n bytes of msg into entry. If msg is longer than n bytes, the extra bytes are simply dropped, preventing a buffer overflow. (Thoughts on making sure that entry is null-terminated if msg is longer than n?) Is this correct?

If so, is there added utility to checking the length of msg to make sure that it is not longer than entry allows? And how would I do that? I would have to allocate some sort of buffer to msg and make sure that the length of msg does not exceed the buffer for entry; but what's to prevent a buffer overflow on msg? I've often wondered about this and would appreciate any insights.

I also just now noticed that I do not close the file after writing to it...could the problem be caused by the program flushing buffers or something to the file as it closes it itself? I'll check that...

Thanks for pointing out the problem with the first use of strcat instead of strcpy. I had noticed a few garbage characters in the file the first couple times I tested it, but then it stopped so I never looked into it. I'm sure it would have cropped up again.

Thanks again for the reply and suggestions.

zaichik · 08-19-2005, 09:47 AM

Hello again sind,

Adding fclose( out ); after writing to the file seems to have solved the double-writing problem. I'd be interested on explanations of that as well.

I would still be interested in thoughts on the buffer overflow question.

Thanks again!

Hko · 08-19-2005, 11:36 AM

Quote:

Originally posted by zaichik
Adding fclose( out ); after writing to the file seems to have solved the double-writing problem. I'd be interested on explanations of that as well.

That's probably due to stdio-buffering.

Quote:

I would still be interested in thoughts on the buffer overflow question.

You declared the length of the buffer (MAX_SIZE_MSG), so you know where its end is (MAX_SIZE_MSG - 1). If always put an '\0' there, it will be 0-terminated when strncpy() truncates the string.

However you can even avoid this by using the friendlier, and also buffer-overflow-safe snprintf().

Also:
There is shortcut for retrieving the local time and converting it to string in one go: ctime()

And:
You don't need a buffer for the time. It even is bad, as the pointer to the allocated buffer is lost, thus introducing a (small) memory-leak. "man asctime" says:

Quote:

"The return value points to a statically allocated string which might be overwritten by subsequent calls to any of the date and time functions."

Modified, easier code:

Code:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <string.h>

#define MAX_SIZE_MSG 64
#define myName "test"


int logEntry(const char *message, const char *file)
{
    FILE *out;
    time_t t;
    char *entry;

    /*
     * Get time/date and create string 
     */
    t = time(NULL);
    entry = (char *) malloc(MAX_SIZE_MSG);
    if (entry == NULL) {
        fprintf(stderr, "%s: Out of memory in logEntry().\n", myName);
        exit(-1);
    }

    snprintf(entry, MAX_SIZE_MSG, "%s: %s\n", ctime(&t), message);

    if ((out = fopen(file, "a")) == NULL) {
        fprintf(stderr, "Could not open %s for append.\n", file);
        free(entry);
        return (-1);
    }

    printf("Message about to be logged is: %s\n", entry);
    fprintf(out, "%s", entry);

    free(entry);
    fclose(out);
    return (0);
}


int main(int argc, char **argv)
{
    return logEntry("Hello, World!!!", "test.out");
}

sind · 08-20-2005, 12:59 AM

I'm glad that you found the problem, zaichik. That looks like a good solution Hko.

Personally I would avoid the "entry" buffer entirely and use two calls to fprintf(out). That way buffer overflows should not be a concern (in your code anyway. You just hope there aren't any in the library code). That said, you still might want to check the length of the message being written to the file, in case it's going to take up heaps of space.

You could also allow your logging function to accept variable numbers of arguments (like printf()) and use a call to fprintf() for the time and then vfprintf() for the message.

With Hko's function, you might still want to remove the newline from the end of the time string; you could do something like this (untested):

Code:

char *time_str;

time_str = ctime(&t);

time_str[strlen(time_str) - 1] = '\0'; /* the length of the string returned by ctime() should be 26 but it's worth checking IMO */

snprintf(entry, MAX_SIZE_MSG, "%s: %s\n", time_str, message);

~sind

zaichik · 08-20-2005, 04:35 PM

Hello Hko and sind,

Thanks for the code suggestions, Hko. Much simpler, and simpler (at least in this case) is better.

One question:

Code:

char *time_str;
time_str = ctime(&t);

Can I do this without using malloc to allocate memory? Or does ctime return the pointer I have been using malloc to
return? And since I cannot explicitly free the memory, is that a concern, or is the memory freed when the variables go
out of scope?

The logging function is only going to be accepting a limited number of calls and with a limited number of program-defined
messages, so for now (while I am under time pressure) there is no need for me to dress it up. Good ideas for future
development, however, so I can quit trying to screw around with these little things and rely on things previously written.

Thanks again for the help on this one!

zaichik · 08-20-2005, 04:38 PM

Hi again,

Never mind, Hko answered this question in his first post:

Quote:

You don't need a buffer for the time. It even is bad, as the pointer to the allocated buffer is lost, thus introducing a (small) memory-leak.

Thanks!