logfiles full or crap

Posted by Gohan_TheDragonball on Thu 18 Jan 2007 07:24 AM — 16 posts, 56,499 views.

USA #0
having a small problem, i am trying to find out how this mumbled garbage is getting printed to my logfiles. what i did was make it so what file and line called the log_string function, and then made it so no line can print to the file stderr without going through the log string function. however i still have junk getting printed to my logfiles.

however i still couldn't figure out how this junk was getting into my logfile, so i commented everything in log_string out, so that none of my code is printing to the stderr file at all. however my logfiles are still getting the same junk printed to them.

so i figured none of my code is to blame for my bloated logfiles full of crap. does anyone have any idea how the smaug code is printing to the logfile or has anyone ran into this?

USA #1
By garbage, do you mean completely random symbols? That means that somewhere you are not terminating a string correctly with a \0 at the end.

Have you tried grepping for all places that print to stderr? That would at least let you figure out where the culprit might be. You'd have to work backwards from there.

Are the garbage lines completely garbage, or are parts of them correct? That would be an even better hint as to where the problem is.
USA #2
i already did grep for stderr and changed every single line to go through log_string so that i could see what file and line number the call was coming from in an effort to find out which string was not being done properly. and in some cases its random characters, or its the same thing over and over, like some random ip address, or the word endif over and over and over. and also what is being printed to the logfile does not have the file and line number next to it, so its not coming through the log_string function.


void log_string_plus2( const char *str, sh_int log_type, sh_int level, int lineNumber, const char *file )
{
    char strtime[MAX_STRING_LENGTH];

    snprintf( strtime, MAX_STRING_LENGTH, "%s :: (%s, line %d) :: %s\n", friendly_ctime( &current_time), file, lineNumber, str );
    fprintf( stderr, strtime );

    return;
}

defined in mud.h as:
#define log_string_plus(txt, log_type, level)   ( log_string_plus2( (txt), (log_type), (level), __LINE__, __FILE__ ) )


thats the func in case anyone was askin.
USA #3
Yes, that definitely sounds like a problem with not terminating the string. Is the first part of these bad lines valid? Again that would give a very good hint as to where you should be looking for the culprit.
USA #4
ok upon further review it looks like the garbage might be getting sent from the function PERROR. i grepped and found about a hundred matches, so the hunt begins.
USA #5
Well, like I said, the best thing to do is look at the prefix of the line. Find the part that's not garbage. Search for that, and see where the string is generated. If the point of generation is not broken, simply follow all functions it gets passed through. That will get you the culprit fairly quickly. This assumes that the first part of the line isn't garbage as well; if it is then you have other concerns because you're printing out a purely garbage string somewhere.
USA #6
i rerouted PERROR to my log_string function and the junk still got printed and no line numbers got printed. so i commented out log_string again with everyhting being rerouted there nothing should be getting printed in theory, but the junk is still being printed. so i am back to square one, and have no clue where it is coming from. and it is nonsensical, nothin leads me to where it might be coming from.
USA #7
Could you please answer my question: is or is not the first part of the line something you expect to see?

As for the rest, well, all I can say is grep for things like:
printf
fprintf
warn
error
perror
etc.
and make sure that everything looks like it should be there. If you comment out **all** of those lines, and you still are getting stuff, well, you need to look more! :-)

Have you tried using valgrind? It's a very good tool for this kind of problem.

There's a program you can run call strace that traces all system calls a program makes. You'll get a lot of uninteresting information, but you will also get to see which call is being made to print stuff to the screen.
USA #8
i am not trying to rude but if the stuff being printed was interrupting that was supposed to be being printed to the logfiles, i would have simply gone to that section of the code. unfortunately wolfpaw are morons, i sent them numerous emails about getting valgrind installed and they never responded, so that is a dead alley.
USA #9
Well, ok, but you should have just said straight off that there was no interruption. :)

Anyhow, you can try using strace as I mentioned which will list the system calls. (ltrace does the same thing but for dynamic links e.g. the C runtime library) This is not ideal as it does not give you the line of code that made the system call, however, it will at least tell you which system calls you should be looking for in the code.

