Logging in shared file

z7ql · September 28, 2013, 12:02am

Hi.
The problem is to write logs in a shared file from several processes.
The cooperate call of fprintf() leads to messing the content even in one call

example:

fprintf(f,"a1 \n a2");
fprintf(f,"a3 \n a4");

out:

a1
a3
a2
a4

Ofcourse this is possible to implement the file as a critical section with semaphores. But there is a significant chanse to crash for one of the processes, so there is not any garanty that the crashed prosess would not be in the critical section at the moment of crash. So it can cause locking of all processes around the file.
Is there another solution for this problem?

Don_Cragun · September 28, 2013, 1:42am

The two fprintf() statements you listed will never produce the output you listed for the file named out no matter what order the fprintf() statements were executed in and no matter whether both fprintf()s were in the same process or different processes. Depending on the mode argument(s) supplied to your call(s) to fopen() to create the STDIO stream(s) f and any calls to setbuf() or setvbuf() on the stream(s) f to set the output buffering mode, there are several possible outcomes, but none of them will result in "a2" or "a4" appearing at the start of a line and none of them will have a <newline> immediately following "a2" or "a4".

However, if all of your calls to fopen() use the mode "a+" and you use setbuf() or setvbuf() to unbuffered (or line buffered if you have each fprintf() format string end output fields result in the last character written being a <newline> character) you could guarantee that the output from each fprintf() would appear in the output as a contiguos string and that the output from one call to fprintf() would not overwrite the output written by another call to fprintf() whether or not those calls occurred in the same thread, same process, or multiple processes as long as no single call to fprintf() produces more than BUFSIZ bytes of output. As long as you use append mode in all cases where you open the stream, you don't need critical sections surrounding the fprintf() calls.

z7ql · September 28, 2013, 2:07am

Thanks for detailed answer.
Indeed I've got the similar situation in my log after two vfprintf calls. I'll check my situation and try to formulate my question more accurate.

Don_Cragun · September 28, 2013, 2:28am

Whether you use fprintf() or vfprintf() (or putc(), putchar(), printf(), dprintf(), etc.) doesn't matter. What matters is:

using append mode in all of your fopen() calls and
using unbuffered output, or writing complete lines in every output request and using line-buffered output.

z7ql · September 28, 2013, 4:51am

Some details:
logger.c

FILE * file;// file = fopen(stampedPath,"a");

void writeLog(char * format, ...)
{
  va_list args;
      va_start (args, format);
      vprintf(format, args);
      va_end(args);
      
      va_start(args, format);
      vfprintf(file, format, args);
      va_end(args);
}

function call

char buff[2048];
char upd ="x10000";
//...
for(i=0; i< 500; ++i)
{
  getMessage(buff,2048);//writing message in the buffer
  writeLog("Got 'isAuthorized' call\n");
  writeLog("Retreiving data from\n");
  writeLog("UPD=%s\n",upd);
  writeLog(buff);
}
//...

LogFragments
Normal:

...
UPD = x10000
<xdata created_by="MA" created_at="">
    <error number="-3123" message="ERROR OPENING IDF FILE [Cannot open IDF file IDF_901234432.xml.]"/>
</xdata>
Got 'isAuthorized' call
...

Corrupted:

...
UPD = x100000
<?xml version="1.0" encoding="UTF-8"?>
<xdata created_by="MA" created_at="">
    <error number="-3123" message="ERROR OPENING IDF FILE [Cannot open IDF file IDF_901234432.xml.]"/>
</xdata>
Got 'isAuthorized' call
RetreivingFILE [Cannot open IDF file IDF_901234432.xml.]"/>
</xdata>
Got 'isAuthorized' call
...

Legend:
Message 1
Start of message 2
End of message 3

May be the reason of mixing up in the vfprintf() using?

---------- Post updated at 03:37 AM ---------- Previous update was at 03:33 AM ----------

Some details:
logger.c

FILE * file;//initialization is ommited

void writeLog(char * format, ...)
{
  va_list args;
      va_start (args, format);
      vprintf(format, args);
      va_end(args);
      
      va_start(args, format);
      vfprintf(file, format, args);
      va_end(args);
}

function call

char buff[2048];
char upd ="x10000";
//...
for(i=0; i< 500; ++i)
{
  getMessage(buff,2048);//writing message in the buffer
  writeLog("Got 'isAuthorized' call\n");
  writeLog("Retreiving data from\n");
  writeLog("UPD=%s\n",upd);
  writeLog(buff);
}
//...

LogFragments
Normal:

...
UPD = x10000
<xdata created_by="MA" created_at="">
    <error number="-3123" message="ERROR OPENING IDF FILE [Cannot open IDF file IDF_901234432.xml.]"/>
</xdata>
Got 'isAuthorized' call
...

Corrupted:

