Permalink
Browse files

Logging changes

  • Loading branch information...
1 parent a7544b1 commit 77e9c02afd9f5ba3fce24d0d29a5215efd0c4990 @solargroovy solargroovy committed May 20, 2013
Showing with 257 additions and 56 deletions.
  1. +33 −0 Kynetx/Configure.pm
  2. +17 −3 Kynetx/Modules/PCI.pm
  3. +50 −7 Kynetx/MongoDB.pm
  4. +4 −0 Kynetx/Response.pm
  5. +31 −36 Kynetx/Util.pm
  6. +50 −0 Log/Log4perl/ApacheStdErr.pm
  7. +1 −1 etc/tmpl/httpd-perl.conf.tmpl
  8. +4 −0 startup-krl.pl
  9. +1 −1 startup.pl
  10. +56 −2 t/Log.t
  11. +3 −2 t/Modules/PCI.t
  12. +7 −4 t/MongoDB.t
View
@@ -26,6 +26,7 @@ use YAML::XS;
use Data::Dumper;
$Data::Dumper::Indent = 1;
+use Log::Log4perl qw(get_logger :levels :easy);
use Exporter;
@@ -127,9 +128,41 @@ sub configure {
$config->{'METRICS'}->{'HOSTNAME'} = $host[0];
$config->{'METRICS'}->{'PROC'} = $$;
+ config_logging();
return 1;
}
+sub config_logging {
+ my $conf_file = Kynetx::Configure::get_config('LOG_CONF') || '/web/etc/log.conf';
+ if (Log::Log4perl->initialized()) {
+ my $logger = Log::Log4perl::get_logger();
+ $logger->debug("Logging ",Log::Log4perl::Level::to_level($logger->level()));
+ } else {
+ my $hostname = Sys::Hostname::hostname();
+ Log::Log4perl->init_once($conf_file);
+ Log::Log4perl::MDC->put( 'hostname', $hostname );
+ my $appenders = Log::Log4perl->appenders();
+ my $logger = Log::Log4perl::get_logger('');
+ my $threshold = get_log_threshold();
+ $logger->level(Log::Log4perl::Level::to_priority($threshold));
+ }
+
+}
+
+sub get_log_threshold {
+ my $mode = Kynetx::Configure::get_config('RUN_MODE');
+ my $debug = Kynetx::Configure::get_config('DEBUG');
+ if ($debug eq 'on') {
+ return "DEBUG"
+ } elsif ($debug eq 'off') {
+ return "WARN"
+ } elsif ($mode eq 'development') {
+ return "DEBUG"
+ } else {
+ return "WARN"
+ }
+
+}
sub get_config {
View
@@ -56,6 +56,7 @@ use Data::Dumper;
$Data::Dumper::Indent = 1;
use constant CREDENTIALS => "system_credentials";
+use constant EXPIRES_IN => "ttl1";
# format of list_tokens is array of {'cid' => val, 'name' => val}
@@ -1111,9 +1112,13 @@ sub auth_ken {
}
sub create_system_key {
+ my ($conf_key) = @_;
my $logger=get_logger();
+ $logger->debug("Make system key");
my $syskey = syskey();
- my $id = make_pass_phrase();
+ my $id = make_pass_phrase($conf_key);
+ return undef unless (defined $id);
+ $logger->debug("Make system key from $id");
my $phrase = get_pass_phrase($id);
my $data = $id . '||' . $phrase;
my $encrypted = RC4($syskey,$data);
@@ -1208,6 +1213,12 @@ sub get_pass_phrase {
}
sub make_pass_phrase {
+ my ($conf_key) = @_;
+ my $logger=get_logger();
+ if (defined $conf_key) {
+ my $salt = Kynetx::Configure::get_config('PCI_KEY');
+ return undef unless ($conf_key eq $salt);
+ }
my $word1 = Kynetx::Modules::Random::rword();
my $word2 = Kynetx::Modules::Random::rword();
my $oid = MongoDB::OID->new();
@@ -1219,8 +1230,11 @@ sub make_pass_phrase {
my $result = Kynetx::MongoDB::update_value('dictionary', $key,$value,1,0,1);
if (defined $result && ref $result eq "HASH") {
my $id = $result->{'upserted'};
- return $id->to_string()
- }
+ my $id_val = $id->to_string();
+ $logger->debug("Make passphrase ($id_val) $phrase expire");
+ Kynetx::MongoDB::set_ttl('dictionary',EXPIRES_IN,$id_val) unless (defined $conf_key);
+ return $id_val;
+ }
return undef;
}
View
@@ -44,6 +44,7 @@ use Devel::Size qw(
total_size
);
use Digest::MD5 qw(md5_base64);
+use DateTime;
use Kynetx::Configure;
use Kynetx::Json;
@@ -652,11 +653,34 @@ sub validate {
return 0;
} else {
return 1;
- }
-
-
+ }
+}
+
+####### TTL operations
+
+# never cache
+sub get_ttl {
+ my ($collection,$var) = @_;
+
+}
+
+sub set_ttl {
+ my ($collection, $ttl_index, $oid) = @_;
+ my $logger = get_logger();
+ $logger->debug("SET TTL: $collection $ttl_index $oid");
+ my $c = get_collection($collection);
+ my $id = MongoDB::OID->new(value => $oid);
+ my $key = {
+ "_id" => $id
+ };
+ my $val = {
+ '$set' => {$ttl_index => DateTime->now}
+ };
+ $c->update($key,$val);
}
+#######
+
sub update_value {
my ($collection,$var,$val,$upsert,$multi,$safe) = @_;
my $logger = get_logger();
@@ -823,7 +847,10 @@ sub get_cache {
my ($collection,$var) = @_;
my $logger = get_logger();
my $keystring = make_keystring($collection,$var);
- $logger->trace("Cache keystring (get) $keystring: ", sub {Dumper($var)});
+ if ($collection eq "edata") {
+ $logger->debug("get cache keystring (get) $keystring: ", sub {Dumper($var)});
+ }
+
my $result = Kynetx::Memcached::check_cache($keystring);
if (defined $result) {
return $result;
@@ -837,14 +864,20 @@ sub set_cache {
my $logger = get_logger();
my $parent = (caller(1))[3];
my $keystring = make_keystring($collection,$var);
+ if ($collection eq "edata") {
+ $logger->debug("set key cache: $keystring $value");
+ }
Kynetx::Memcached::mset_cache($keystring,$value,$CACHETIME);
}
sub clear_cache {
my ($collection,$var) = @_;
my $logger= get_logger();
my $keystring = make_keystring($collection,$var);
- $logger->trace("Clear cache for: $keystring");
+ if ($collection eq "kpds") {
+ $logger->debug("Clear cache for: $keystring");
+ }
+
Kynetx::Memcached::flush_cache($keystring);
#clear any reference to hash parts as well
clear_cache_for_hash($collection,$var);
@@ -880,6 +913,10 @@ sub get_cache_for_hash {
my $logger = get_logger();
my $key = make_keystring($collection,$var);
my $lookup_key = "_map_" . $key;
+ if ($collection eq "kpds") {
+ $logger->debug("list key cache: $lookup_key");
+ }
+
my $mcache_prefix = Kynetx::Memcached::check_cache($lookup_key);
my $dupe = clone $var;
$logger->trace("$lookup_key: ", sub {Dumper($mcache_prefix)});
@@ -897,12 +934,18 @@ sub set_cache_for_hash {
my $logger = get_logger();
my $key = make_keystring($collection,$var);
$logger->trace("Var: ",sub {Dumper($var)});
- $logger->trace("Calculated keystring in scfh: $key");
+ if ($collection eq "kpds") {
+ $logger->debug("Calculated keystring in scfh list key: $key");
+ }
+
$logger->trace("SCFH: ", sub {Dumper($path)});
my $lookup_key = "_map_" . $key;
my $mcache_prefix = time();
Kynetx::Memcached::mset_cache($lookup_key,$mcache_prefix,$CACHETIME);
- $logger->trace("Set master $lookup_key: ($mcache_prefix)");
+ if ($collection eq "kpds") {
+ $logger->debug("Set master $lookup_key: ($mcache_prefix)");
+ }
+
$var->{"cachemap"} = $mcache_prefix;
$var->{"hashpath"} = $path;
Kynetx::MongoDB::set_cache($collection,$var,$value);
View
@@ -180,6 +180,10 @@ sub respond {
return $dd->gen_raw_document($r);
} elsif ($req_info->{'understands_javascript'}) {
$logger->debug("Returning javascript from evaluation");
+ if ($logger->is_debug()) {
+ $logger->debug("__SCREEN__");
+ }
+
print $heartbeat, $js;
} else {
$logger->debug("Returning directives from evaluation");
View
@@ -100,10 +100,25 @@ correct_bool
our @EXPORT_OK =(@{ $EXPORT_TAGS{'all'} }) ;
+sub init_logging {
+# my $conf_file = Kynetx::Configure::get_config('LOG_CONF') || '/web/etc/log.conf';
+# if (Log::Log4perl->initialized()) {
+# my $logger = get_logger();
+# $logger->debug("Logging already initialized");
+# } else {
+# Log::Log4perl->init_once($conf_file);
+# }
+# my $appenders = Log::Log4perl->appenders();
+# foreach my $key (keys %{$appenders}) {
+# print STDERR $key
+# }
+ return 1;
+}
# set up logging
sub config_logging {
+ return;
my ($r) = @_;
if(Log::Log4perl->initialized()) {
my $logger = get_logger();
@@ -177,44 +192,21 @@ sub config_logging {
sub turn_on_logging {
-
- my $logger = get_logger('Kynetx');
-
- # match any newline not at the end of the string
- my $re = qr%\n(?!$)%;
- my $appender = Log::Log4perl::Appender->new(
- "Log::Dispatch::Screen",
- stderr => 0,
- name => "ConsoleLogger",
- callbacks => sub{my (%h) = @_;
- $h{'message'} =~ s%$re%\n//%gs;
- return $h{'message'};
- }
- );
-
-
- #$logger->add_appender($appender);
-
- # don't write detailed logs unless we're already in debug mode
- $logger->remove_appender('FileLogger') unless $logger->is_debug();
- $logger->level($DEBUG);
-
- # Layouts
- my $layout =
- Log::Log4perl::Layout::PatternLayout->new(
- "// %d %p %F{1} %X{site} %X{rule} %m%n"
- );
- $appender->layout($layout);
-
+ my $appenderName = "Screen";
+ my $threshold = Kynetx::Configure::get_log_threshold();
+ my $level = Log::Log4perl::Level::to_priority($threshold);
+ my $appender = $Log::Log4perl::Logger::APPENDER_BY_NAME{$appenderName};
+ if (defined $appender) {
+ $appender->threshold($level);
+ }
}
sub turn_off_logging {
- my $logger = get_logger('Kynetx');
- # this is cheating. Removing an appender that doesn't exist
- # causes an error. This traps it
- eval {
- $logger->remove_appender('ConsoleLogger');
- }
+ my $appenderName = "Screen";
+ my $appender = $Log::Log4perl::Logger::APPENDER_BY_NAME{$appenderName};
+ if (defined $appender) {
+ $appender->threshold($OFF);
+ }
}
@@ -309,8 +301,11 @@ sub get_host {
my $hostname = '';
if (defined $url) {
my $parsed_url= URI->new($url );
- $hostname = $parsed_url->host()
+ if ($parsed_url) {
+ $hostname = $parsed_url->host()
if $parsed_url->scheme() eq 'http' || $parsed_url->scheme() eq 'https';
+ }
+
}
}
@@ -0,0 +1,50 @@
+##################################################
+package Log::Log4perl::ApacheStdErr;
+##################################################
+
+#use 5.006;
+use strict;
+#use warnings;
+
+use Log::Log4perl qw(:easy);
+
+sub TIEHANDLE {
+ my $class = shift;
+ bless [], $class;
+}
+
+sub PRINT {
+ my $self = shift;
+ no warnings;
+ my ($str) = @_;
+ if ($str =~ /^\[.+\]/) {
+ untie *STDERR;
+ print STDERR @_;
+ tie *STDERR, 'Log::Log4perl::ApacheStdErr';
+ }
+ eval {$str = join(" ", @_)};
+ if ($@) {
+ untie *STDERR;
+ print STDERR @_;
+ print STDERR $@;
+ tie *STDERR, 'Log::Log4perl::ApacheStdErr';
+ }
+ if ($str =~ /uninitialized/ ) {
+ $Log::Log4perl::caller_depth++;
+ TRACE @_;
+ $Log::Log4perl::caller_depth--;
+
+ } elsif ($str =~ /redefined/ ) {
+ $Log::Log4perl::caller_depth++;
+ TRACE @_;
+ $Log::Log4perl::caller_depth--;
+
+ } else {
+ $Log::Log4perl::caller_depth++;
+ DEBUG @_;
+ WARN $str;
+ $Log::Log4perl::caller_depth--;
+ }
+}
+
+1;
@@ -366,7 +366,7 @@ LogFormat "%h %t %{TOTAL_SECS}e %{METHOD}e %{RIDS}e %{TXN_ID}e \"%{CALLER}e\" %{
CustomLog "|/web/sbin/cronolog --period=<TMPL_VAR NAME=LOG_PERIOD> --symlink=/web/logs/cloud_log /web/logs/kynetx/CLOUD-%Y%m%d-%H%M.log" CLOUD env=CLOUD
# rule logging for OAUTH
-LogFormat "%h %t %{TOTAL_SECS}e %{METHOD}e %{RIDS}e %{TXN_ID}e \"%{CALLER}e\" %{SID}e \"%{REFERER}e\" \"%{TITLE}e\" [%{RULE_NAMES}e] [%{RESULTS}e] [%{ACTIONS}e] [%{TAGS}e] [%{LABELS}e] " OAUTH
+LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %{X-Forwarded-For}i %{METHOD}e" OAUTH
CustomLog "|/web/sbin/cronolog --period=<TMPL_VAR NAME=LOG_PERIOD> --symlink=/web/logs/oauth_log /web/logs/kynetx/OAUTH-%Y%m%d-%H%M.log" OAUTH env=OAUTH
ExtendedStatus On
View
@@ -84,6 +84,7 @@
#use Kynetx::Util ();
use Kynetx::Version ();
use Kynetx::Configure ();
+use Log::Dispatch::Email ();
# initialize Log4perl
@@ -94,6 +95,9 @@
# srand( time() ^ ($$ + ($$ <<15)) );
# configure KNS
+use Log::Log4perl::ApacheStdErr;
+
+tie *STDERR, "Log::Log4perl::ApacheStdErr";
Kynetx::Configure::configure();
1;
Oops, something went wrong.

0 comments on commit 77e9c02

Please sign in to comment.