I mean, you claim to have commented out every single line that prints something, and yet stuff is still being printed, so something was missed somewhere. These diagnostic tools can help you pinpoint what was called where.

Here is some sample output running ltrace on my MUD:
vsnprintf("---------------------[ Boot Log "..., 4096, "---------------------[ Boot Log "..., 0xff976ba4) = 53
ctime(0x82a2ec4)                                                                   = "Fri Jan 19 00:03:25 2007\n"
fprintf(0xf7dde560, "%s :: %s\n", "Fri Jan 19 00:03:25 2007", "[*****] BOOT: ------------------"...Fri Jan 19 00:03:25 2007 :: [*****] BOOT: ---------------------[ Boot Log ]--------------------
) = 96
fclose(0x82bacf8)                                                                  = 0
fopen("../system/boot.txt", "a")                                                   = 0
fopen("/dev/null", "r")                                                            = 0x82bacf8
ctime(0x82a2ec4)                                                                   = "Fri Jan 19 00:03:25 2007\n"
fprintf(0xf7dde560, "%s :: %s\n", "Fri Jan 19 00:03:25 2007", "Loading commands"Fri Jan 19 00:03:25 2007 :: Loading commands
)  = 45
fopen("../system/commands.dat", "r")                                               = 0
vsprintf(0xff975b15, 0x826feb2, 0xff976b84, 0x8124067, 0xff975b20)                 = 24
ctime(0x82a2ec4)                                                                   = "Fri Jan 19 00:03:25 2007\n"
fprintf(0xf7dde560, "%s :: %s\n", "Fri Jan 19 00:03:25 2007", "[*****] BUG: Cannot open command"...Fri Jan 19 00:03:25 2007 :: [*****] BUG: Cannot open commands.dat
) = 66
fclose(0x82bacf8)                                                                  = 0
fopen("../system/bugs.txt", "a")                                                   = 0
fopen("/dev/null", "r")                                                            = 0x82bacf8
exit(0 <unfinished ...>
USA #10
ok i ran strace on my mud and heres what i got:

open("../system/REQUESTS", O_RDONLY|O_NONBLOCK) = 7
write(1, "if\n\rendif\n\rndif\n\rendif\n\rndif\n\ren"..., 4096) = 4096
fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(9, 0x831c188, 8192) = -1 EAGAIN (Resource temporarily unavailable)
fcntl64(9, F_SETFL, O_RDWR) = 0

i can't tell where the call is coming from though. i turned off the requests pipe and it seemed to remove the problem. but i can't figure out how the requests pipe is writing this crap to the logfiles.
Amended on Fri 19 Jan 2007 08:47 AM by Gohan_TheDragonball
USA #11
OK. The line
write(1, "if\n\rendif\n\rndif\n\rendif\n\rndif\n\ren"..., 4096)
is a problem. The '1' as the first argument means file descriptor #1, which is standard output. The second argument is the string to write. The third argument is how much to write. Somehow, you are printing out that string very shortly after opening the requests pipe. ("that string" being something basically random from memory)

What you need to do is to trace the code starting at that open syscall -- the one that opens the request pipe -- and look for *any* line that could *possibly* issue a call down the line to the write system call. Note that functions like printf are not system calls but library calls; basically you need to look for anything that prints anything anywhere.

If you don't feel like tracing line by line, you can try putting in bogus calls to the "open" system call, and narrow down where that write call is being made. (This is basically printf debugging, but using strace! Whee!)
USA #12
well i finally found the problem, well at least the function which is the source of the problem. when i turned off the webwho updater, which is located in the requests part, the crap stopped coming into my logs. so its somewhere in my WHO command. now the hard part of tracking it down.
USA #13
turned out to not be that hard, looks like when i was adding in my sql stuff i forgot an 's' and put printf instead of sprintf.
USA #14
How come you didn't find this when grepping for printf? :P
USA #15
because until last night i didn't know about the -w option in grep.