(Long post):

Hi -

1.  I have a question regarding the C "system" call in a UNIX
environment.  My question arises from a problem I discovered using HP-
UX 11.0.
The problem:  In an existing application, I added a function to write
a transaction log to a new, separate file.  During testing I sometimes
saw  some extraneous messages in this new output file.  Here's what I
believe was causing them:

2.  The program (which I "inherited" as existing code) logs certain
errors to a file by making system calls.  The essence of what happens
in the error logger is:

void log_err( char * errorMessage)
{
char buffer[256];
char * log_dir, * log_file;
..
sprintf(buffer,"echo %s >> %s/%s",  errorMessage, log_dir, log_file);
system(buffer);
}

So, if errorMessage points to "Error xyz"
log_dir points to "/prod/foo/logs"
and  log_file points to "bar

then the message "Error xyz" gets appended to file /prod/foo/logs/bar.
And this seems to work OK.  (The question of whether this is a
sensible way to write to the log file is beyond the scope of this
post).

3.  But suppose errorMessage points to "before \n after" when the
sprintf and system calls (above) are made.  The system call gets the
string "echo before \n after >> /prod/foo/logs/bar"

What I believe happens is that "before" gets echoed to stdout
and then the shell tries to do "after >> /prod/foo/logs/bar" as
a separate shell command.....
But since 'after' is not a valid command, the shell attempts to write
an error message to stderr.  Somehow, the error message from the shell
gets written to my new transaction log file mentioned in paragraph 1.
I'm  not making any explicit association between the transaction log
file and stderr.  The
transaction log is intended to be known only to one function
that is essentially:

void log_trans( char * some_message)
{
static FILE * trans_log = 0;

..

if (trans_log == (FILE *)0)
{
trans_log = fopen("my_log_file", "a");
}

..
fprintf(trans_log, "%s", some_message);
fflush(trans_log);
..
}

The file "my_log_file" and its associated FILE object are not supposed
to be used by anything other than function log_trans (code immediately
above).  What I'm trying to understand is how the system function
error messages are getting written to my
transaction log.  I'm guessing that UNIX is looking for any open file
handle that it can find and writing its error messages there (rather
than simply discarding them).

BTW, I have fixed the problem by removing all newline characters from
the strings being passed to the log_err function.  The fix seems to
work.  What's more, I can make the bug come back simply by adding the
statement

system((char *)">> This is an intentional error.");

to the original log_err function.  Still puzzling, because function
log_err knows nothing about "my_log_file" or its associated FILE
object.

Thanks for any info you all can provide.  I'm also curious if anyone
has encountered this sort of thing on any other versions of UNIX.

TKJ

[ Post a follow-up to this message ]

In article <1174340649.985470.171540@n59g2000hsh.googlegroups.com>,
thosjohnson@sbcglobal.net wrote:

> (Long post):
>
> Hi -
>
> 1.  I have a question regarding the C "system" call in a UNIX
> environment.  My question arises from a problem I discovered using HP-
> UX 11.0.
> The problem:  In an existing application, I added a function to write
> a transaction log to a new, separate file.  During testing I sometimes
> saw  some extraneous messages in this new output file.  Here's what I
> believe was causing them:
>
> 2.  The program (which I "inherited" as existing code) logs certain
> errors to a file by making system calls.  The essence of what happens
> in the error logger is:
>
> void log_err( char * errorMessage)
> {
>  char buffer[256];
>  char * log_dir, * log_file;
>  ...
>  sprintf(buffer,"echo %s >> %s/%s",  errorMessage, log_dir, log_file);
>  system(buffer);
> }
>
> So, if errorMessage points to "Error xyz"
>        log_dir points to "/prod/foo/logs"
> and  log_file points to "bar
>
> then the message "Error xyz" gets appended to file /prod/foo/logs/bar.
> And this seems to work OK.  (The question of whether this is a
> sensible way to write to the log file is beyond the scope of this
> post).
>
> 3.  But suppose errorMessage points to "before \n after" when the
> sprintf and system calls (above) are made.  The system call gets the
> string "echo before \n after >> /prod/foo/logs/bar"
>
> What I believe happens is that "before" gets echoed to stdout
> and then the shell tries to do "after >> /prod/foo/logs/bar" as
> a separate shell command.....
> But since 'after' is not a valid command, the shell attempts to write
> an error message to stderr.  Somehow, the error message from the shell
> gets written to my new transaction log file mentioned in paragraph 1.
> I'm  not making any explicit association between the transaction log
> file and stderr.  The
> transaction log is intended to be known only to one function
> that is essentially:

Is it possible that something is CLOSING stderr before the first time
you call log_trans()?  When a file is opened it gets the lowest
available descriptor, so of stderr is closed then the next open() will
cause stderr to be associated with that file.

If you close any of the standard 3 file descriptors, it's generally best
to connect them to /dev/null to avoid accidents like this.

