Author Topic: Time between receving logs and updating the interface  (Read 360 times)

0 Members and 1 Guest are viewing this topic.

Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Time between receving logs and updating the interface
« on: January 10, 2012, 12:50:56 pm »
Sorry for the vague subject but I didn't know how else to describe it.  The situation is, it doesn't seem that entries are updated to the interface in a very timely fashion, at times.  And it would seem that when it does occur, you'll get multiple updates for different "hosts" all at the same time whose log entries were also received at different times.

I am talking about the "Last 10 Hosts" section.

A recently new host was configured to send its logs to the server.  Syslog-ng received that at 12:24 EST but it didn't post to the logzilla interface until roughly 12:46 EST.  When the host finally became present in the interface, it was updated, or the "Last Seen" column reflected the exact same time period as another random host logging to this server for which syslog-ng did see at 12:46.

So, one hosts log was received by syslog-ng at 12:24
Another hosts log was received at 12:46
Logzilla updated the "Last Seen" column for both hosts at 12:46

I experience similarities all the time.

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #1 on: January 10, 2012, 01:42:53 pm »
Hi,
My guess is that the sending device has an incorrect time and syslog-ng is comfigured to use the sender's timestamp.

Check your syslog-ng.conf and see if you are using R_times (received), it should look something like this:

Code: [Select]
destination d_logzilla {
   program("/var/www/logzilla/scripts/db_insert.pl"
   template("$R_YEAR-$R_MONTH-$R_DAY $R_HOUR:$R_MIN:$R_SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};
Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #2 on: January 10, 2012, 01:45:58 pm »
I forgot:
You can also print a test directly into db_insert to make sure it isn't syslog-ng causing it:


Code: [Select]
printf "`date \"+%Y-%m-%d %H:%M:%S\"`\ttest\t190\tCRON\tTest\n" | /var/www/logzilla/scripts/db_insert.pl -d5 -v
If the problem still exists, make sure you are using "tail" mode to show live events as they come in, otherwise you will have to make sure your sphinx indexer has indexed the data before it can be searched (check the cron entry in /etc/cron.d/logzilla - the default is every minute).



Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Re: Time between receving logs and updating the interface
« Reply #3 on: January 10, 2012, 02:30:55 pm »
I have used db_insert on several occasions to test and the update has always been immediate as was this last test just run.

Here is my syslog-ng.conf settings for the applicable area:

destination d_logzilla {
   program("/var/www/logzilla/scripts/db_insert.pl"
   template("$YEAR-$MONTH-$DAY $HOUR:$MIN:$SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};

So I guess I am not using R_times.  Should I be?  My server is in EST and I my senders exist in both EST and MST and the problem seems persistent across both.  The server and senders are all sync'd to NTP.

The Sphinx delta script looks to be configured to run every minute but here is the full output from /etc/cron.d/logzilla:

#####################################################
# BEGIN LogZilla Cron Entries
#####################################################
# http://www.logzilla.pro
# Sphinx indexer cron times
# Note: Your setup may require some tweaking depending on expected message rates!
# Install date: Sat Jan  7 00:49:32 2012
#####################################################

#####################################################
# Run Sphinx "full" scan 30 minutes after midnight
# in order to create a new index for today.
#####################################################
30 0 1 * * root /var/www/logzilla/sphinx/indexer.sh full >> /var/log/logzilla/sphinx_indexer.log 2>&1

#####################################################
# Run Sphinx "delta" scans every 5 minutes throughout
# the day. 
# Delta indexing should be very fast but you may need
# to adjust these times on very large systems.
#####################################################
*/1 * * * * root /var/www/logzilla/sphinx/indexer.sh delta >> /var/log/logzilla/sphinx_indexer.log 2>&1

#####################################################
# Run Sphinx "merge" scans every day at midnight
# Merging is much faster than a full scan.
# You may need to adjust these times on very large systems.
#####################################################
0 0 * * * root /var/www/logzilla/sphinx/indexer.sh merge >> /var/log/logzilla/sphinx_indexer.log 2>&1

#####################################################
# Daily export archives
#####################################################
0 1 * * * root sh /var/www/logzilla/scripts/export.sh

#####################################################
# END LogZilla Cron Entries
#####################################################

I'm not familiar with tail mode, so I'll see what I can learn about it.


Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Re: Time between receving logs and updating the interface
« Reply #4 on: January 10, 2012, 03:19:00 pm »
Hey Clayton, perhaps this will help.  I ran db_insert.pl against my debug file which results in INVALID MESSAGE FORMAT indicators and "Error inserting record ..." messages.

Here is the rest of the output that is less sensitive information.

    DBI::st=HASH(0x6c9c040) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
    DBI::st=HASH(0x6c9c130) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
    DBI::st=HASH(0x6c9c220) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
EOF - Flushing buffer
Importing 4 messages into the database
    DBI::st=HASH(0x6c9c310) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
    -> execute for DBD::mysql::st (DBI::st=HASH(0x6c9c3c0)~0x6c9c310) thr#644b010
    -> dbd_st_execute for 06c9c4d0
---> parse_params with statement LOAD DATA INFILE '/tmp/logzilla_import.txt' INTO TABLE logs FIELDS TERMINATED BY "\t" LINES TERMINATED BY "\n" (host,facility,severity,program,msg,mne,eid,fo,lo) num params 0
mysql_st_internal_execute
    <- dbd_st_execute returning imp_sth->row_num 0
    <- execute= '0E0' at /var/www/logzilla/scripts/db_insert.pl line 392
Inserting MPS string: chart_mps_13,8
Ending insert: 15:11:13
Time taken for entire loop was  0 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU) seconds
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c310)~INNER) thr#644b010
    <- DESTROY= undef
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c220)~INNER) thr#644b010
    <- DESTROY= undef
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c130)~INNER) thr#644b010
    <- DESTROY= undef
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c040)~INNER) thr#644b010
    <- DESTROY= undef

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #5 on: January 10, 2012, 03:19:46 pm »
Quote
So I guess I am not using R_times.  Should I be?
Yes - that will mark every incoming message with your LogZilla server's timestamp instead of what the sending device is generating. This will save you a lot of pain with systems in various time zones also.

