[interchange/gateway_log: 1/11] Vend::Payment::GatewayLog
Mark Johnson <[email protected]> Sat, 04 Nov 2017 18:05:14 +0000
| Newsgroups | gmane.comp.web.interchange.cvs |
|---|---|
| Message-ID | <[email protected]> |
commit c36681872e7333c15954b797c3990e8d51a952e5 Author: Mark Johnson <[email protected]> Date: Mon Sep 7 22:25:21 2009 -0400 Vend::Payment::GatewayLog * New module facilitates adding logging support for all transactions through any of the standard gateway modules. * Introduce logging support to Vend::Payment::PayflowPro. * Fully sever database connections in Vend::Payment when global timeout is invoked. Code operating in production proved to behave unpredictably when parent and child shared the same database server. * Add gateway_log table to standard in expected format for each DBI database type. * Adjusted Vend::Table::DBI to support SQLite's AUTOINCREMENT in parallel to same support of MySQL's feature. dist/standard/dbconf/mysql/gateway_log.mysql | 16 ++ dist/standard/dbconf/pgsql/gateway_log.pgsql | 11 + dist/standard/dbconf/sqlite/gateway_log.lite | 16 ++ dist/standard/products/gateway_log.txt | 1 + lib/Vend/Payment.pm | 47 +++-- lib/Vend/Payment/GatewayLog.pm | 296 ++++++++++++++++++++++++++ lib/Vend/Payment/PayflowPro.pm | 130 ++++++++++- lib/Vend/Table/DBI.pm | 7 +- 8 files changed, 491 insertions(+), 33 deletions(-) --- diff --git a/dist/standard/dbconf/mysql/gateway_log.mysql b/dist/standard/dbconf/mysql/gateway_log.mysql new file mode 100644 index 0000000..e08f7e5 --- /dev/null +++ b/dist/standard/dbconf/mysql/gateway_log.mysql @@ -0,0 +1,16 @@ +Database gateway_log gateway_log.txt __SQLDSN__ + +Database gateway_log DEFAULT_TYPE text not null default '' +Database gateway_log AUTO_SEQUENCE 1 +Database gateway_log KEY gateway_log_id +Database gateway_log COLUMN_DEF "order_md5=varchar(32) not null default ''" +Database gateway_log COLUMN_DEF "request_date=varchar(32) not null default ''" +Database gateway_log COLUMN_DEF "request_id=varchar(255) not null default ''" +Database gateway_log COLUMN_DEF "order_number=varchar(32) not null default ''" +Database gateway_log COLUMN_DEF "email=varchar(128) not null default ''" +Database gateway_log INDEX request_date +Database gateway_log INDEX request_id +Database gateway_log INDEX order_number +Database gateway_log INDEX email +Database gateway_log INDEX order_md5 +Database gateway_log NO_ASCII_INDEX 1 diff --git a/dist/standard/dbconf/pgsql/gateway_log.pgsql b/dist/standard/dbconf/pgsql/gateway_log.pgsql new file mode 100644 index 0000000..3ca5f66 --- /dev/null +++ b/dist/standard/dbconf/pgsql/gateway_log.pgsql @@ -0,0 +1,11 @@ +Database gateway_log gateway_log.txt __SQLDSN__ + +Database gateway_log DEFAULT_TYPE TEXT NOT NULL DEFAULT '' +Database gateway_log AUTO_SEQUENCE gateway_log_id_seq +Database gateway_log KEY gateway_log_id +Database gateway_log COLUMN_DEF "gateway_log_id=INTEGER PRIMARY KEY NOT NULL DEFAULT NEXTVAL('gateway_log_id_seq')" +Database gateway_log INDEX request_date +Database gateway_log INDEX request_id +Database gateway_log INDEX order_number +Database gateway_log INDEX email +Database gateway_log NO_ASCII_INDEX 1 diff --git a/dist/standard/dbconf/sqlite/gateway_log.lite b/dist/standard/dbconf/sqlite/gateway_log.lite new file mode 100644 index 0000000..e08f7e5 --- /dev/null +++ b/dist/standard/dbconf/sqlite/gateway_log.lite @@ -0,0 +1,16 @@ +Database gateway_log gateway_log.txt __SQLDSN__ + +Database gateway_log DEFAULT_TYPE text not null default '' +Database gateway_log AUTO_SEQUENCE 1 +Database gateway_log KEY gateway_log_id +Database gateway_log COLUMN_DEF "order_md5=varchar(32) not null default ''" +Database gateway_log COLUMN_DEF "request_date=varchar(32) not null default ''" +Database gateway_log COLUMN_DEF "request_id=varchar(255) not null default ''" +Database gateway_log COLUMN_DEF "order_number=varchar(32) not null default ''" +Database gateway_log COLUMN_DEF "email=varchar(128) not null default ''" +Database gateway_log INDEX request_date +Database gateway_log INDEX request_id +Database gateway_log INDEX order_number +Database gateway_log INDEX email +Database gateway_log INDEX order_md5 +Database gateway_log NO_ASCII_INDEX 1 diff --git a/dist/standard/products/gateway_log.txt b/dist/standard/products/gateway_log.txt new file mode 100644 index 0000000..ff58fba --- /dev/null +++ b/dist/standard/products/gateway_log.txt @@ -0,0 +1 @@ +gateway_log_id trans_type processor catalog result_code response_msg request_id order_number email session_id request_source request_date request_duration request response diff --git a/lib/Vend/Payment.pm b/lib/Vend/Payment.pm index 9dd2642..61b2654 100644 --- a/lib/Vend/Payment.pm +++ b/lib/Vend/Payment.pm @@ -40,7 +40,7 @@ use Vend::Order; use IO::Pipe; use strict; -use vars qw/$Have_LWP $Have_Net_SSLeay/; +use vars qw/$Have_LWP $Have_Net_SSLeay $Global_Timeout/; my $pay_opt; @@ -399,17 +399,24 @@ sub charge { my $pipe = IO::Pipe->new; unless ($pid = fork) { - Vend::Server::child_process_dbi_prep(); + $pipe->writer; + + Vend::Server::sever_database(); + local $SIG{USR2} = sub { + $Global_Timeout = 'Global Timeout on gateway request'; + exit; + }; + my %rv = $sub->($pay_opt); + $pipe->print( ::uneval(\%rv) ); exit; - } + } $pipe->reader; - my $to_msg = $pay_opt->{global_timeout_msg} - || charge_param('global_timeout_msg') + my $to_msg = charge_param('global_timeout_msg') || 'Due to technical difficulties, your order could not be processed.'; local $SIG{ALRM} = sub { die "$to_msg\n" }; @@ -422,24 +429,24 @@ sub charge { my $rv = eval join ('', $pipe->getlines); return %$rv; - } + } return $sub->($pay_opt); - }; - - if($@) { - my $msg = errmsg( - "payment routine '%s' returned error: %s", - $charge_type, - $@, - ); - kill (KILL => $pid) + }; + + if($@) { + my $msg = errmsg( + "payment routine '%s' returned error: %s", + $charge_type, + $@, + ); + kill (USR2 => $pid) if $pid && kill (0 => $pid); - ::logError($msg); - $result{MStatus} = 'died'; - $result{MErrMsg} = $msg; - } - } + ::logError($msg); + $result{MStatus} = 'died'; + $result{MErrMsg} = $msg; + } + } elsif($charge_type =~ /^\s*custom\s+(\w+)(?:\s+(.*))?/si) { #::logDebug("Charge custom"); # MV4 and IC4.6.x methods diff --git a/lib/Vend/Payment/GatewayLog.pm b/lib/Vend/Payment/GatewayLog.pm new file mode 100644 index 0000000..f0bb49c --- /dev/null +++ b/lib/Vend/Payment/GatewayLog.pm @@ -0,0 +1,296 @@ +package Vend::Payment::GatewayLog; + +use strict; +use warnings; + +use Time::HiRes; + +sub new { + my ($class, $self) = @_; + $self = {} unless ref ($self) eq 'HASH'; + $self->{_log_table} = $self->{LogTable} || 'gateway_log'; + $self->{_enabled} = $self->{Enabled} || ''; + $Vend::Payment::Global_Timeout = undef; + bless ($self, $class); +} + +sub start { + my $self = shift; + return unless $self->_enabled; + my $override = shift; + $self->{__start} = Time::HiRes::clock_gettime() + if $override || !$self->{__start}; + return $self->{__start}; +} + +sub stop { + my $self = shift; + return unless $self->_enabled; + my $override = shift; + $self->{__stop} = Time::HiRes::clock_gettime() + if $override || !$self->{__stop}; + return $self->{__stop}; +} + +sub duration { + my $self = shift; + return unless $self->_enabled; + my $fmt = shift || '%0.3f'; + return sprintf ($fmt, $self->stop - $self->start); +} + +sub timestamp { + my $self = shift; + return unless $self->_enabled; + my $fmt = shift || '%Y-%m-%d %T'; + return POSIX::strftime($fmt, localtime($self->start)); +} + +sub request { + my $self = shift; + return unless $self->_enabled; + my $request = shift; + return $self->{__request} + unless $request; + unless (ref ($request) eq 'HASH') { + ::logDebug( + 'Skipping non-HASH request set: received %s (unevals to %s)', + $request, + ::uneval($request) + ); + return; + } + $self->{__request} = { %$request }; +} + +sub response { + my $self = shift; + return unless $self->_enabled; + my $response = shift; + return $self->{__response} + unless $response; + unless (ref ($response) eq 'HASH') { + ::logDebug( + 'Skipping non-HASH response set: received %s (unevals to %s)', + $response, + ::uneval($response) + ); + return; + } + $self->{__response} = { %$response }; +} + +sub clean { + my $self = shift; + return unless $self->_enabled; + delete $self->{$_} + for grep { /^__/ } keys %$self; + return 1; +} + +sub log_it { + die 'Must override log_it() in subclass'; +} + +sub table { + return shift()->{_log_table}; +} + +sub _enabled { + return shift()->{_enabled}; +} + +sub DESTROY { + my $self = shift; + return 1 unless $self->_enabled; + $self->log_it; + 1; +} + +1; + +__END__ + +=head1 NAME + +Vend::Payment::GatewayLog - Basic package and methods for enabling full +transaction logging in any of the gateways within the Vend::Payment::* +namespace. + +=head1 VERSION + +1.00 + +=head1 USAGE + +From within the normally unused namespace of the payment gateway: + + package Vend::Payment::WhizBang; + + use Vend::Payment::GatewayLog + use base qw/Vend::Payment::GatewayLog/; + + sub log_it { + # Override log_it() with gateway-dependent mapping to a logging table, + # by default gateway_log + ... + } + +Then from inside the gateway sub itself: + + ... + my $gwl = + Vend::Payment::WhizBang + -> new({ + Enabled => charge_param('gwl_enabled'), + }); + + $gwl->request(\%scrubbed_request_hash); + $gwl->start; + ... Code that calls out to gateway's API ... + $gwl->stop; + ... + $gwl->response(\%response_hash); + +=head1 DESCRIPTION + +Module sets up an object with some utility methods to facilitate full database +logging of all transaction attempts executed through the gateway. Often these +data are either missing or insufficient for proper evaluation of problem events +or general reporting. + +It's important to scrub all sensitive data appropriate for permanent storage. +Minimally, this is recommended to include credit card numbers and CVV2 values, +any senstitive gateway credentials (passwords or secret keys), or any personal +data that can be used to exploit a customer's identity (SSN, date of birth, +etc.). + +You do not want to call log_it() yourself. It is set up to execute +automatically on destruction to help ensure that unexpected exits or aborts are +still logged. + +=head2 Options + +Pass hashref to the constructor to include the following options: + +=over 4 + +=item Enabled + +Boolean to indicate that actual logging should be performed. Default is false; +thus logging must be explicitly requested. Route indicator should be +"gwl_enabled" for consistency and so that global logging can be enabled by +setting MV_PAYMENT_GWL_ENABLED in catalog.cfg. + +=item LogTable + +Name of table to which logging should be directed. Default is gateway_log. +Route indicator should be "gwl_table" for consistency and so that a global +target table can be set through MV_PAYMENT_GWL_TABLE in catalog.cfg. + +=back + +=head1 METHODS + +=over 4 + +=item new() + +Constructor with optional hash ref indicating any of the above Options. Note +that when Enabled, it will trigger a log write as soon as it goes out of scope, +so consider when and where you want to call the constructor. + +=item start() + +Return, and optionally set, the Time::HiRes::clock_gettime() of the beginning +of the call to the gateway's API. When called for the first time, it will set +the value in the object and return said value; otherwise, it simply returns the +previously set value. The set can be overridden by calling the method with a +perly true arg. + +=item stop() + +Return, and optionally set, the Time::HiRes::clock_gettime() of the end of the +call to the gateway's API. Same conditions apply as do for start() + +=item duration() + +Returns the delta of stop() - start(). Be aware that calling this method +prior to calling either start() or stop() will cause the current time to +be used for each and frozen. + +Default format is '%0.3f', but can be overriden passed as an arg. + +=item timestamp() + +Returns the timestamp of the value of start(). Again, calling this method +prior to calling start() will cause the current time to be used and frozen. + +Default format is '%Y-%m-%d %T', but can be overriden passed as an arg. + +=item request() + +Freeze the hash request sent to the payment gateway if passed as an arg. Code +will freeze a copy of the hash (though not a deep copy, if that impacts your +particular gateway's request structure) so that any post-request processing on +the original hash will not affect the stored request. + +Method only accepts a hash reference and will skip any other data structure +that is attempted to be saved and logs the issue to the debug log, along with +an ::uneval() of whatever was passed in. + +Calling with no args will only return the currently stored request hash +reference. + +=item response() + +Freeze the hash response from the payment gateway if passed as an arg. Code +will freeze a copy of the hash (though not a deep copy, if that impacts your +particular gateway's response structure) so that any post-response processing +on the original hash will not affect the stored response. + +Method only accepts a hash reference and will skip any other data structure +that is attempted to be saved and logs the issue to the debug log, along with +an ::uneval() of whatever was passed in. + +Calling with no args will only return the currently stored response hash +reference. + +=item clean() + +Will purge all stored data from the object. + +=item log_it() + +Stub that must be overridden in the subclass. Invoking the object when +log_it() has failed to be overridden will cause the code to die. + +=item table() + +Returns the name of the table against which the database update is to be +performed. Default is 'gateway_log', but can be overridden in the constructor +using the LogTable option. + +=back + +=head1 AUTHOR + +Mark Johnson ([email protected]), End Point Corp. + +=head1 LICENSE AND COPYRIGHT + +Copyright (C) 2009 Interchange Development Group and others + +This program is free software; you can redistribute it and/or modify it under +the terms of the GNU General Public License as published by the Free Software +Foundation; either version 2 of the License, or (at your option) any later +version. + +This program is distributed in the hope that it will be useful, but WITHOUT ANY +WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A +PARTICULAR PURPOSE. See the GNU General Public License for more details. + +You should have received a copy of the GNU General Public License along with +this program; if not, see: http://www.gnu.org/licenses/ + +=cut diff --git a/lib/Vend/Payment/PayflowPro.pm b/lib/Vend/Payment/PayflowPro.pm index 6f5ff16..085a61b 100644 --- a/lib/Vend/Payment/PayflowPro.pm +++ b/lib/Vend/Payment/PayflowPro.pm @@ -673,18 +673,23 @@ sub payflowpro { } } -# Uncomment all the following block to use the debug statement. It strips -# the arg of any sensitive credit card information and is safe -# (and recommended) to enable in production. -# -# { -# my %munged_query = %query; -# $munged_query{PWD} = 'X'; -# $munged_query{ACCT} =~ s/^(\d{4})(.*)/$1 . ('X' x length($2))/e; -# $munged_query{CVV2} =~ s/./X/g; -# $munged_query{EXPDATE} =~ s/./X/g; + my $gwl = + Vend::Payment::PayflowPro + -> new({ + Enabled => charge_param('gwl_enabled'), + LogTable => charge_param('gwl_table'), + }) + ; + + { + my %munged_query = %query; + $munged_query{PWD} = 'X'; + $munged_query{ACCT} =~ s/^(\d{4})(.*)/$1 . ('X' x length($2))/e; + $munged_query{CVV2} =~ s/./X/g; + $munged_query{EXPDATE} =~ s/./X/g; #::logDebug("payflowpro query: " . ::uneval(\%munged_query)); -# } + $gwl->request(\%munged_query); + } my $timeout = $opt->{timeout} || 45; die "Bad timeout value, security violation." unless $timeout && $timeout !~ /\D/; @@ -732,18 +737,22 @@ sub payflowpro { my $request = HTTP::Request->new('POST', $uri, $headers, $string); my $ua = LWP::UserAgent->new(timeout => $timeout); $ua->agent('Vend::Payment::PayflowPro'); + $gwl->start; my $response = $ua->request($request); + $gwl->stop; my $resultstr = $response->content; #::logDebug(qq{PayflowPro response:\n\t$resultstr\n--------------------}); unless ( $response->is_success ) { - return ( + my %return = ( RESULT => -1, RESPMSG => 'System Error', MStatus => 'failure-hard', MErrMsg => 'System Error', lwp_response => $resultstr, ); + $gwl->response(\%return); + return %return; } %$result = split /[&=]/, $resultstr; @@ -757,6 +766,7 @@ sub payflowpro { } my $decline = $result->{RESULT}; + $gwl->response($result); if ( $result->{RESULT} =~ /^0|12[67]$/ @@ -849,4 +859,100 @@ sub payflowpro { package Vend::Payment::PayflowPro; +use Vend::Payment::GatewayLog; +use base qw/Vend::Payment::GatewayLog/; + +# log_it() must be overridden. +sub log_it { + my $self = shift; + my $request = $self->request + or ::logDebug('Cannot write to %s: no request present', $self->table), + return; + + my $response = $self->response; + unless ($response) { + + if ($Vend::Payment::Global_Timeout) { + my $msg = errmsg('No response. Global timeout triggered'); + ::logDebug($msg); + $response = { + RESULT => -2, + RESPMSG => $Vend::Payment::Global_Timeout, + }; + } + else { + my $msg = errmsg('No response. Reason unknown'); + ::logDebug($msg); + $response = { + RESULT => -3, + RESPMSG => $msg, + }; + } + } + + eval { + my $table = $self->table; + my $db = ::database_exists_ref($table) + or die "'$table' not a valid Interchange table"; + $db = $db->ref; + + my %fields = ( + trans_type => $request->{TRXTYPE} || 'x', + processor => 'payflowpro', + catalog => $Vend::Cfg->{CatalogName}, + result_code => + defined ($response->{RESULT}) + && $response->{RESULT} =~ /^-?\d+$/ + ? $response->{RESULT} + : undef, + response_msg => $response->{RESPMSG} || '', + request_id => $response->{PNREF} || '', + order_number => $request->{COMMENT1} || '', + request_duration => $self->duration, + request_date => $self->timestamp, + email => $request->{EMAIL} || '', + request => ::uneval($request) || '', + response => ::uneval($response) || '', + session_id => $::Session->{id}, + ); + + my $hostname = `hostname -s`; + chomp $hostname; + $fields{request_source} = $hostname; + + $fields{order_md5} = + Digest::MD5::md5_hex( + $request->{EMAIL}, + $request->{TRXTYPE}, + $request->{ORIGID}, + $request->{AMT}, + $::Session->{id}, + map { ($_->{code}, $_->{quantity}) } @$Vend::Items + ) + ; + + $db->set_slice( + [ { dml => 'insert' } ], + \%fields + ) + or die "set_slice for $table failed"; + }; # End eval + + if ($@) { + my $err = $@; + ::logDebug( + q{Couldn't write to %s: %s -- request: %s -- response: %s}, + $self->table, + $err, + ::uneval($request), + ::uneval($response) + ); + } + else { + $self->clean; + } + + return 1; +} + 1; diff --git a/lib/Vend/Table/DBI.pm b/lib/Vend/Table/DBI.pm index 95f35b1..217932b 100644 --- a/lib/Vend/Table/DBI.pm +++ b/lib/Vend/Table/DBI.pm @@ -157,6 +157,7 @@ my %known_capability = ( DB2 => 1, Pg => 1, Oracle => 1, + SQLite => 1, }, HAS_DESCRIBE => { mysql => 1, @@ -185,6 +186,7 @@ my %known_capability = ( HAS_LIMIT => { mysql => 1, Pg => 1, + SQLite => 1, }, ALTER_DELETE => { mysql => 'ALTER TABLE _TABLE_ DROP _COLUMN_', @@ -225,12 +227,14 @@ my %known_capability = ( Pg => "SELECT nextval(_SEQUENCE_NAME_V_)", }, SEQUENCE_VAL => { - mysql => undef, + mysql => undef, + SQLite => undef, }, SEQUENCE_KEY => { mysql => 'INT PRIMARY KEY AUTO_INCREMENT', Pg => 'INT NOT NULL PRIMARY KEY', Oracle => 'INT NOT NULL PRIMARY KEY', + SQLite => 'INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL', }, SEQUENCE_VALUE_FUNCTION => { Pg => "SELECT currval(_SEQUENCE_NAME_V_)", @@ -238,6 +242,7 @@ my %known_capability = ( }, SEQUENCE_LAST_FUNCTION => { mysql => 'select last_insert_id()', + SQLite => 'select last_insert_rowid()', ## These use explicit Pg => undef, Oracle => undef,