>
> void log_trans( char * some_message)
> {
>    static FILE * trans_log = 0;
>
>    ...
>
>    if (trans_log == (FILE *)0)
>    {
>        trans_log = fopen("my_log_file", "a");
>    }
>
>    ...
>    fprintf(trans_log, "%s", some_message);
>    fflush(trans_log);
>    ...
> }
>
> The file "my_log_file" and its associated FILE object are not supposed
> to be used by anything other than function log_trans (code immediately
> above).  What I'm trying to understand is how the system function
> error messages are getting written to my
> transaction log.  I'm guessing that UNIX is looking for any open file
> handle that it can find and writing its error messages there (rather
> than simply discarding them).
>
> BTW, I have fixed the problem by removing all newline characters from
> the strings being passed to the log_err function.  The fix seems to
> work.  What's more, I can make the bug come back simply by adding the
> statement
>
> system((char *)">> This is an intentional error.");
>
> to the original log_err function.  Still puzzling, because function
> log_err knows nothing about "my_log_file" or its associated FILE
> object.
>
> Thanks for any info you all can provide.  I'm also curious if anyone
> has encountered this sort of thing on any other versions of UNIX.
>
> TKJ

--
Barry Margolin, barmar@alum.mit.edu
Arlington, MA
*** PLEASE post questions in newsgroups, not directly to me ***
*** PLEASE don't copy me on replies, I'll read them in the group ***

[ Post a follow-up to this message ]

On Mar 19, 2:44 pm, thosjohn...@sbcglobal.net wrote:

> void log_err( char * errorMessage)
> {
>  char buffer[256];
>  char * log_dir, * log_file;
>  ...
>  sprintf(buffer,"echo %s >> %s/%s",  errorMessage, log_dir, log_file);
>  system(buffer);
>
> }

> then the message "Error xyz" gets appended to file /prod/foo/logs/bar.
> And this seems to work OK.  (The question of whether this is a
> sensible way to write to the log file is beyond the scope of this
> post).

Sorry, this function is hopelessly broken. It's a disaster waiting to
happen for many reasons, and worrying about log messages going to
wrong place (because of its assumptions about stdout and stderr) is
really the least of your problems.

If any log messages ever contain any data that might potentially be
supplied by a hostile user, you are *so* screwed. Consider if the user
supplies the following string:
foo"; rm -rf /*; echo"
and it gets pasted into
File "%s" does not exist

DS

[ Post a follow-up to this message ]

"David Schwartz" <davids@webmaster.com> writes:
> On Mar 19, 2:44 pm, thosjohn...@sbcglobal.net wrote:
> 
> 
>
> Sorry, this function is hopelessly broken.

It has the invariant that errorMessage, log_dir and log_file must have
suitable values so that the size of buffer is not exceeded by the
sprintf and that the contents of buffer after the sprintf make up a
shell command with only the intended purpose.

This is not particularly clever coding, but not necessarily defective.

[ Post a follow-up to this message ]

On Mar 19, 10:27 pm, "David Schwartz" <dav...@webmaster.com> wrote:
> On Mar 19, 2:44 pm, thosjohn...@sbcglobal.net wrote:
> 
> 
>
> Sorry, this function is hopelessly broken. It's a disaster waiting to
> happen for many reasons, and worrying about log messages going to
> wrong place (because of its assumptions about stdout and stderr) is
> really the least of your problems.
>
> If any log messages ever contain any data that might potentially be
> supplied by a hostile user, you are *so* screwed. Consider if the user
> supplies the following string:
>  foo"; rm -rf /*; echo"
> and it gets pasted into
>  File "%s" does not exist
>
> DS

I really have to agree.  And although I can rule out intentionally
hostile users, the list of things that could possibly go wrong by
accident is long.  I can only guess that the original programmer's
intent was to have a logging function that could be called safely from
any thread in this multi-threaded application and avoid mixing up the
messages from simultaneous calls.  His approach introduces the
problems you mention and doesn't even assure the messages won't get
scrambled together.

I'm now thinking I should just rewrite the logger  along the lines
of:

extern pthread_mutex_t  *logger_mutex;   //  Mutex built and
initialized by main
void log_err(char * msg)
{
static FILE * log_file = 0;
int ret_val;
ret_val = pthread_mutex_lock (logger_mutex);  //  Lock POSIX
mutex.
//  Do appropriate checks on ret_val.

if (log_file == (FILE *)0)
{
//  open the file, check for errors on open.
//  write to stderr and bail out if we cannot open the log
file.
}

//  Assume log_file is valid after error checks above.
fprint(log_file, msg);
fflush(log_file);   //  Allows UNIX tail, etc. to show latest log
messages.
ret_val = pthread_mutex_unlock(logger_mutex);  //  Release the
POSIX mutex.
//  Do appropriate checks on ret_val.
return;
}
////////////////// end of thread-safe function
log_err ////////////////////////////

[ Post a follow-up to this message ]