The "tail" mode is a setting on the main page of LogZilla under the Search Options portlet - look for "Live Scroll (Tail)" , then set it to 1 second. If you don't see your message com in there, then it most likely has the wrong time stamp (or syslog-ng didn't send it to LogZilla).

Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #6 on: January 10, 2012, 03:21:40 pm »

    DBI::st=HASH(0x6c9c040) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
    DBI::st=HASH(0x6c9c130) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
    DBI::st=HASH(0x6c9c220) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
EOF - Flushing buffer
Importing 4 messages into the database
    DBI::st=HASH(0x6c9c310) trace level set to 0x0/4 (DBI @ 0x0/0) in DBI 1.616-ithread (pid 2159)
    -> execute for DBD::mysql::st (DBI::st=HASH(0x6c9c3c0)~0x6c9c310) thr#644b010
    -> dbd_st_execute for 06c9c4d0
---> parse_params with statement LOAD DATA INFILE '/tmp/logzilla_import.txt' INTO TABLE logs FIELDS TERMINATED BY "\t" LINES TERMINATED BY "\n" (host,facility,severity,program,msg,mne,eid,fo,lo) num params 0
mysql_st_internal_execute
    <- dbd_st_execute returning imp_sth->row_num 0
    <- execute= '0E0' at /var/www/logzilla/scripts/db_insert.pl line 392
Inserting MPS string: chart_mps_13,8
Ending insert: 15:11:13
Time taken for entire loop was  0 wallclock secs ( 0.00 usr  0.00 sys +  0.00 cusr  0.00 csys =  0.00 CPU) seconds
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c310)~INNER) thr#644b010
    <- DESTROY= undef
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c220)~INNER) thr#644b010
    <- DESTROY= undef
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c130)~INNER) thr#644b010
    <- DESTROY= undef
    -> DESTROY for DBD::mysql::st (DBI::st=HASH(0x6c9c040)~INNER) thr#644b010
    <- DESTROY= undef

This is "normal" output - no errors here. Was there more?
Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Re: Time between receving logs and updating the interface
« Reply #7 on: January 10, 2012, 03:32:52 pm »
Just the preceding messages.  This is an example of what I previously left out.  I omitted the hostname which is just the FQDN of a sender on the network, nothing fancy - (host.name.domain.com)

