diff --git a/config/openxpki/log.conf b/config/openxpki/log.conf index 451aed9e1e..dfad42ee8c 100644 --- a/config/openxpki/log.conf +++ b/config/openxpki/log.conf @@ -33,12 +33,18 @@ log4perl.category.openxpki.system = INFO, Logfile ## FACILITY: WORKFLOW # INTERNAL logger for the workflow engine, conditions evaluated, actions taken -# This must not be used by implementors, log you stuff to APPLICATION! +# This must not be used by implementors, log your stuff to APPLICATION! log4perl.category.openxpki.workflow = DEBUG, WorkflowLog ## FACILITY: APPLICATION # info about the workflows, conditions evaluated, actions taken -log4perl.category.openxpki.application = INFO, Logfile +log4perl.category.openxpki.application = INFO, Logfile, DBI + +## FACILITY: USAGE +# Poor-Mans statistcs tool to track usage of functions +# the log message should be a single token +log4perl.category.openxpki.usage = INFO, DBI + ## FACILITY: Connector (outside OXI!) # internal logging of the config layer, errors indicate missconfiguration diff --git a/config/sql/schema-mysql.sql b/config/sql/schema-mysql.sql index 6a87394413..deaa400c29 100644 --- a/config/sql/schema-mysql.sql +++ b/config/sql/schema-mysql.sql @@ -291,6 +291,25 @@ CREATE TABLE IF NOT EXISTS `workflow_history` ( KEY (`workflow_id`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8; +-- -------------------------------------------------------- + +-- +-- Table structure for table `application_log` +-- + +DROP TABLE IF EXISTS `application_log`; +CREATE TABLE IF NOT EXISTS `application_log` ( + `application_log_id` bigint(20) unsigned NOT NULL, + `logtimestamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, + `workflow_id` decimal(49,0) NOT NULL, + `priority` int(3) DEFAULT 999, + `category` varchar(255) NOT NULL, + `message` longtext, + PRIMARY KEY (`application_log_id`), + KEY (`workflow_id`), + KEY (`workflow_id`,`priority`) +) ENGINE=InnoDB DEFAULT CHARSET=utf8; + -- -------------------------------------------------------- @@ -423,6 +442,19 @@ CREATE TABLE IF NOT EXISTS `seq_workflow_history` ( PRIMARY KEY (`seq_number`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8; +-- -------------------------------------------------------- + +-- +-- Table structure for table `seq_application_log` +-- + +DROP TABLE IF EXISTS `seq_application_log`; +CREATE TABLE IF NOT EXISTS `seq_application_log` ( + `seq_number` bigint(20) UNSIGNED NOT NULL AUTO_INCREMENT, + `dummy` int(11) DEFAULT NULL, + PRIMARY KEY (`seq_number`) +) ENGINE=InnoDB DEFAULT CHARSET=utf8; + /*!40101 SET CHARACTER_SET_CLIENT=@OLD_CHARACTER_SET_CLIENT */; diff --git a/core/i18n/de_DE/openxpki.po b/core/i18n/de_DE/openxpki.po index 11f23361eb..2e4051e2a6 100644 --- a/core/i18n/de_DE/openxpki.po +++ b/core/i18n/de_DE/openxpki.po @@ -2440,6 +2440,26 @@ msgstr "Übergeordneter Workflow" msgid "I18N_OPENXPKI_UI_WORKFLOW_LAST_UPDATE_LABEL" msgstr "Untergeordnete Workflows" +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG" +msgstr "Übergeordneter Workflow" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_LABEL" +msgstr "Übergeordneter Workflow" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_MESSAGE_LABEL" +msgstr "Untergeordnete Workflows" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_PRIORITY_LABEL" +msgstr "Untergeordnete Workflows" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_TIMESTAMP_LABEL" +msgstr "Untergeordnete Workflows" + #, fuzzy msgid "I18N_OPENXPKI_UI_WORKFLOW_MOTD_FIELD_LEVEL_DESCRIPTION" msgstr "Export" @@ -7381,10 +7401,6 @@ msgstr "Benutzername" #~ msgid "I18N_OPENXPKI_UI_PROFILE_USER" #~ msgstr "Nutzer" -#, fuzzy -#~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION" -#~ msgstr "Übergeordneter Workflow" - #, fuzzy #~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION_AUTH_LDAP_ERR_DESC" #~ msgstr "Arbeitsabläufe" diff --git a/core/i18n/en_GB/openxpki.po b/core/i18n/en_GB/openxpki.po index c50b585060..7db9b9dcda 100644 --- a/core/i18n/en_GB/openxpki.po +++ b/core/i18n/en_GB/openxpki.po @@ -8,7 +8,7 @@ msgstr "" "Project-Id-Version: OpenXPKI 0.9\n" "Report-Msgid-Bugs-To: \n" "POT-Creation-Date: 2004-09-08 14:02+0200\n" -"PO-Revision-Date: 2016-04-25 11:26+0100\n" +"PO-Revision-Date: 2016-05-09 19:19+0100\n" "Last-Translator: OpenXPKI Team \n" "Language-Team: OpenXPKI developers list \n" @@ -1803,6 +1803,21 @@ msgstr "go back" msgid "I18N_OPENXPKI_UI_WORKFLOW_LAST_UPDATE_LABEL" msgstr "Last Update" +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG" +msgstr "Technical Log" + +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_LABEL" +msgstr "Technical Log" + +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_MESSAGE_LABEL" +msgstr "Message" + +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_PRIORITY_LABEL" +msgstr "Priority" + +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_TIMESTAMP_LABEL" +msgstr "Timestamp" + msgid "I18N_OPENXPKI_UI_WORKFLOW_MOTD_FIELD_LEVEL_DESCRIPTION" msgstr "" "The attention level of your message. This gets reflected in the color of the " @@ -2468,9 +2483,6 @@ msgstr "Yes" #~ msgid "I18N_OPENXPKI_UI_PROFILE_USER" #~ msgstr "User Certificate" -#~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION" -#~ msgstr "Action" - #, fuzzy #~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION_SCPERS_ADD_ESCROW_CERT_TO_PUBLISH_QUEUE_DESC" #~ msgstr "Publish CRL" diff --git a/core/i18n/it_IT/openxpki.po b/core/i18n/it_IT/openxpki.po index 9d25367e1e..e7d41cc525 100644 --- a/core/i18n/it_IT/openxpki.po +++ b/core/i18n/it_IT/openxpki.po @@ -1911,6 +1911,26 @@ msgstr "torna indietro" msgid "I18N_OPENXPKI_UI_WORKFLOW_LAST_UPDATE_LABEL" msgstr "Ultimo Aggiornamento" +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG" +msgstr "Action" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_LABEL" +msgstr "Workflow Id" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_MESSAGE_LABEL" +msgstr "Link" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_PRIORITY_LABEL" +msgstr "Workflow History" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_TIMESTAMP_LABEL" +msgstr "Contesto Workflow" + msgid "I18N_OPENXPKI_UI_WORKFLOW_MOTD_FIELD_LEVEL_DESCRIPTION" msgstr "" "Il livello di attenzione del tuo messaggio. Viene riflesso nel colore del " @@ -2569,9 +2589,6 @@ msgstr "Chiave" #~ msgid "I18N_OPENXPKI_UI_PROFILE_USER" #~ msgstr "User Certificate" -#~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION" -#~ msgstr "Action" - #, fuzzy #~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION_SCPERS_ADD_ESCROW_CERT_TO_PUBLISH_QUEUE_DESC" #~ msgstr "Publish CRL" diff --git a/core/i18n/ru_RU/openxpki.po b/core/i18n/ru_RU/openxpki.po index 2e9eeaf403..da41fdbdfd 100644 --- a/core/i18n/ru_RU/openxpki.po +++ b/core/i18n/ru_RU/openxpki.po @@ -2436,6 +2436,26 @@ msgstr "Родительский технологический процесс" msgid "I18N_OPENXPKI_UI_WORKFLOW_LAST_UPDATE_LABEL" msgstr "Дочерние технологические процессы" +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG" +msgstr "Родительский технологический процесс" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_LABEL" +msgstr "Родительский технологический процесс" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_MESSAGE_LABEL" +msgstr "Дочерние технологические процессы" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_PRIORITY_LABEL" +msgstr "Дочерние технологические процессы" + +#, fuzzy +msgid "I18N_OPENXPKI_UI_WORKFLOW_LOG_TIMESTAMP_LABEL" +msgstr "Дочерние технологические процессы" + #, fuzzy msgid "I18N_OPENXPKI_UI_WORKFLOW_MOTD_FIELD_LEVEL_DESCRIPTION" msgstr "Экспорт" @@ -7593,10 +7613,6 @@ msgstr "Имя учетной записи" #~ msgid "I18N_OPENXPKI_UI_PROFILE_USER" #~ msgstr "Профиль пользователя" -#, fuzzy -#~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION" -#~ msgstr "Родительский технологический процесс" - #, fuzzy #~ msgid "I18N_OPENXPKI_UI_WORKFLOW_ACTION_AUTH_LDAP_ERR_DESC" #~ msgstr "Технологические процессы" diff --git a/core/server/OpenXPKI/Client/UI/Workflow.pm b/core/server/OpenXPKI/Client/UI/Workflow.pm index 903633fd56..d3b9d714df 100644 --- a/core/server/OpenXPKI/Client/UI/Workflow.pm +++ b/core/server/OpenXPKI/Client/UI/Workflow.pm @@ -734,6 +734,54 @@ sub init_task { } + +=head2 init_log + +Load and display the technical log file of the workflow + +=cut + +sub init_log { + + my $self = shift; + my $args = shift; + + my $wf_id = $self->param('wf_id'); + + $self->_page({ + label => 'I18N_OPENXPKI_UI_WORKFLOW_LOG' + }); + + my $result = $self->send_command( 'get_workflow_log', { ID => $wf_id } ); + + $self->logger()->trace( "dumper result: " . Dumper $result); + + $self->add_section({ + type => 'grid', + className => 'workflow', + content => { + columns => [ + { sTitle => 'I18N_OPENXPKI_UI_WORKFLOW_LOG_TIMESTAMP_LABEL'}, + { sTitle => 'I18N_OPENXPKI_UI_WORKFLOW_LOG_PRIORITY_LABEL'}, + { sTitle => 'I18N_OPENXPKI_UI_WORKFLOW_LOG_MESSAGE_LABEL'}, + ], + data => $result, + empty => 'I18N_OPENXPKI_UI_TASK_LIST_EMPTY_LABEL', + } + }); + + $self->add_section({ + type => 'text', + content => { + buttons => [{ + 'action' => 'redirect!workflow!load!wf_id!'.$wf_id, + 'label' => 'I18N_OPENXPKI_UI_WORKFLOW_OPEN_WORKFLOW_LABEL', #'open workflow', + }] + } + }); + +} + =head2 action_index =head3 instance creation @@ -1568,6 +1616,11 @@ sub __render_from_workflow { 'action' => 'redirect!workflow!history!wf_id!'.$wf_info->{WORKFLOW}->{ID}, 'label' => 'I18N_OPENXPKI_UI_WORKFLOW_HISTORY_LABEL', }; + + push @buttons, { + 'page' => 'redirect!workflow!log!wf_id!'.$wf_info->{WORKFLOW}->{ID}, + 'label' => 'I18N_OPENXPKI_UI_WORKFLOW_LOG_LABEL', + }; # The workflow info contains info about all control actions that # can done on the workflow -> render appropriate buttons. diff --git a/core/server/OpenXPKI/Server/API.pm b/core/server/OpenXPKI/Server/API.pm index 706a220f26..ad7a14eaec 100644 --- a/core/server/OpenXPKI/Server/API.pm +++ b/core/server/OpenXPKI/Server/API.pm @@ -30,6 +30,7 @@ use OpenXPKI::Server::API::Profile; use OpenXPKI::Server::API::Secret; use OpenXPKI::Server::API::Token; use OpenXPKI::Server::API::Visualization; +use OpenXPKI::Server::API::Housekeeping; use OpenXPKI::Server::API::Workflow; use OpenXPKI::Server::API::Smartcard; use OpenXPKI::Server::API::UI; @@ -1132,6 +1133,17 @@ sub BUILD { }, }, + ### Housekeeping API + 'purge_application_log' => { + class => 'Housekeeping', + params => { + MAXAGE => { + type => SCALAR, + regex => $re_integer_string, + }, + }, + }, + ### Workflow API 'get_workflow_instance_types' => { class => 'Workflow', @@ -1186,6 +1198,25 @@ sub BUILD { }, }, }, + 'get_workflow_log' => { + class => 'Workflow', + params => { + ID => { + type => SCALAR, + regex => $re_integer_string, + }, + REVERSE => { + type => SCALAR, + optional => 1, + regex => $re_boolean, + }, + LIMIT => { + type => SCALAR, + optional => 1, + regex => $re_integer_string, + }, + }, + }, 'get_workflow_history' => { class => 'Workflow', params => { diff --git a/core/server/OpenXPKI/Server/API/Housekeeping.pm b/core/server/OpenXPKI/Server/API/Housekeeping.pm new file mode 100644 index 0000000000..a054c64d18 --- /dev/null +++ b/core/server/OpenXPKI/Server/API/Housekeeping.pm @@ -0,0 +1,105 @@ +## OpenXPKI::Server::API::Housekeeping.pm +## +## Written 2016 by Scott Hardin for the OpenXPKI project +## +## Based on work by Michael Bell and Martin Bartosch +## Copyright (C) 2005-2016 by The OpenXPKI Project + +package OpenXPKI::Server::API::Housekeeping; + +use strict; +use warnings; +use utf8; +use English; +use Class::Std; + +use OpenXPKI::Server::Context qw( CTX ); + +sub START { + # somebody tried to instantiate us, but we are just an + # utility class with static methods + OpenXPKI::Exception->throw( + message => 'I18N_OPENXPKI_SERVER_API_SUBCLASSES_CAN_NOT_BE_INSTANTIATED', + ); +} + +sub get_utc_time { + my $t = shift || time; + my ($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = + gmtime($t); + $year += 1900; + $mon++; + my $time; + my $microseconds = 0; + eval { # if Time::HiRes is available, use it to get microseconds + use Time::HiRes qw( gettimeofday ); + my ($seconds, $micro) = gettimeofday(); + $microseconds = $micro; + }; + $time = sprintf("%04d%02d%02d%02d%02d%02d%06d", $year, $mon, $mday, $hour, $min, $sec, $microseconds); + + return $time; +} + +sub purge_application_log { + my $self = shift; + my $args = shift; + + ##! 1: "purge_application_log" + + my $maxage = 60*60*24*180; # 180 days + if ( $args->{MAXAGE} ) { + $maxage = $args->{MAXAGE}; + } + my $maxutc = get_utc_time( time - $maxage ); + + my $result = CTX('dbi_backend')->delete( + TABLE => 'APPLICATION_LOG', + DATA => { TIMESTAMP => [ "<", $maxutc ], }, + ); + CTX('dbi_backend')->commit(); + return $result; +} + +1; + +__END__ + +=head1 Name + +OpenXPKI::Server::API::Housekeeping + +=head1 Description + +This is the housekeeping interface which should be used by all user interfaces of OpenXPKI. +A user interface MUST NOT access the server directly. The only allowed +access is via this API. Any function which is not available in this API is +not for public use. +The API gets access to the server via the 'server' context object. This +object must be set before instantiating the API. + +=head1 Functions + +=head2 new + +Default constructor created by Class::Std. + +=head2 purge_application_log + +Purges old records from the application_log table. + +Named parameters: + +=over + +=item * MAXAGE + +The maximum age (in seconds) of the application log entries to preserve. +[default: 1 year (60*60*24*365)] + +=back + +Examples: + + $api->purge_application_log( { MAXAGE => 60*60*24*180 } ); + diff --git a/core/server/OpenXPKI/Server/API/Workflow.pm b/core/server/OpenXPKI/Server/API/Workflow.pm index 51332062fe..c05f39c0e7 100644 --- a/core/server/OpenXPKI/Server/API/Workflow.pm +++ b/core/server/OpenXPKI/Server/API/Workflow.pm @@ -70,6 +70,78 @@ sub get_workflow_type_for_id { return $type; } + +=head2 get_workflow_log + +Return the workflow log for a given workflow id (ID), by default you get +the last 50 items of the log sorted neweset first. Set LIMIT to the number +of lines expected or 0 to get all lines (might be huge!). Set REVERSE = 1 +to reverse sorting (oldest first). + +The return value is a list of arrays with a fixed order of fields: +TIMESTAMP, PRIORITY, MESSAGE + +=over + +=item ID numeric workflow id + +=item LIMIT number of lines to return, 0 for all + +=item REVERSE set to 1 to reverse sorting + +=back + +=cut + +sub get_workflow_log { + + my $self = shift; + my $args = shift; + + ##! 1: "get_workflow_log" + + my $wf_id = $args->{ID}; + + my $limit = 50; + if (defined $args->{LIMIT}) { + $limit = $args->{LIMIT}; + } + + # we want to track the usage + CTX('log')->usage()->info("get_workflow_log"); + + # Reverse is inverted as we want to have reversed order by default + my $reverse = 1; + if ($args->{REVERSE}) { + $reverse = 0; + } + + my $result = CTX('dbi_workflow')->select( + TABLE => 'APPLICATION_LOG', + DYNAMIC => { + WORKFLOW_SERIAL => { VALUE => $wf_id }, + }, + ORDER => [ 'TIMESTAMP', 'APPLICATION_LOG_SERIAL' ], + REVERSE => $reverse, + LIMIT => $limit + ); + + my @log; + while (my $line = shift @{$result}) { + push @log, [ $line->{TIMESTAMP}, $line->{PRIORITY}, $line->{MESSAGE} ]; + } + + return \@log; + +} + + +=head2 get_workflow_info + +This is a simple passthru to __get_workflow_ui_info + +=cut + sub get_workflow_info { my $self = shift; my $args = shift; @@ -416,7 +488,7 @@ sub wakeup_workflow { $wf_title, $wf_id ); - + my $proc_state = $workflow->proc_state(); if (!($proc_state eq 'pause' || $proc_state eq 'retry_exceeded')) { OpenXPKI::Exception->throw( @@ -552,6 +624,12 @@ sub create_workflow_instance { # workflow acl fails when the first non-initial action is autorun $workflow->attrib({ creator => $creator }); + OpenXPKI::Server::Context::setcontext( + { + workflow_id => $wf_id, + force => 1, + }); + ##! 16: 'workflow id ' . $wf_id CTX('log')->log( MESSAGE => "Workflow instance $wf_id created for $creator (type: '$wf_title')", @@ -956,6 +1034,11 @@ sub __get_workflow_factory { ); } + OpenXPKI::Server::Context::setcontext( + { + workflow_id => $arg_ref->{WORKFLOW_ID}, + force => 1, + }); # We have now obtained the configuration id that was active during # creation of the workflow instance. However, if for some reason diff --git a/core/server/OpenXPKI/Server/Context.pm b/core/server/OpenXPKI/Server/Context.pm index 0c80695faa..830f8f9e61 100644 --- a/core/server/OpenXPKI/Server/Context.pm +++ b/core/server/OpenXPKI/Server/Context.pm @@ -43,6 +43,7 @@ my $context = { session => undef, authentication => undef, notification => undef, + workflow_id => undef, }, }; diff --git a/core/server/OpenXPKI/Server/DBI/Driver.pm b/core/server/OpenXPKI/Server/DBI/Driver.pm index fd65022ab4..f540d2bd59 100644 --- a/core/server/OpenXPKI/Server/DBI/Driver.pm +++ b/core/server/OpenXPKI/Server/DBI/Driver.pm @@ -96,6 +96,8 @@ our %COLUMN = ( "message" => "TEXT", "category" => "TEXT_KEY", "loglevel" => "TEXT_KEY", + "priority" => "NUMERIC", + "application_log_id" => "BIGINT", "keyid" => "TEXT_KEY", "ca_issuer_name" => "TEXT_KEY", diff --git a/core/server/OpenXPKI/Server/DBI/Schema.pm b/core/server/OpenXPKI/Server/DBI/Schema.pm index 82ec6584f6..3037e4b655 100644 --- a/core/server/OpenXPKI/Server/DBI/Schema.pm +++ b/core/server/OpenXPKI/Server/DBI/Schema.pm @@ -23,6 +23,7 @@ my %SEQUENCE_of = ( DATAEXCHANGE => "seq_dataexchange", WORKFLOW => "seq_workflow", WORKFLOW_HISTORY => "seq_workflow_history", + APPLICATION_LOG => "seq_application_log", ); my %COLUMN_of = ( @@ -59,6 +60,7 @@ my %COLUMN_of = ( CRR_SERIAL => "crr_key", CRL_SERIAL => "crl_key", AUDITTRAIL_SERIAL => "audittrail_key", + APPLICATION_LOG_SERIAL => "application_log_id", DATA_SERIAL => "data_key", PRIVATE_SERIAL => "private_key", SIGNATURE_SERIAL => "signature_key", @@ -69,7 +71,7 @@ my %COLUMN_of = ( WORKFLOW_HISTORY_SERIAL => "workflow_hist_id", GROUP_ID => "group_id", PART_ID => "part_id", - + ATTRIBUTE_SERIAL => 'attribute_key', ATTRIBUTE_KEY => 'attribute_contentkey', ATTRIBUTE_VALUE => 'attribute_value', @@ -102,6 +104,7 @@ my %COLUMN_of = ( MESSAGE => "message", CATEGORY => "category", LOGLEVEL => "loglevel", + PRIORITY => "priority", KEYID => "keyid", CA_ISSUER_NAME => "ca_issuer_name", @@ -233,6 +236,15 @@ my %TABLE_of = ( "CATEGORY", "LOGLEVEL", "MESSAGE" ], KEY => "AUDITTRAIL_SERIAL" }, + APPLICATION_LOG => { + NAME => "application_log", + INDEX => [ "APPLICATION_LOG_SERIAL" ], + COLUMNS => [ "APPLICATION_LOG_SERIAL", + "TIMESTAMP", + "WORKFLOW_SERIAL", + "CATEGORY", "PRIORITY", "MESSAGE" ], + KEY => "APPLICATION_LOG_SERIAL" + }, SECRET => { NAME => "secret", diff --git a/core/server/OpenXPKI/Server/Log.pm b/core/server/OpenXPKI/Server/Log.pm index 60ec1e893a..6e23dfc627 100644 --- a/core/server/OpenXPKI/Server/Log.pm +++ b/core/server/OpenXPKI/Server/Log.pm @@ -61,12 +61,19 @@ sub init { } ## ensure that all relevant loggers are present - foreach my $facility ("auth", "audit", "monitor", "system", "workflow", "application" ) + foreach my $facility ("auth", "audit", "monitor", "system", "workflow", "application", "usage" ) { ## get the relevant logger $self->{$facility} = Log::Log4perl->get_logger("openxpki.$facility"); if (not $self->{$facility}) { + # backwards compatibility + if ($facility eq "usage") { + $self->{'usage'} = $self->{'monitor'}; + $self->{'system'}->warn("Log facility 'usage' is missing - falling back to monitor"); + return 1; + } + OpenXPKI::Exception->throw ( message => "I18N_OPENXPKI_SERVER_LOG_NEW_MISSING_LOGGER", params => {"FACILITY" => $facility}); @@ -82,6 +89,14 @@ sub re_init { return $self->init(); } +# todo - if this PoC is valuable, we should change all logger calls +sub usage { + + my $self = shift; + return $self->{'usage'}; + +} + sub log { my $self = shift; @@ -112,7 +127,7 @@ sub log $facility = lc($keys->{FACILITY}) if (exists $keys->{FACILITY} and - $keys->{FACILITY} =~ m{ \A (?:auth|audit|monitor|system|workflow|application) \z }xms); + $keys->{FACILITY} =~ m{ \A (?:auth|audit|monitor|system|workflow|application|usage) \z }xms); $prio = uc($keys->{PRIORITY}) if (exists $keys->{PRIORITY} and @@ -156,6 +171,12 @@ sub log }; } + # get workflow instance information + my $wf_id; + if (OpenXPKI::Server::Context::hascontext('workflow_id')) { + $wf_id = CTX('workflow_id'); + } + ## build and store message $msg = "[$package" . " (" @@ -163,6 +184,7 @@ sub log . "$line)" . (defined $user ? '; ' . $user . $role : '') . (defined $session_short ? '@' . $session_short : '') + . (defined $wf_id ? '#' . $wf_id : '') . "] $msg"; # remove trailing newline characters diff --git a/core/server/OpenXPKI/Server/Log/Appender/DBI.pm b/core/server/OpenXPKI/Server/Log/Appender/DBI.pm index c46b1d213d..1053cdd2f8 100644 --- a/core/server/OpenXPKI/Server/Log/Appender/DBI.pm +++ b/core/server/OpenXPKI/Server/Log/Appender/DBI.pm @@ -11,6 +11,20 @@ use OpenXPKI::Debug; use OpenXPKI::Server::Context qw( CTX ); use Data::Dumper; use English; +use Log::Log4perl::Level; +use Carp; + +my %LOGLEVELS = ( + ALL => 0, + TRACE => 5000, + DEBUG => 10000, + INFO => 20000, + WARN => 30000, + ERROR => 40000, + FATAL => 50000, + OFF => (2 ** 31) - 1, +); + sub new { ##! 1: 'start' @@ -50,35 +64,79 @@ sub log { return; } - my $serial; - eval { - $serial = $dbi->get_new_serial( + # TODO: If category IS '*.audit', write to the audittrail. Otherwise, + # write to application_log and also put workflow_id into its + # own column instead of in the message. + if ( $category =~ m{\.audit$} ) { + my $serial; + eval { + $serial = $dbi->get_new_serial( + TABLE => 'AUDITTRAIL', + ); + ##! 64: 'serial: ' . $serial + }; + if (my $exc = OpenXPKI::Exception->caught()) { + ##! 16: 'exception caught' + if ($exc->message() eq 'I18N_OPENXPKI_SERVER_DBI_DBH_DO_QUERY_NOT_CONNECTED') { + ##! 16: 'dbi_log not connected' + print STDERR "dbi_log not connected! (tried to log: $timestamp, $category, $loglevel, $message)\n"; + return; + } + else { + $exc->rethrow(); + } + } + $dbi->insert( TABLE => 'AUDITTRAIL', + HASH => { + AUDITTRAIL_SERIAL => $serial, + TIMESTAMP => $timestamp, + CATEGORY => $category, + LOGLEVEL => $loglevel, + MESSAGE => $message, + }, ); - ##! 64: 'serial: ' . $serial - }; - if (my $exc = OpenXPKI::Exception->caught()) { - ##! 16: 'exception caught' - if ($exc->message() eq 'I18N_OPENXPKI_SERVER_DBI_DBH_DO_QUERY_NOT_CONNECTED') { - ##! 16: 'dbi_log not connected' - print STDERR "dbi_log not connected! (tried to log: $timestamp, $category, $loglevel, $message)\n"; - return; + } else { + my $serial; + my $wf_id = 0; + if (OpenXPKI::Server::Context::hascontext('workflow_id')) { + $wf_id = CTX('workflow_id'); + } + eval { + $serial = $dbi->get_new_serial( + TABLE => 'APPLICATION_LOG', + ); + ##! 64: 'serial: ' . $serial + }; + if (my $exc = OpenXPKI::Exception->caught()) { + ##! 16: 'exception caught' + if ($exc->message() eq 'I18N_OPENXPKI_SERVER_DBI_DBH_DO_QUERY_NOT_CONNECTED') { + ##! 16: 'dbi_log not connected' + print STDERR "dbi_log not connected! (tried to log: $timestamp, $category, $loglevel, $wf_id, $message)\n"; + return; + } + else { + $exc->rethrow(); + } } - else { - $exc->rethrow(); + my $loglevel_int = 0; + if ( exists $LOGLEVELS{$loglevel} ) { + $loglevel_int = $LOGLEVELS{$loglevel}; } + + $dbi->insert( + TABLE => 'APPLICATION_LOG', + HASH => { + APPLICATION_LOG_SERIAL => $serial, + TIMESTAMP => $timestamp, + WORKFLOW_SERIAL => $wf_id, + CATEGORY => $category, + PRIORITY => $loglevel_int, + MESSAGE => $message, + }, + ); } - $dbi->insert( - TABLE => 'AUDITTRAIL', - HASH => { - AUDITTRAIL_SERIAL => $serial, - TIMESTAMP => $timestamp, - CATEGORY => $category, - LOGLEVEL => $loglevel, - MESSAGE => $message, - }, - ); $dbi->commit(); ##! 1: 'end' diff --git a/core/server/t/30_dbi/01.t b/core/server/t/30_dbi/01.t index a49108f973..5d45bd4c1b 100644 --- a/core/server/t/30_dbi/01.t +++ b/core/server/t/30_dbi/01.t @@ -8,8 +8,6 @@ diag "OpenXPKI::Server::DBI: Database Initialization\n" if $ENV{VERBOSE}; use_ok('OpenXPKI::Server::DBI', 'Using OpenXPKI::Server::DBI'); -TODO: { - todo_skip 'See Issue #188', 8; our %config; our $dbi; require 't/30_dbi/common.pl'; @@ -28,5 +26,4 @@ if ($ENV{DEBUG}) { $sqlscript = eval { $dbi->init_schema (MODE => 'FORCE') }; ok(! $EVAL_ERROR, 'init_schema') or diag $EVAL_ERROR; -} 1; diff --git a/core/server/t/30_dbi/04_quoting_bug.t b/core/server/t/30_dbi/04_quoting_bug.t index c7f7dcc947..ea79df9732 100644 --- a/core/server/t/30_dbi/04_quoting_bug.t +++ b/core/server/t/30_dbi/04_quoting_bug.t @@ -1,7 +1,7 @@ use strict; use warnings; use Test::More; -plan tests => 3; +plan tests => 7; diag "OpenXPKI::Server::DBI: Quoting bug\n" if $ENV{VERBOSE}; @@ -11,8 +11,8 @@ use OpenXPKI::Crypto::CRL; use Data::Dumper; -TODO: { - todo_skip 'See Issue #188', 3; +#TODO: { +# todo_skip 'See Issue #188', 3; our $dbi; our $token; require 't/30_dbi/common.pl'; @@ -41,7 +41,7 @@ is(scalar @{$result}, 1, 'one entry returned (equal)'); TODO: { - local $TODO = 'MySQL seems to have a problem with quoting, see #1951540'; + todo_skip 'MySQL seems to have a problem with quoting, see #1951540', 1; my $result = $dbi->select( TABLE => 'CERTIFICATE', DYNAMIC => @@ -52,5 +52,5 @@ TODO: { is(scalar @{$result}, 1, 'one entry returned'); } -} +#} 1; diff --git a/core/server/t/30_dbi/30_log.t b/core/server/t/30_dbi/30_log.t index e276402430..b9e8dbe39a 100644 --- a/core/server/t/30_dbi/30_log.t +++ b/core/server/t/30_dbi/30_log.t @@ -2,15 +2,14 @@ use strict; use warnings; use English; use Test::More; -plan tests => 6; + +plan tests => 41; use OpenXPKI::Debug; if ($ENV{DEBUG_LEVEL}) { $OpenXPKI::Debug::LEVEL{'.*'} = $ENV{DEBUG_LEVEL}; } -TODO: { - todo_skip 'See Issue #188', 6; our $dbi; our $token; @@ -20,13 +19,13 @@ use OpenXPKI::Server::Context; use OpenXPKI::Server::Log; OpenXPKI::Server::Context::setcontext({ - dbi_log => $dbi + dbi_log => $dbi, + dbi_backend => $dbi }); -my $log = OpenXPKI::Server::Log->new( CONFIG => 't/28_log/log4perl.conf' ); +my $log = OpenXPKI::Server::Log->new( CONFIG => 't/30_dbi/log4perl.conf' ); my $msg = sprintf "DBI Log Test %01d", rand(10000000); -# Workflow errors go to DBI ok ($log->log (FACILITY => "audit", PRIORITY => "info", MESSAGE => $msg), 'Test message'); @@ -41,5 +40,58 @@ ok ($log->log (FACILITY => "audit", ); is(scalar @{$result}, 1, 'Log entry found'); +$msg = sprintf "DBI Log Workflow Test %01d", rand(10000000); +OpenXPKI::Server::Context::setcontext({ + workflow_id => 12345 +}); + +ok ($log->log (FACILITY => "application", + PRIORITY => "info", + MESSAGE => $msg), 'Workflow Test message') + or diag "ERROR: log=$log"; + +$result = $dbi->select( + TABLE => 'APPLICATION_LOG', + DYNAMIC => + { + CATEGORY => {VALUE => 'openxpki.application' }, + MESSAGE => {VALUE => "%$msg", OPERATOR => 'LIKE'}, + } +); +is(scalar @{$result}, 1, 'Log entry found'); +is($result->[0]->{WORKFLOW_SERIAL}, 12345, "Check that workflow id was set"); +isnt($result->[0]->{TIMESTAMP}, undef, "Check that timestamp was set"); +is($result->[0]->{PRIORITY}, 20000, "Check that the priority 'info' is saved as 20000"); + +my %levels = ( + 'fatal' => 50000, + 'error' => 40000, + 'warn' => 30000, + 'info' => 20000, + 'debug' => 10000, + 'bogus' => 50000, +); + +foreach my $level ( sort keys %levels ) { + # Check via our DBI.pm code + $msg = sprintf "DBI Log Workflow Test %01d", rand(10000000); + ok ($log->log (FACILITY => "application", + PRIORITY => $level, + MESSAGE => $msg), '[' . $level . '] Workflow Test message') + or diag "ERROR: log=$log ($@)"; + + $result = $dbi->select( + TABLE => 'APPLICATION_LOG', + DYNAMIC => + { + CATEGORY => {VALUE => 'openxpki.application' }, + MESSAGE => {VALUE => "%$msg", OPERATOR => 'LIKE'}, + } + ); + is(scalar @{$result}, 1, '[' . $level . '] Log entry found'); + is($result->[0]->{WORKFLOW_SERIAL}, 12345, "[$level] Check that workflow id was set"); + isnt($result->[0]->{TIMESTAMP}, undef, "[$level] Check that timestamp was set"); + is($result->[0]->{PRIORITY}, $levels{$level}, "[$level] Check the priority value"); } + 1; diff --git a/core/server/t/30_dbi/31_purge_applog.t b/core/server/t/30_dbi/31_purge_applog.t new file mode 100644 index 0000000000..cb820c13ec --- /dev/null +++ b/core/server/t/30_dbi/31_purge_applog.t @@ -0,0 +1,128 @@ +use strict; +use warnings; +use English; +use Test::More; + +plan tests => 15; + +my $maxage = 60*60*24; # 1 day + +sub get_utc_time { + my $t = shift || time; + my ($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = + gmtime($t); + $year += 1900; + $mon++; + my $time; + my $microseconds = 0; + eval { # if Time::HiRes is available, use it to get microseconds + use Time::HiRes qw( gettimeofday ); + my ($seconds, $micro) = gettimeofday(); + $microseconds = $micro; + }; + $time = sprintf("%04d%02d%02d%02d%02d%02d%06d", $year, $mon, $mday, $hour, $min, $sec, $microseconds); + + return $time; +} + +use OpenXPKI::Debug; +if ($ENV{DEBUG_LEVEL}) { + $OpenXPKI::Debug::LEVEL{'.*'} = $ENV{DEBUG_LEVEL}; +} + + +our $dbi; +our $token; +require 't/30_dbi/common.pl'; + +use OpenXPKI::Server::Context; +use OpenXPKI::Server::Log; + +OpenXPKI::Server::Context::setcontext({ + dbi_log => $dbi, + dbi_backend => $dbi +}); +my $log = OpenXPKI::Server::Log->new( CONFIG => 't/30_dbi/log4perl.conf' ); + +my $wf_id = int(rand(10000000)); +my $msg = sprintf "DBI Log Workflow Test %01d", rand(10000000); +OpenXPKI::Server::Context::setcontext({ + workflow_id => $wf_id +}); + +ok ($log->log (FACILITY => "application", + PRIORITY => "info", + MESSAGE => $msg), 'Workflow Test message') + or diag "ERROR: log=$log"; + +my $result = $dbi->select( + TABLE => 'APPLICATION_LOG', + DYNAMIC => + { + CATEGORY => {VALUE => 'openxpki.application' }, + MESSAGE => {VALUE => "%$msg", OPERATOR => 'LIKE'}, + } +); +is(scalar @{$result}, 1, "Log entry found: $msg"); + +my $serial = $dbi->get_new_serial(TABLE => 'APPLICATION_LOG'); +$msg = sprintf "DBI Log Workflow Test Old %01d", rand(10000000); +my $timestamp = get_utc_time( time - $maxage + 5); +#diag "WFID=$wf_id, TS=$timestamp, SER=$serial, MSG=$msg"; +isnt($serial, 0, 'serial for test entry not zero') or die "Error: unable to continue without serial"; +ok($dbi->insert( + TABLE => 'APPLICATION_LOG', + HASH => { + APPLICATION_LOG_SERIAL => $serial, + TIMESTAMP => $timestamp, + WORKFLOW_SERIAL => $wf_id, + CATEGORY => 'openxpki.application', + PRIORITY => 'info', + MESSAGE => $msg, + }, + ), "insert old test message"); +ok($dbi->commit(), "Commit insert of old test message"); + +$serial = $dbi->get_new_serial(TABLE => 'APPLICATION_LOG'); +$msg = sprintf "DBI Log Workflow Test Old %01d", rand(10000000); +$timestamp = get_utc_time( time - $maxage - 5); +#diag "WFID=$wf_id, TS=$timestamp, SER=$serial, MSG=$msg"; +isnt($serial, 0, 'serial for test entry not zero') or die "Error: unable to continue without serial"; +ok($dbi->insert( + TABLE => 'APPLICATION_LOG', + HASH => { + APPLICATION_LOG_SERIAL => $serial, + TIMESTAMP => $timestamp, + WORKFLOW_SERIAL => $wf_id, + CATEGORY => 'openxpki.application', + PRIORITY => 'info', + MESSAGE => $msg, + }, + ), "insert old test message"); +ok($dbi->commit(), "Commit insert of old test message"); + +$result = $dbi->select( + TABLE => 'APPLICATION_LOG', + DYNAMIC => + { + CATEGORY => {VALUE => 'openxpki.application' }, + WORKFLOW_SERIAL => {VALUE => $wf_id, OPERATOR => 'EQUAL'}, + } +); +is(scalar @{$result}, 3, "Log entries found for WFID $wf_id"); + +# CALL API TO PURGE RECORDS +my $maxutc = get_utc_time( time - $maxage ); +ok(CTX('api')->purge_application_log( { MAXAGE => $maxage } ), "exec purge_application_log for $maxutc"); + +$result = $dbi->select( + TABLE => 'APPLICATION_LOG', + DYNAMIC => + { + CATEGORY => {VALUE => 'openxpki.application' }, + WORKFLOW_SERIAL => {VALUE => $wf_id, OPERATOR => 'EQUAL'}, + } +); +is(scalar @{$result}, 2, "2 log entries found for WFID $wf_id after purge"); + +1; diff --git a/core/server/t/30_dbi/common.pl b/core/server/t/30_dbi/common.pl index fdf4738194..a70015ac53 100644 --- a/core/server/t/30_dbi/common.pl +++ b/core/server/t/30_dbi/common.pl @@ -33,7 +33,7 @@ my %params = (LOG => $log); my $db_config = $config->get_hash('system.database.main'); -foreach my $key qw(type name namespace host port user passwd) { +foreach my $key ( qw(type name namespace host port user passwd) ) { ##! 16: "dbi: $key => " . $db_config->{$key} $params{uc($key)} = $db_config->{$key}; } diff --git a/core/server/t/30_dbi/log4perl.conf b/core/server/t/30_dbi/log4perl.conf new file mode 100644 index 0000000000..53f7506346 --- /dev/null +++ b/core/server/t/30_dbi/log4perl.conf @@ -0,0 +1,39 @@ +# Sample Log4Perl Config + +# Catch-all root logger +log4perl.rootLogger = ERROR, Logfile + +## FACILITY: AUTH +log4perl.category.openxpki.auth = INFO, Logfile, DBI + +## FACILITY: AUDIT +log4perl.category.openxpki.audit = INFO, Logfile, DBI + +## FACILITY: MONITOR +log4perl.category.openxpki.monitor = INFO, Logfile, DBI + +## FACILITY: SYSTEM +log4perl.category.openxpki.system = DEBUG, Logfile, DBI + +## FACILITY: WORKFLOW +log4perl.category.openxpki.workflow = INFO, Logfile, DBI + +## FACILITY: APPLICATION +log4perl.category.openxpki.application = DEBUG, Logfile, DBI + +## FACILITY: Connector (outside OXI!) +log4perl.category.connector = DEBUG, Connector + +log4perl.appender.Logfile = Log::Log4perl::Appender::File +log4perl.appender.Logfile.filename = t/var/openxpki/openxpki.log +log4perl.appender.Logfile.layout = Log::Log4perl::Layout::PatternLayout +log4perl.appender.Logfile.layout.ConversionPattern = %d %c.%p %m%n + +log4perl.appender.Connector = Log::Log4perl::Appender::File +log4perl.appender.Connector.filename = t/var/openxpki/connector.log +log4perl.appender.Connector.layout = Log::Log4perl::Layout::PatternLayout +log4perl.appender.Connector.layout.ConversionPattern = %d %c.%p %m%n + +log4perl.appender.DBI = OpenXPKI::Server::Log::Appender::DBI +log4perl.appender.DBI.layout = Log::Log4perl::Layout::NoopLayout +log4perl.appender.DBI.warp_message = 0