On Mar 20, 8:29 am, thosjohn...@sbcglobal.net wrote:

>  I'm now thinking I should just rewrite the logger  along the lines
> of:

Yeah, that would probably be best.

> extern pthread_mutex_t  *logger_mutex;   //  Mutex built and
> initialized by main

If you're dealing with C++, you'll want to statically initialize this
to NULL and check for NULL first in log_err. Otherwise, the function
is not safe if constructors of global objects try to log an error.
Make sure to initialize it before you create your first additional
thread in case no global objects logged any errors.

> void log_err(char * msg)
> {
>       static FILE * log_file = 0;
>       int ret_val;
>       ret_val = pthread_mutex_lock (logger_mutex);  //  Lock POSIX
> mutex.
>       //  Do appropriate checks on ret_val.

Not much point. If the mutex lock fails, what can you do? Something
must be really broken.

>       if (log_file == (FILE *)0)
>      {
>           //  open the file, check for errors on open.
>           //  write to stderr and bail out if we cannot open the log
> file.
>      }
>
>      //  Assume log_file is valid after error checks above.
>     fprint(log_file, msg);
>     fflush(log_file);   //  Allows UNIX tail, etc. to show latest log
> messages.

You could just open the file without any buffering.

>     ret_val = pthread_mutex_unlock(logger_mutex);  //  Release the
> POSIX mutex.
>     //  Do appropriate checks on ret_val.
>    return;}

Again, not much point. All you can do if it fails is terminate the
process with extreme prejudice. I guess that might make sense, after
all, we may be logging something fatal and things could be massively
screwy.

> ////////////////// end of thread-safe function
> log_err ////////////////////////////

DS

[ Post a follow-up to this message ]

"David Schwartz" <davids@webmaster.com> writes:
> On Mar 20, 8:29 am, thosjohn...@sbcglobal.net wrote: 
>
> Yeah, that would probably be best.
> 
>
> If you're dealing with C++, you'll want to statically initialize this
> to NULL and check for NULL first in log_err.

If there is no other initialization defined, the pointer will be
initialized to a NULL pointer before anything takes place, by virtue
of being an object with static storage duration.
 
>
> Not much point. If the mutex lock fails, what can you do?

Dump core, for instance, to help diagnose an eventual problem.

[ Post a follow-up to this message ]

On Mar 21, 5:41 am, Rainer Weikusat <rainer.weiku...@sncag.com> wrote:
> "David Schwartz" <dav...@webmaster.com> writes: 
> 
>

Thanks for all the suggestions.  Once again, it was easier and quicker
to start over and rewrite a function vs. trying to fix everything that
was broken in the old one.  I'm handling the "this should never
happen" errors by writing messages to stderr and calling exit.  I'm
putting this into production next week.  Next I have to fix similar
code in several related applications... the same person wrote both C
and C++ versions of the error logger, and they both abuse 'system' in
the same way.
Thanks again. TKJ

[ Post a follow-up to this message ]

On Mar 21, 5:41 am, Rainer Weikusat <rainer.weiku...@sncag.com> wrote:
> "David Schwartz" <dav...@webmaster.com> writes: 
> 
>

Thanks for all the suggestions.  Once again, it was easier and quicker
to start over and rewrite a function vs. trying to fix everything that
was broken in the old one.  I'm handling the "this should never
happen" errors by writing messages to stderr and calling exit.  I'm
putting this into production next week.  Next I have to fix similar
code in several related applications... the same person wrote both C
and C++ versions of the error logger, and they both abuse 'system' in
the same way.
Thanks again. TKJ

[ Post a follow-up to this message ]

thosjohnson@sbcglobal.net writes:
> On Mar 21, 5:41 am, Rainer Weikusat <rainer.weiku...@sncag.com> wrote: 
>
> Thanks for all the suggestions.  Once again, it was easier and quicker
> to start over and rewrite a function vs. trying to fix everything that
> was broken in the old one.  I'm handling the "this should never
> happen" errors by writing messages to stderr and calling exit.

I would be careful with this type of situations. One possible reason
for a mutex operation to fail would be that 'other code' destroyed the
mutex data structure by writing through a dangling pointer, which
generally means that one cannot really predict what is going to happen
once control flow is allowed to leave the point of error detection, eg
the chance to terminate the thing with some kind of debugging aid may
be gone after that. A real-world situation I already had to deal with:
Some binary-only third-party library (Opsec) that apparently managed
to corrupt the malloc heap by causing an item to be inserted into some
internal freelist that had a 'sucessor' pointed which pointed to
itself, eventually causing free calls happening during
'exit'-processing to endlessly loop while trying to move to the end of
this list. That's why I generally try to cause a segfault for
unexpected errors (eg '*(volatile unsigned *)-1 = 0' or something
similar). Then the kernel will forcibly terminate the process and will
eventually create a core dump file that is very helpful for
post-mortem analysis of what actually happened.

[ Post a follow-up to this message ]