Generated: Mon Aug 29 19:34:28 2016 from fgms-alog.pl 2016/01/09 22.2 KB. text copy
#!/usr/bin/perl -w # NAME: fgms-alog.pl # AIM: Given a fgms.log, read, analyse, and show results # 08/01/2016 - Some enhancements... # 20/06/2015 - Deal with some tracker message # 14/06/2015 - Added fgmslog.bat to run, and improve stats... # 01/06/2014 geoff mclane http://geoffair.net/mperl use strict; use warnings; use File::Basename; # split path ($name,$dir,$ext) = fileparse($file [, qr/\.[^.]*/] ) use Time::Local; use Cwd; my $os = $^O; my $perl_dir = '/home/geoff/bin'; my $PATH_SEP = '/'; my $temp_dir = '/tmp'; if ($os =~ /win/i) { $perl_dir = 'C:\GTools\perl'; $temp_dir = $perl_dir; $PATH_SEP = "\\"; } unshift(@INC, $perl_dir); require 'lib_utils.pl' or die "Unable to load 'lib_utils.pl' Check paths in \@INC...\n"; # log file stuff our ($LF); my $pgmname = $0; if ($pgmname =~ /(\\|\/)/) { my @tmpsp = split(/(\\|\/)/,$pgmname); $pgmname = $tmpsp[-1]; } my $outfile = $temp_dir.$PATH_SEP."temp.$pgmname.txt"; open_log($outfile); # user variables my $VERS = "0.0.1 2014-06-01"; my $load_log = 0; my $in_file = ''; my $verbosity = 0; my $out_file = ''; # ### DEBUG ### my $debug_on = 1; my $def_file = 'C:\Users\user\Downloads\logs\mp01\logfile.20160109'; #my $def_file = 'C:\Users\user\Downloads\logs\mp01\logfile.20160108'; #my $def_file = 'C:\Projects\PuTTY\logs\fgms-01.log'; ###my $def_file = 'C:\Users\user\Downloads\logs\temp\fgms.log'; ### program variables my @warnings = (); my $cwd = cwd(); sub VERB1() { return $verbosity >= 1; } sub VERB2() { return $verbosity >= 2; } sub VERB5() { return $verbosity >= 5; } sub VERB9() { return $verbosity >= 9; } sub show_warnings($) { my ($val) = @_; if (@warnings) { prt( "\nGot ".scalar @warnings." WARNINGS...\n" ); foreach my $itm (@warnings) { prt("$itm\n"); } prt("\n"); } else { prt( "\nNo warnings issued.\n\n" ) if (VERB9()); } } sub pgm_exit($$) { my ($val,$msg) = @_; if (length($msg)) { $msg .= "\n" if (!($msg =~ /\n$/)); prt($msg); } show_warnings($val); close_log($outfile,$load_log); exit($val); } sub prtw($) { my ($tx) = shift; $tx =~ s/\n$//; prt("$tx\n"); push(@warnings,$tx); } sub mycmp_decend_alpha { return 1 if (lc($a) gt lc($b)); return -1 if (lc($a) lt lc($b)); return 0; } # lines of interest # 02.04.2014 09:16:40 # My PID is 1678 # 06.04.2014 13:57:20 New REMOTE Client: Porcius@mpserver01:5000 (Aircraft/Lightning/Models/lightning-model.xml) current clients: 43 max: 78 # 06.04.2014 13:57:22 New LOCAL Client: BanditO@88.174.182.234:5000 (Aircraft/f-14b/Models/f-14b-bs.xml) current clients: 44 max: 78 # 06.04.2014 13:57:29 TTL exceeded, dropping pilot Diddy@mpserver01 after 133 seconds. Current clients: 43 max: 78 sub process_in_file($) { my ($inf) = @_; if (! open INF, "<$inf") { pgm_exit(1,"ERROR: Unable to open file [$inf]\n"); } my ($line,$inc,$lnn,$len); my ($day,$mth,$yr,$hr,$min,$sec,$pid,$pilot,$start,$rem,$j); my (@arr,@arr2,$dt,$tmp,$epoch,$startep,$endep,$diff,$cnt,$i,$ind,$ln,$wline); $lnn = 0; my $bad_lines = 0; my $remcnt = 0; my $loccnt = 0; my $dropcnt = 0; my %online = (); my %dropped = (); my %pilots = (); my $server_name = "No server name"; my $server_version = "No version"; my $server_port = "No port"; my $telnet_port = "No telnet"; my $admin_port = "No admin"; my $log_file = "Not given"; my $listen_on = "Not given"; my $relay_cnt = "not given"; my $cf_count = "not given"; my $last_epoch = 0; my %crossfeeads = (); $pid = "None given"; my $server_on = 0; my $start_count = 0; my $discdd = ""; my $ishub = 0; my $skipped_lines = 0; my $skipped_min = 999999; my $skipped_last = 0; my @lines = <INF>; close(INF); my $lncnt = scalar @lines; prt("Processing $lncnt lines, from [$inf]...\n"); for ($ln = 0; $ln < $lncnt; $ln++) { $line = $lines[$ln]; $lnn = $ln + 1; chomp $line; $line = trim_all($line); $len = length($line); next if ($len == 0); $wline = $line; # keep whole line... if ($line =~ /^(\d{2})\.(\d{2})\.(\d{4})\s+(\d{2}):(\d{2}):(\d{2})\s+/) { $day = $1; $mth = $2; $yr = $3; $hr = $4; $min = $5; $sec = $6; $dt = "$day.$mth.$yr $hr:$min:$sec"; $epoch = timelocal($sec,$min,$hr,$day,$mth-1,$yr); $rem = ''; # @arr = split(/\s+/,$line); # $cnt = scalar @arr; # for ($i = 0; $i < $cnt; $i++) { # $tmp = $arr[$i]; # if ($tmp =~ /(\d{2}):(\d{2}):(\d{2})/ ) { # $i++; # for (; $i < $cnt; $i++) { # $rem .= ' ' if (length($rem)); # $rem .= $arr[$i]; # } # } # } if (length($rem)) { $line = $rem; } else { $line =~ s/^\d{2}\.\d{2}\.\d{4}\s+\d{2}:\d{2}:\d{2}\s+//; } $ind = index($line,'#'); if ($ind > 1) { $tmp = substr($line,$ind + 1); $ind = index($line,'#'); if ($ind > 1) { # prt("$lnn: Discard [$line]\n"); # note thread overlap - sometimes a BAD LINE following # lots of joined lines... $discdd = "[$wline]"; $skipped_lines++; while ($lnn < $lncnt) { $tmp = trim_all($lines[$lnn]); if ($tmp =~ /^(\d{2})\.(\d{2})\.(\d{4})\s+(\d{2}):(\d{2}):(\d{2})\s+/) { last; # found a valid date stamp } $ln++; $lnn = $ln + 1; $discdd .= "." if (length($discdd)); $discdd .= "[$tmp]"; $skipped_lines++; } if ($skipped_last) { $diff = $epoch - $skipped_last; $skipped_min = $diff if ($diff < $skipped_min); } else { $skipped_last = $epoch; } prt("$lnn: Warn: discarded $discdd\n") if (VERB9()); next; # got get NEXT line } $line = substr($line,$ind); } # deal with LINE AFTER DATE TIME if ($line =~ /^\#\s+This\s+is\s+(.+)$/) { # first message as server starts $server_name = $1; $startep = $epoch; } elsif ($line =~ /^FG_SERVER::Done\(\)\s+-\s+exiting$/) { $endep = $epoch; $diff = $endep - $startep; prt("Server $server_name ran for $diff secs (".secs_HHMMSS($diff).")\n"); } elsif ($line =~ /\#\s+My\s+PID\s+is\s+(\d+)$/) { $pid = $1; prt("Started $day.$mth.$yr $hr:$min:$sec as PID $pid ($epoch)\n"); } elsif ($line =~ /New\s+REMOTE\s+Client:\s+(.+)$/) { # $pilot = $1; $rem = $1; @arr = split(/\s+/,$rem); $pilot = $arr[0]; $j = 1; while (index($pilot,'@') == -1) { $tmp = $arr[$j]; last if ($tmp =~ /^\(/); $pilot .= ' '; $pilot .= $tmp; $j++; } $remcnt++; #@arr = split(':',$pilot); #@arr2 = split('@',$arr[0]); @arr2 = split('@',$pilot); $pilot = $arr2[0]; $online{$pilot} = "$dt REMOTE"; $pilots{$pilot} = $dt; $pilot .= ' ' while (length($pilot) < 7); prt("REMOT '$pilot' at $dt\n") if (VERB2()); ##} elsif ($line =~ /New\s+LOCAL\s+Client:\s+(\S+)\s+\(/) { } elsif ($line =~ /^New\s+LOCAL\s+Client:\s+(.+)$/) { # $pilot = $1; # fails when space in name like # New LOCAL Client: Ceska R@71.237.60.230:5000 (Aircraft/707/Models/707.xml) current clients: 2 max: 4 $rem = $1; @arr = split(/\s+/,$rem); $pilot = $arr[0]; $j = 1; while (index($pilot,'@') == -1) { $tmp = $arr[$j]; last if ($tmp =~ /^\(/); $pilot .= ' '; $pilot .= $tmp; $j++; } $loccnt++; #@arr = split(':',$pilot); #@arr2 = split('@',$arr[0]); @arr2 = split('@',$pilot); $pilot = $arr2[0]; $online{$pilot} = "$dt LOCAL"; $pilots{$pilot} = $dt; $pilot .= ' ' while (length($pilot) < 7); prt("LOCAL '$pilot' at $dt\n") if (VERB2()); ###} elsif ($line =~ /TTL\s+exceeded,\s+dropping\s+pilot\s+(\S+)\s+after/) { } elsif ($line =~ /Users: TTL exceeded for /) { # Users: TTL exceeded for SP-K79 62.129.143.50 after 1 minutes ########## USELESS REPEATED MESSAGE ########## } elsif ($line =~ /^##\s+/) { # [## Pilots: total 22, local 16] *** FIX ME *** # [## Since: Packets 14289 BL=0 INV=0 UR=0 RD=1106 PD=14289 NP=0 CF=0/0 TN=167] *** FIX ME *** # [## Total: Packets 14289 BL=0 INV=0 UR=0 RD=1106 PD=14289 NP=0 CF=0/0 TN=167 TC/D/P=16/0/8] *** FIX ME *** } elsif ($line =~ /TTL\s+exceeded,\s+dropping\s+pilot\s+(.+)$/) { ###} elsif ($line =~ /^TTL\s+exceeded,\s+dropping\s+pilot\s+(.+)\s+after\s+(\d+)\s+seconds.\s+Current\s+clients:\s+(\d+)\s+max:\s+(\d+)$/) { # $pilot = $1; # fails when space in name like # TTL exceeded, dropping pilot * Bad Client *@LOCAL after 44231 seconds. Current clients: 2 max: 3 $rem = $1; @arr = split(/\s+/,$rem); $pilot = $arr[0]; $j = 1; while (index($pilot,'@') == -1) { $tmp = $arr[$j]; last if ($tmp =~ /^\(/); $pilot .= ' '; $pilot .= $tmp; $j++; } $dropcnt++; @arr2 = split('@',$pilot); $pilot = $arr2[0]; if (defined $online{$pilot}) { $start = delete $online{$pilot}; } else { if (!defined $dropped{$pilot}) { if ($pilot ne '* Bad Client *') { prtw("WARNING: $lnn: pilot '$pilot' not found in online\n") if (VERB5()); } } } $dropped{$pilot} = "$day.$mth.$yr $hr:$min:$sec"; $pilot .= ' ' while (length($pilot) < 7); prt("DROPD '$pilot' at $dt\n") if (VERB2()); } elsif ($line =~ /^\#\s+FlightGear\s+Multiplayer\s+Server\s+(.+)\s+started$/) { $server_version = $1; } elsif ($line =~ /^\#\s+using\s+protocol\s+version\s+v1.1\s+\(LazyRelay\s+enabled\)$/) { } elsif ($line =~ /^\#\s+listening\s+to\s+port\s+(\d+)$/) { $server_port = $1; } elsif ($line =~ /^\#\s+telnet\s+port\s+(\d+)$/) { $telnet_port = $1; } elsif ($line =~ /^\#\s+admin\s+port\s+(\d+)$/) { $admin_port = $1; } elsif ($line =~ /^\#\s+using\s+logfile\s+(.+)$/) { $log_file = $1; } elsif ($line =~ /^\#\s+listening\s+on\s+(.+)$/) { $listen_on = $1; } elsif ($line =~ /^\#\s+tracking\s+is\s+disabled.$/) { } elsif ($line =~ /^\#\s+I\s+have\s+(\d+)\s+relays$/) { $relay_cnt = $1; } elsif ($line =~ /^\#\s+I\s+have\s+(\d+)\s+crossfeeds$/) { $cf_count = $1; } elsif ($line =~ /^\#\s+crossfeed\s+(.+)$/) { $crossfeeads{$1} = 1; } elsif ($line =~ /^\#\sI\s+have\s+(\d+)\s+blacklisted\s+IPs$/) { } elsif ($line =~ /^\#\s+Files:\s+exit=\[\/tmp\/fgms_exit\]\s+stat=\[\/tmp\/fgms_stat\]$/) { } elsif ($line =~ /^\# I am a HUB Server/ ) { $ishub = 1; } elsif ($line =~ /^Main\s+server\s+started!$/) { } elsif ($line =~ /^\#\s+Admin\s+port\s+disabled,\s+please\s+set\s+user\s+and\s+password$/) { } elsif ($line =~ /^\#\#\s+Got\s+STAT\s+file\s+(.+)$/) { } elsif ($line =~ /^ERROR:\s+Unable\s+to\s+delete\s+stat\s+file!\s+Doing\s+hard\s+exit\.\.\.$/) { } elsif ($line =~ /^FG_SERVER::AddBadClient\(\)\s+-\s+(.+)\s+BAD\s+magic\s+number:.*$/) { } elsif ($line =~ /^\#\s+relay\s+/) { #} elsif ($line =~ /^\#\s+relay\s+(\S+)\s+\((\S+)\)$/) { # # relay mpserver01.flightgear.org:5000 (217.78.131.44) } elsif ($line =~ /^UNKNOWN RELAY:\s+(\S+)\s+is\s+not\s+a\s+valid\s+relay!$/) { ### Blacklist: TTL exceeded for not a valid relay 176.36.248.61 after 3 minutes ### Blacklist: TTL exceeded for not a valid relay 176.36.248.61 after 52 seconds } elsif ($line =~ /^Blacklist:\s+TTL\s+exceeded\s+for\s+not\s+a\s+valid\s+relay\s+(\S+)\s+after\s+(\d+)\s+/) { } elsif ($line =~ /FG_SERVER::HandleTelnet\(\)\s+-\s+Connection\s+reset\s+by\s+peer$/) { } elsif ($line =~ /^\#\s+tracked\s+to\s+(.+),\s+using\s+a\s+thread\./) { # # tracked to 123.202.160.230:8000, using a thread. } elsif ($line =~ /^\#\sFG_TRACKER::Loop:\s+started,\s(.+)$/) { # # FG_TRACKER::Loop: started, thread ID 05.01.2016 14:41:39 # I have 8 relays1 # note thread overlap - sometimes a BAD LINE following $discdd = ""; while ($lnn < $lncnt) { $tmp = trim_all($lines[$lnn]); if ($tmp =~ /^(\d{2})\.(\d{2})\.(\d{4})\s+(\d{2}):(\d{2}):(\d{2})\s+/) { last; } $ln++; $lnn = $ln + 1; $discdd .= "." if (length($discdd)); $discdd .= $tmp; } $tmp = length($discdd); prt("$lnn: Warn: discarded $discdd\n") if (length($discdd)); } elsif ($line =~ /^\#\sFG_TRACKER::Connect:\s+success$/) { # # FG_TRACKER::Connect: success } elsif ($line =~ /^\# FG_TRACKER::TrackerWrite: lost connection to server$/) { # # FG_TRACKER::TrackerWrite: lost connection to server } elsif ($line =~ /^\# FG_TRACKER::TrackerRead: lost connection to server$/) { # # FG_TRACKER::TrackerRead: lost connection to server } elsif ($line =~ /^\# FG_TRACKER::Loop: trying to connect$/) { # # FG_TRACKER::Loop: trying to connect } elsif ($line =~ /^\# FG_TRACKER::Loop: not connected, will slepp for 10 seconds$/) { # # FG_TRACKER::Loop: not connected, will slepp for 10 seconds } elsif ($line =~ /^\# FG_TRACKER::Connect: Connect failed!$/) { # # FG_TRACKER::Connect: Connect failed! } elsif ($line =~ /^\# FG_TRACKER::Loop: seding msg ping pilot/) { # # FG_TRACKER::Loop: seding msg ping pilot... } elsif ($line =~ /^\# FG_TRACKER::TrackerRead: received message from server/) { # } elsif ($line =~ /^\# FG_TRACKER::Loop: not connected, will sleep for (\d+) seconds/) { # # FG_TRACKER::Loop: not connected, will sleep for 30 seconds } elsif ($line =~ /^\# FG_TRACKER::ReplyFromServer:\s/) { # # FG_TRACKER::ReplyFromServer: Received error message from FGTracker. Msg: 'ERROR FGTracker is closing your connection' } elsif ($line =~ /FG_TRACKER::Loop: /) { # # I have 08.01.2016 20:26:53 # FG_TRACKER::Loop: started, thread ID 8 relays } else { prtw("WARNING: $lnn: NOT Parsed [$line] *** FIX ME ***\n"); #pgm_exit(1,""); $load_log = 1; } } else { # BAD Time but otherwise # WHAT IS THIS? [05.0105.0105.01.2016 17:14:49 # FG_TRACKER::TrackerRead: received message from server] if ($line =~ /FG_TRACKER::TrackerRead:/) { # just dump this bad message } elsif ($line =~ /TTL exceeded for/) { # 15516: WHAT IS THIS? [06.016201.2016 11:34:03 11:34:03Usersp: TTL exceeded for helijah 64.69.4opc5:8s8nding asg r 1 msinutes] *** FIX ME *** } elsif ($line =~ / DISCONNECT/) { # 15518: WHAT IS THIS? [50 bytes: DISCONNECT vn110 test SenecaII 2016-01-06 10:33:52] } elsif ($line =~ /^\d+$/) { # 394809508503 } else { prtw("WARNING:$lnn: WHAT IS THIS? [$line] *** FIX ME ***\n"); ###pgm_exit(1,""); $bad_lines++; } } } ### close INF; $endep = $epoch; $diff = $endep - $startep; prt("Server $server_name end log $diff secs. (".secs_HHMMSS($diff).")\n"); prt("Server name $server_name, version $server_version, port $server_port, telnet $telnet_port, admin $admin_port\n"); prt("Log file $log_file, listen on $listen_on, relays $relay_cnt, cf $cf_count"); @arr = keys %crossfeeads; if (@arr) { prt(" - ".join(" ",@arr)); } prt("\n"); $tmp = secs_HHMMSS($diff); prt("Last $day.$mth.$yr $hr:$min:$sec as PID $pid - rt $tmp\n"); if ($skipped_min < 999999) { $tmp = secs_HHMMSS($skipped_min); } else { $tmp = ''; } prt("Processed $lnn lines... bad $bad_lines, skipped $skipped_lines ($tmp)\n"); prt("REMOTE $remcnt, LOCAL $loccnt, dropped $dropcnt\n"); @arr = sort mycmp_decend_alpha keys %pilots; $cnt = scalar @arr; prt("Had $cnt different pilots...\n"); if (VERB5()) { $cnt = 0; foreach $pilot (@arr) { prt("'$pilot' "); $cnt++; if ($cnt == 10) { prt("\n"); $cnt = 0; } } prt("\n") if ($cnt); } @arr = sort mycmp_decend_alpha keys %online; $cnt = scalar @arr; prt("Got $cnt still online...\n"); $remcnt = 0; $loccnt = 0; foreach $pilot (@arr) { $dt = $online{$pilot}; prt("$pilot $dt\n") if (VERB1()); if ($dt =~ /REMOTE$/) { $remcnt++; } else { $loccnt++; } } prt("Got $remcnt REMOTE, $loccnt LOCAL...\n"); } ######################################### ### MAIN ### parse_args(@ARGV); process_in_file($in_file); pgm_exit(0,""); ######################################## sub need_arg { my ($arg,@av) = @_; pgm_exit(1,"ERROR: [$arg] must have a following argument!\n") if (!@av); } sub parse_args { my (@av) = @_; my ($arg,$sarg); my $verb = VERB2(); while (@av) { $arg = $av[0]; if ($arg =~ /^-/) { $sarg = substr($arg,1); $sarg = substr($sarg,1) while ($sarg =~ /^-/); if (($sarg =~ /^h/i)||($sarg eq '?')) { give_help(); pgm_exit(0,"Help exit(0)"); } elsif ($sarg =~ /^v/) { if ($sarg =~ /^v.*(\d+)$/) { $verbosity = $1; } else { while ($sarg =~ /^v/) { $verbosity++; $sarg = substr($sarg,1); } } $verb = VERB2(); prt("Verbosity = $verbosity\n") if ($verb); } elsif ($sarg =~ /^l/) { if ($sarg =~ /^ll/) { $load_log = 2; } else { $load_log = 1; } prt("Set to load log at end. ($load_log)\n") if ($verb); } elsif ($sarg =~ /^o/) { need_arg(@av); shift @av; $sarg = $av[0]; $out_file = $sarg; prt("Set out file to [$out_file].\n") if ($verb); } else { pgm_exit(1,"ERROR: Invalid argument [$arg]! Try -?\n"); } } else { $in_file = $arg; prt("Set input to [$in_file]\n") if ($verb); } shift @av; } if ($debug_on) { prtw("WARNING: DEBUG is ON!\n"); if (length($in_file) == 0) { $in_file = $def_file; prt("Set DEFAULT input to [$in_file]\n"); } #$load_log = 1; } if (length($in_file) == 0) { give_help(); pgm_exit(1,"ERROR: No input files found in command!\n"); } if (! -f $in_file) { pgm_exit(1,"ERROR: Unable to find in file [$in_file]! Check name, location...\n"); } } sub give_help { prt("\n"); prt("$pgmname: version $VERS\n"); prt("Usage: $pgmname [options] in-file\n"); prt("Options:\n"); prt(" --help (-h or -?) = This help, and exit 0.\n"); prt(" --verb[n] (-v) = Bump [or set] verbosity. def=$verbosity\n"); prt(" --load (-l) = Load LOG at end. ($outfile)\n"); prt(" --out <file> (-o) = Write output to this file.\n"); prt("\n"); prt(" Read a fgms server text log, and show some information.\n"); prt("\n"); #prt(" See also fgms-alog.pl, fgmslog.bat, which does the same thing\n"); prt(" See also showlog.pl, showlog.bat, which does the same thing\n"); prt(" See crossfeed, hcfm.bat, for reading a RAW fgms log.\n"); prt("\n"); } # eof - template.pl