...
UPD = x100000
<?xml version="1.0" encoding="UTF-8"?>
<xdata created_by="MA" created_at="">
    <error number="-3123" message="ERROR OPENING IDF FILE [Cannot open IDF file IDF_901234432.xml.]"/>
</xdata>
Got 'isAuthorized' call
RetreivingFILE [Cannot open IDF file IDF_901234432.xml.]"/>
</xdata>
Got 'isAuthorized' call
...

Legend:
Message 1
Start of message 2
End of message 3

---------- Post updated at 03:42 AM ---------- Previous update was at 03:37 AM ----------

Thanks. I'll try to set larger buffer.

---------- Post updated at 03:51 AM ---------- Previous update was at 03:42 AM ----------

Thanks. I'll try to experiment with buffer

achenle · September 28, 2013, 11:27am

A larger buffer won't help. Setting the buffer size to zero won't help. The problem is that each vfprintf() call can generate multiple calls to write() - the calls that actually write the data to the file. Each individual write() call is guaranteed to be atomic, but a series of multiple write() calls from different processes and/or threads will wind up as you're seeing - all interleaved together.

You need to make certain each call to your writeLog() function results in one and only one underlying write() call.

write(). Not fwrite() or fprintf().

#define BUF_LEN 4096
void writeLog( const char *format, ... )
{
    char buffer[ BUF_LEN ];
    char *ptr;
    int length;
    va_list args;
    
    va_start( args, format );

    // expand the format and args into a single string
    length = vsnprintf( buffer, BUF_LEN, format, args );

    // if the buffer isn't big enough, allocate a temporary
    // one on the stack (if strings can be really long and
    // blow up the stack, use malloc() here - but then you
    // have to add complexity to the code to make sure
    // any malloc()'d buffer is freed.)
    if ( length >= BUF_LEN )
    {
        // I don't recall offhand if the  "+ 1" is needed, but
        // it doesn't hurt to have it
        ptr = ( char * ) alloca( length + 1 );
        length = vsnprintf( ptr, length + 1, format, args );
    }
    else
    {
        ptr = buffer;
    }

    write( logFd, ptr, length );

    va_end( args );
}

In theory, you could pass a zero length to the first call to vsnprintf() and get back the known length of the final string. In practice there are still vsnprintf() implementations that don't do that per current standards. (The old SUSv2 standard specified different return values.)

z7ql · September 29, 2013, 11:49pm

Thanks. I did not know about the fact what 'write' is an atomic function. I'll use it. I am using pretty old compiller version on the target system. And with high possibility there are no implementation of vsnprintf.

---------- Post updated at 10:49 PM ---------- Previous update was at 10:39 PM ----------

I've checked this and I found the implementation. The system was updated recently. So the problem with determination of buffer length was solved.

z7ql · October 3, 2013, 12:20am

I've explored that there are big difference between

{         va_start( args, format );      length = vsnprintf( buffer, BUF_LEN, format, args );
    
    if (length >= BUF_LEN )
    { 
     expandBuffer(buffer, length + 1);  
     length = vsnprintf(buffer, length + 1, format, args );     }         va_end( args ); }

and

{    
    va_list args2;     va_start( args, format );     va_copy(args2,args);
    length = vsnprintf( buffer, BUF_LEN, format, args );
    
    if (length >= BUF_LEN )
    { 
     expandBuffer(buffer, length + 1);  
     length = vsnprintf(buffer, length + 1, format, args2 );     }         va_end( args ); }

The first variant doesn't work if the second vsnprintf is called. vsnprintf spoil the args.

achenle · October 5, 2013, 10:31am

What platform and O/S are you running on? Because I don't think that should happen.

That sounds like your stack is getting corrupted, and that's not good.

z7ql · October 14, 2013, 6:25am

Linux Red Hat. I've build it also on openvms alpha 8.3. May be I can check it on a small example, where a stack corruption will be practically impossible.

---------- Post updated at 05:25 AM ---------- Previous update was at 04:44 AM ----------

So the experiment:

Without copying
main.c

void vprintf2x(char * format, va_list args)
{
  vprintf(format, args);
  vprintf(format, args);
}

void printf2x(char * format, ...)
{
  va_list args;
  va_start(args, format);
  vprintf2x(format, args);
  va_end(args);
}


int main()
{
  printf2x("%s - %s", "123", "321\n");
  return 0;
}

Result:
$ ./a.out
123 - 321
Segmentation fault

With copying
main.c

#include <stdio.h>
#include <stdarg.h>

void vprintf2x(char * format, va_list args)
{
  va_list args2;
  va_copy(args2, args);
  vprintf(format, args);
  vprintf(format, args2);
  va_end(args2);
}

void printf2x(char * format, ...)
{
  va_list args;
  va_start(args, format);
  vprintf2x(format, args);
  va_end(args);
}


int main()
{
  printf2x("%s - %s", "123", "321\n");
  return 0;
}

Result:
$ ./a.out
123 - 321
123 - 321