INCOMING MESSAGE:
<omitted_hostname>    181     5935    Jan 10 15:11:03.188 EST: %SYS-5-CONFIG_I: Configured from console by vty1 (omitted_ip.addr)

INVALID MESSAGE FORMAT:
<omitted_hostname>    181     5935    Jan 10 15:11:03.188 EST: %SYS-5-CONFIG_I: Configured from console by vty1 (omitted_ip.addr)

Error inserting record <omitted_hostname>     181     5935    Jan 10 15:11:03.188 EST: %SYS-5-CONFIG_I: Configured from console by vty1 (omitted_ip.addr)

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #8 on: January 10, 2012, 03:40:03 pm »
I don't see a reason that should be invalid. You are cat'ing your DEBUG.log, right? (not copy/paste - if you copy/paste, you miss the TAB characters).


Can you please change your DEBUG.log in syslog-ng to use R_times as well? (restart syslog-ng after you do for changes to take effect).


Example:
Code: [Select]
destination d_logzilla {
   program("/var/www/logzilla/scripts/db_insert.pl"
   template("$R_YEAR-$R_MONTH-$R_DAY $R_HOUR:$R_MIN:$R_SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};
destination df_logzilla {
   file("/var/log/logzilla/DEBUG.log"
   template("$R_YEAR-$R_MONTH-$R_DAY $R_HOUR:$R_MIN:$R_SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};

# Tell syslog-ng to log to our new destination
log {
   source(s_all);
      destination(d_logzilla);
      # Uncomment below and restart syslog-ng for debugging
      destination(df_logzilla);
};

Once you have that DEBUG.log, you can "replay" an event from it by typing:

Code: [Select]
tail -1 /var/www/logzilla/DEBUG.log | /var/www/logzilla/scripts/db_insert.pl -d5 -v
Which would replay (insert into the DB as a new record)  the last event that came in.



Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Re: Time between receving logs and updating the interface
« Reply #9 on: January 10, 2012, 05:06:53 pm »
The results are the same whether or not R_times are used.  I forced the sender to log basically identical entries 3 times in a row at 16:54:34, 16:56:51 & 16:58:45.  I piped all those through db_insert all with the same result - INVALID MESSAGE FORMAT & Error inserting record.

BUT, this particular host updated to be "Last Seen" 5 minutes ago with the last message having a "RECEIVED" time at 16:56:52.  1 of the 3 appear to have been inserted but the output of the script tell me otherwise?

So.....

Since my last update, I've since removed the RPM package version of syslog-ng and compiled from source, now running 3.3.3 instead of 2.1.4 from CenOS repos (I read in some other places the possibility of issues with older versions).

Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Re: Time between receving logs and updating the interface
« Reply #10 on: January 10, 2012, 11:15:30 pm »
Any thoughts on the INVALID MESSAGE FORMAT messages?  I checked all of my devices logs by piping it into the pl-script and interestingly it seems most if not all result in this but that it also seems some messages get inserted and some don't.

Anything else I can show?

TIA

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #11 on: January 10, 2012, 11:25:59 pm »
Can you please capture some logs in your debug log (http://forum.logzilla.pro/index.php/topic,203.0.html) for me? so I can try to recreate the problem here?
Also, which version of LogZilla are you using?

Once you have the debug.log, please gzip it and send it to cdukes @ logzilla.pro
Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #12 on: January 11, 2012, 09:30:29 am »
Hi,
Thanks for the logs. They are working properly for me.
I suspect you are unable to replay them because you didn't set the template for the DEBUG.log as I stated in a previous post (the time stamps are missing).
Here's the correct template to use for both the db_insert and DEBUG.log.

Code: [Select]
destination d_logzilla {
   program("/var/www/logzilla/scripts/db_insert.pl"
   template("$R_YEAR-$R_MONTH-$R_DAY $R_HOUR:$R_MIN:$R_SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};
destination df_logzilla {
   file("/var/log/logzilla/DEBUG.log"
   template("$R_YEAR-$R_MONTH-$R_DAY $R_HOUR:$R_MIN:$R_SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};

# Tell syslog-ng to log to our new destination
log {
   source(s_all);
      destination(d_logzilla);
      # Uncomment below and restart syslog-ng for debugging
      destination(df_logzilla);
};


That said, here is a script you can use that will replay the events you gave me without a timestamp (they will be inserted with the current time).
(note that you may need additional perl modules to run it), which you can do by typing, for example, :
Code: [Select]
perl cpan Data::Random
# cat playlogs.pl
Code: [Select]
#!/usr/bin/perl

##
##
use strict;

$| = 1;

use POSIX qw/strftime/;
use Switch;
use vars qw/ %opt /;
use Data::Random qw(:all);


my ($input, $output, $sleep, $sleep_end);
sub init()
{
    use Getopt::Std;
    my $opt_string = 'i:o:ht:e:';
    getopts( "$opt_string", \%opt ) or usage();
    usage() if $opt{h};
    $input = defined($opt{'i'}) ? $opt{'i'} : 'syslog.log';
    $sleep = defined($opt{'t'}) ? $opt{'t'} : '1';
    $sleep_end = $opt{'e'};
}
init();

#
# Help message
#
sub usage()
{
    print STDERR << "EOF";
    Used to replay lz formatted logs into db_insert with timestamps
    -i        : Specify input file from the sample_logs/ directory
    -t        : Sleep seconds between messages (default: 1)
    -e        : End sleep seconds (optional, will randomize between start (-t) and end (-e) seconds.
    Sample Usage:
    Show what would be replayed:
    $0 -i sample_logs/*.log -t .5 -e 1.5 | more
    Replay into LogZilla:
    $0 -i sample_logs/*.log -t .5 -e 1.5 | /var/www/logzilla/scripts/db_insert.pl
    Note that db_insert will not return status while running unless you set debug or verbose on it as well (-d1 -v)
EOF
    exit;
}

my $regex = qr/\t?(\S+)\t(\d+)\t(\S+).*\t(.*)/;
my $count = 0;
my ($host, $sev, $fac, $pri, $msg, $mne, $prg, @arr);
open(INPUT, "<$input") || die("Try $0 -h\n");
while(<INPUT>) {
    chomp;
    $_ =~ s/\r\n$/\n/;
    if ($_ =~ m/$regex/) {
        $host = $1;
        $pri = $2;
        $prg = $3;
        $msg = $4;
        my $now = strftime("%Y-%m-%d %H:%M:%S", localtime);
        my $dt = rand_datetime( min => '2011-9-1 4:0:0', max => 'now' );
        print("$now\t$host\t$pri\t$prg\t$msg\n");
        my $sleeptime;
        if ($sleep_end) {
            $sleeptime = ($sleep + rand($sleep_end));
        } else {
            $sleeptime = $sleep;
        }
        #print "Sleeping for $sleeptime\n";
        select( undef, undef, undef, $sleeptime );
    }
    $host = "";
    $prg = "";
    $mne = "";
    $msg = "";
    $sev = "";
    $count++;
}
Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline cdukes

  • LogZilla
  • Administrator
  • Hero Member
  • *****
  • Posts: 951
    • View Profile
    • LogZilla
Re: Time between receving logs and updating the interface
« Reply #13 on: January 11, 2012, 10:08:10 am »
Let me know how this works out for you. I found out this morning that you just purchased. Even though you did not purchase support, I would be happy to do a remote WebEx session with you to get this resolved. We like to make sure our customers are happy :)
Your Network is Your Business.  Be Proactive.  Go LogZilla.
Clayton Dukes
CTO, LogZilla, LLC
http://www.logzilla.pro

Offline jch

  • Newbie
  • *
  • Posts: 11
    • View Profile
Re: Time between receving logs and updating the interface
« Reply #14 on: January 11, 2012, 10:49:40 am »
You are right and I am a noob.  I have df_logzilla set correctly now like this:

destination df_logzilla {
   file("/var/log/logzilla/DEBUG.log"
   template("$R_YEAR-$R_MONTH-$R_DAY $R_HOUR:$R_MIN:$R_SEC\t$HOST\t$PRI\t$PROGRAM\t$MSGONLY\n")
   template_escape(yes)
   );
};

Having said that, the db_insert.pl script inserts the contents of a "fresh" DEBUG.log when manually executed.

So I then have some other problem because all of those new messages I just piped from DEBUG.log should have been inserted under normal circumstances when they were received from the sender.  The Host table of the interface doesn't reflect it until the manual run of the script.  Of the 30+ messages that should have been updated, it looks like perhaps 1 message is appearing.