Mailing List Archive

commit c36681872e7333c15954b797c3990e8d51a952e5
Author: Mark Johnson <mark@endpoint.com>
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 (mark@endpoint.com), 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,

_______________________________________________
interchange-cvs mailing list
interchange-cvs@icdevgroup.org
http://www.icdevgroup.org/mailman/listinfo/interchange-cvs