Memory Glitches and the Logs

Posted by Gohan_TheDragonball on Mon 27 Mar 2006 06:14 AM — 14 posts, 46,243 views.

USA #0
I have been having a serious glitch for awhile now, basically tons of wierd characters are getting printed into my logs. I have no idea where it is coming from, and when i grepped for the function that prints to the logs, there are over 130 calls to the function, what I want to know is how can I figure out where the function is being called from so I can figure out where the glitch is coming from. I am not sure, but I think if I used that __FILE__ and __LINE__ thing in the actual function, it would merely print the file and line number of the file the function is merely in, and i don't need to know that.

This thing is happening quite often, which is making my logs hit high in the megabytes fairly quickly. i should also note i am not seeing these glitches in the mud anywhere, strictly in the logs.
Amended on Mon 27 Mar 2006 06:23 AM by Gohan_TheDragonball
Canada #1
Copy and paste from your logs, please.
It sounds like you have a char that's not being allocated, but used for log strings.
USA #2
That's correct, __FILE__ and __LINE__ will show the exact file and line number where they appear, not where the function caller appeared.

What you can do is add additional, optional arguments to your log function that indicate file and line number.

Here's an example, in psuedo-C:
void log_string(const char * str, int lineNumber, const char * file)
{
    int len;
    char * buf;
    
    len = strlen(str) + strlen(file) + 100; // get a lot of extra room, just in case.
    // Should technically only need strlen + strlen + floor(log(lineNumber)) + 1 + 11, but better safe than sorry.
    buf = (char*) malloc(len);
    sprintf(buf, "%s (%s, line %d)", str, file, lineNumber);
    log_string(buf);
    free(buf);
}


You would then use this new version of log_string in places where you want to log line numbers as well.

I think that you might also be able to do:

#define LINE_LOG_STRING(buf) log_string(buf, __LINE__, __FILE__)

This should work because, IIRC, the macro LINE_LOG_STRING will be expanded, and *then* __LINE__ and __FILE__ are evaluated, which means that they will be evaluated in the file using the macro, not the file defining the macro.
USA #3
Below is what my logs look like now:
^Mendif
^Mehave 5 people beginning+
^Mtheir training as well.
^Mendif
^Mendif
^Mendif
^Mendif
^Mehave 5 people beginning+
^Mtheir training as well.
^Mendif
^Mendif
^Mendif
^Mendif
^Mehave 5 people beginning+
^Mtheir training as well.
^Mendif
^Mendif
^Mendif
^Mendif
^Mehave 5 people beginning+
^Mtheir training as well.
^Mendif
^Mendif
^Mendif
^Mendif
^Mehave 5 people beginning+
^Mtheir training as well.
^Mendif
^Mendif
^Mendif
^Mendif
^Me^H¡;^ !^HÈ;^¼^VÁ
^Mendif
^Mendif
^Me^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^$
;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^$
Mon Mar 27 02:06:03 2006 :: (act_wiz.c, line 4006) :: [MON_DEBUG] Kreacher(#23): 38.000000(r2) + 2(egain) + 3(iq) + 4(awr) = 47
;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^$
Mon Mar 27 02:06:17 2006 :: (act_wiz.c, line 4006) :: [MON_CON] 220.245.152.234 attempting to multiplay.
Mon Mar 27 02:06:18 2006 :: (act_wiz.c, line 4006) :: [MON_CON] Preloading player data for: Harath (5K)
Mon Mar 27 02:06:18 2006 :: (act_wiz.c, line 4006) :: [MON_CON] Loading player data for: Harath (5K)
;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^H^\;^ ;^^H¡;^ !^HÈ;^¼^VÁ!0Ñ, ^$
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 sses
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006ces
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 gues
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006list
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 nges
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 sn's
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 0 0
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 ands
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 ials
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 sses
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006ces
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 gues
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006list
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 nges
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006 sn's
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^^QÂÁ!2006
^H¡;^ !^H^H¡;^ !^H^H¡;^ !^H^H¡;^ !^H^H¡;^ !^Hx^Gx^Gx^Gx^Gx^G^H¡;^ !^H^H¡;^ !^H^H¡;^ !^H^H¡;^ !^H^$
¿!(¡;^ç^Z^Hè;^ÿÿÿÿ÷ÿÿÿ^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^ÿÿÿÿ÷ÿÿÿ^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^ÿÿÿÿ÷ÿÿÿ^H¡;^ $
R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^ÿÿÿÿ^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;^ÿÿÿÿ^H¡;^ !^HÈ;^R~¿!^X¡;^^Sè^Z^HØ;^R~¿!(¡;^ç^Z^Hè;$
USA #4
Well besides that crap, I am now noticing a huge trend now that i can see file and line numbers, that is act_wiz.c:4006, when i look into that its the monitor_chan() snippet i inputed a long time ago. here is what that part looks like:

void monitor_chan( const char *message, int channel, sh_int level_mon )
{
char buf[MAX_STRING_LENGTH];
char buf3[MAX_STRING_LENGTH];
DESCRIPTOR_DATA *d;
int a;
int level = MAX_LEVEL;

for ( a = 0; monitor_table[a].min_level != 0; a++ )
if ( monitor_table[a].channel == channel )
{
level = monitor_table[a].min_level;
break;
}

sprintf( buf, "%s&G[&B%s&G]&B&W %s\n\r",
monitor_table[a].col, monitor_table[a].id, message);
sprintf( buf3, "[%s] %s", monitor_table[a].id, message);
log_string_plus( buf3, LOG_BUILD, MAX_LEVEL + 1);

for ( d = first_descriptor; d; d = d->next )
{
if ( d->connected == CON_PLAYING
&& !IS_NPC( d->character )
&& IS_SET( d->character->pcdata->monitor, channel )
&& level_mon <= get_trust( d->character ) )
{
stc( buf, d->character );
}

}

}

However, I see no glitches on the mud. Can anyone see anything wrong with that? While I am at it, just in case its the actual log function itself, here it is:

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

strtime = ctime( &current_time );
strtime[strlen(strtime)-1] = '\0';
fprintf( stderr, "%s :: (%s, line %d) :: %s\n", strtime, file, lineNumber, str );
return;
}
Amended on Mon 27 Mar 2006 08:29 AM by Gohan_TheDragonball
USA #5
Please use the code tag when posting code.

What does the "stc" function do? Is that show_to_char?

You should also look into those places that call the monitor_chan function, because the 'message' parameter itself might be broken.
USA #6
yeah i'm lazy and shortened send_to_char to stc, but i don't see how the functions calling that one would do anything, if message was broken, i would see the extra characters in the mud too wouldn't I? Because I don't see ANY extra characters.
USA #7
Doesn't Smaug strip any of those characters from being viewable on screen? That would be why you aren't seeing them displayed but they show up in the logs.

The only reason I can think of off hand at this hour that would cause a mess like this is an uninitialized value for the "a" variable causing it to grab random memory.
USA #8

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

   strtime = ctime( &current_time );
   strtime[strlen(strtime)-1] = '\0';
   fprintf( stderr, "%s :: (%s, line %d) :: %s\n", strtime, file, lineNumber, str );
   return;
}


Why does this function take paramaters it doesnt use? Also, the offset variable doesnt appear to be used either.

I think the problem must be with a string you are passing to the functions.
Amended on Mon 27 Mar 2006 03:20 PM by Nick Cash
Canada #9
Shouldn't you be using STRALLOC/sprintf/strcpy for
strtime = ctime( &current_time );
? :P
Amended on Mon 27 Mar 2006 08:09 PM by Dace K
USA #10
Not necessarily. ctime returns a pointer to its own static buffer, and so this would work. It's completely unsafe for threading, but for single threaded applications it's probably fine.

Gohan, if you could please edit your code post to use the code tag, that would make reading and debugging it much easier.
Canada #11
Hmm. I don't really see anything else it could possibly be though. Gohan, want to try that and see if it fixes it? :P It *should* work as you have it now, but it might be the reason.

It certainly was on a function I had to fix up on my mud the other day. *cough*.
USA #12
Just kind of want to update on my progress. I don't know if this is stock smaug or if the people that gave me the smaug codebase way back when modified it, but for some reason there was a global char called log_buf, which apparently was being used around 56 times in my codebase in some of the various calls to log_string. I removed that global definition and added the definitions to each of the functions, and that alleviated around 60% of my memory glitches. I do however still have some, so I am going to try out Valgrind and see what it gives me.
USA #13
Yes. The global definition of the static variable log_buf doesn't really help much. One of the reasons I ended up removing it myself for pretty much the same reasons.