PAYONE-GmbH · BoulangerV · Apr 12, 2022
diff --git a/extend/application/controllers/fcPayOneOrderView.php b/extend/application/controllers/fcPayOneOrderView.php
@@ -83,10 +83,18 @@ public function __construct()
      */
     public function execute()
     {
+        $this->_oFcpoHelper->debugGlobalVariables('(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $sFcpoMandateCheckbox = $this->_oFcpoHelper->fcpoGetRequestParameter('fcpoMandateCheckbox');
         $sPaymentId = $this->_oFcpoHelper->fcpoGetSessionVariable('paymentid');
         $blIsRedirectPayment = fcPayOnePayment::fcIsPayOneRedirectType($sPaymentId);
 
+        $this->_oFcpoHelper->debugLog('Executing payment : ' . $sPaymentId, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
+        if($blIsRedirectPayment) {
+            $this->_oFcpoHelper->debugLog('Payment is redirected' , '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
+        } else {
+            $this->_oFcpoHelper->debugLog('Payment is NOT redirected' , '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
+        }
+
         $blConfirmMandateError = (
             (!$sFcpoMandateCheckbox || $sFcpoMandateCheckbox == 'false') &&
             $this->_fcpoMandateAcceptanceNeeded()

diff --git a/extend/application/controllers/fcPayOnePaymentView.php b/extend/application/controllers/fcPayOnePaymentView.php
@@ -955,10 +955,13 @@ public function validateAmazonPayment() {
      */
     public function validatePayment() 
     {
+        $this->_oFcpoHelper->debugGlobalVariables('(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $sPaymentId = $this->_fcpoGetPaymentId();
+        $this->_oFcpoHelper->debugLog('Payment chosen : ' . $sPaymentId, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $this->_fcpoCheckKlarnaUpdateUser($sPaymentId);
 
         $mReturn = parent::validatePayment();
+        $this->_oFcpoHelper->debugLog('Payment validation result : ' . $mReturn, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         $mReturn = $this->_processParentReturnValue($mReturn);
         $mReturn = $this->_fcpoProcessValidation($mReturn, $sPaymentId);
@@ -1453,6 +1456,7 @@ protected function _fcpoKlarnaUpdateUser()
         }
 
         if ($blUserChanged === true) {
+            $this->_oFcpoHelper->debugLog('Klarna User updated : ' . $oUser->oxuser__oxid, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $oUser->save();
         }
     }
@@ -1521,24 +1525,33 @@ protected function _fcpoProcessValidation($mReturn, $sPaymentId)
             $oPayment = $this->_oFcpoHelper->getFactoryObject('oxpayment');
             $oPayment->load($sPaymentId);
             $mReturn = $this->_fcpoSecInvoiceSaveRequestedValues($mReturn, $sPaymentId);
+            $this->_oFcpoHelper->debugLog('Secinvoice validation result : ' . $mReturn, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $blContinue = $this->_fcpoCheckBoniMoment($oPayment);
 
             if ($blContinue !== true) {
                 $this->_fcpoSetBoniErrorValues($sPaymentId);
+                $this->_oFcpoHelper->debugLog('Boni validation failed', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
                 $mReturn = 'basket';
             } else {
                 $this->_fcpoSetMandateParams($oPayment);
+                $this->_oFcpoHelper->debugLog('Boni validated', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             }
 
             $this->_fcCleanupSessionFragments($oPayment);
+            $this->_oFcpoHelper->debugLog('Session variables cleaned', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
             $mReturn = $this->_fcpoKlarnaCombinedValidate($mReturn, $sPaymentId);
+            $this->_oFcpoHelper->debugLog('Klarna validation result : ' . $mReturn, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
             $mReturn = $this->_fcpoPayolutionPreCheck($mReturn, $sPaymentId);
+            $this->_oFcpoHelper->debugLog('Unzer validation result : ' . $mReturn, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
+
             if (in_array($sPaymentId, array('fcporp_bill', 'fcporp_debitnote'))) {
                 $mReturn = $this->_fcpoCheckRatePayBillMandatoryUserData($mReturn, $sPaymentId);
+                $this->_oFcpoHelper->debugLog('Ratepay validation result : ' . $mReturn, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             }
             $mReturn = $this->_fcpoAdultCheck($mReturn, $sPaymentId);
+            $this->_oFcpoHelper->debugLog('Adult check validation result : ' . $mReturn, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         }
 
         return $mReturn;

diff --git a/extend/application/controllers/fcPayOneThankyouView.php b/extend/application/controllers/fcPayOneThankyouView.php
@@ -145,6 +145,7 @@ public function fcpoOrderHasProblems()
      */
     public function render() 
     {
+        $this->_oFcpoHelper->debugGlobalVariables('(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $oUser = $this->getUser();
         if($oUser) {
             $this->_oFcpoHelper->fcpoSetSessionVariable('sFcpoUserId', $oUser->getId());
@@ -166,6 +167,7 @@ public function render()
      */
     protected function _fcpoDeleteSessionVariablesOnOrderFinish()
     {
+        $this->_oFcpoHelper->debugLog('Delete session variables on order finish', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $this->_oFcpoHelper->fcpoDeleteSessionVariable('fcpoRefNr');
         $this->_oFcpoHelper->fcpoDeleteSessionVariable('klarna_authorization_token');
         $this->_oFcpoHelper->fcpoDeleteSessionVariable('klarna_client_token');

diff --git a/extend/application/models/fcPayOneOrder.php b/extend/application/models/fcPayOneOrder.php
@@ -471,12 +471,15 @@ protected function _fcpoFinalizeOrder($oBasket, $oUser, $blRecalculatingOrder) {
 
         // copies user info
         $this->_setUser($oUser);
+        $this->_oFcpoHelper->debugLog('Finalize order : copy user info', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         // copies basket info if no basket injection or presave order is inactive
         $this->_fcpoHandleBasket($blSaveAfterRedirect, $oBasket);
+        $this->_oFcpoHelper->debugLog('Finalize order : handle basket', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         // payment information
         $oUserPayment = $this->_setPayment($oBasket->getPaymentId());
+        $this->_oFcpoHelper->debugLog('Finalize order : set payment info', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         // set folder information, if order is new
         // #M575 in recalcualting order case folder must be the same as it was
@@ -485,12 +488,14 @@ protected function _fcpoFinalizeOrder($oBasket, $oUser, $blRecalculatingOrder) {
         }
 
         $mRet = $this->_fcpoExecutePayment($blSaveAfterRedirect, $oBasket, $oUserPayment, $blRecalculatingOrder);
+        $this->_oFcpoHelper->debugLog('Finalize order : execute payment : ' . $mRet, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         if ($mRet !== null) {
             return $mRet;
         }
 
         //saving all order data to DB
         $this->_blFinishingSave = true;
+        $this->_oFcpoHelper->debugLog('Finalize order : saving order to DB', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $this->save();
 
         $this->_fcpoSaveAfterRedirect($blSaveAfterRedirect);
@@ -505,6 +510,7 @@ protected function _fcpoFinalizeOrder($oBasket, $oUser, $blRecalculatingOrder) {
         }
 
         $this->_fcpoSetOrderStatus();
+        $this->_oFcpoHelper->debugLog('Finalize order : set order status', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         // store orderid
         $oBasket->setOrderId($this->getId());
@@ -521,17 +527,20 @@ protected function _fcpoFinalizeOrder($oBasket, $oUser, $blRecalculatingOrder) {
         $this->_fcpoMarkVouchers($blRecalculatingOrder, $oUser, $oBasket);
 
         if (!$this->oxorder__oxordernr->value) {
+            $this->_oFcpoHelper->debugLog('Finalize order : assign missing order nr', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $this->_setNumber();
         } else {
             oxNew(\OxidEsales\Eshop\Core\Counter::class)->update($this->_getCounterIdent(), $this->oxorder__oxordernr->value);
         }
+        $this->_oFcpoHelper->debugLog('Finalize order : order nr = ' . $this->oxorder__oxordernr->value, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         $this->_oFcpoHelper->fcpoDeleteSessionVariable('fcpoordernotchecked');
         $this->_oFcpoHelper->fcpoDeleteSessionVariable('fcpoWorkorderId');
 
         // send order by email to shop owner and current user
         // skipping this action in case of order recalculation
         $iRet = $this->_fcpoFinishOrder($blRecalculatingOrder, $oUser, $oBasket, $oUserPayment);
+        $this->_oFcpoHelper->debugLog('Finalize order : finish order result : ' . $iRet, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
 
         // OXID-233 : handle amazon different login
         $this->_fcpoAdjustAmazonPayUserDetails($oUserPayment);
@@ -593,6 +602,7 @@ protected function _fcpoExecutePayment($blSaveAfterRedirect, $oBasket, $oUserPay
     {
         if ($blSaveAfterRedirect === true) {
             $sRefNrCheckResult = $this->_fcpoCheckRefNr();
+            $this->_oFcpoHelper->debugLog('Ref nr check result (empty = ok) : ' . $sRefNrCheckResult, '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $sTxid = $this->_oFcpoHelper->fcpoGetSessionVariable('fcpoTxid');
 
             if ($sRefNrCheckResult != '') {
@@ -751,6 +761,7 @@ protected function _fcpoEarlyValidation($blSaveAfterRedirect, $oBasket, $oUser,
             $oUtils = $this->_oFcpoHelper->fcpoGetUtils();
             $oUtils->logger('BLOCKER');
             // we might use this later, this means that somebody klicked like mad on order button
+            $this->_oFcpoHelper->debugLog('Order validation failed : order already exists', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             return self::ORDER_STATE_ORDEREXISTS;
         }
 
@@ -766,6 +777,7 @@ protected function _fcpoEarlyValidation($blSaveAfterRedirect, $oBasket, $oUser,
 
             // validating various order/basket parameters before finalizing
             if (($iOrderState = $this->validateOrder($oBasket, $oUser))) {
+                $this->_oFcpoHelper->debugLog('Order validation failed : misc. order/basket parameters', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
                 return $iOrderState;
             }
         }
@@ -783,6 +795,7 @@ protected function _fcCompareBasketAgainstShadowBasket($oBasket) {
         $oShadowBasket = $this->fcpoGetShadowBasket();
         $blIsValid = $this->_fcpoCompareBaskets($oBasket, $oShadowBasket);
         if ($blIsValid === false) {
+            $this->_oFcpoHelper->debugLog('Order validation failed : non-matching shadow basket', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $this->_fcpoMarkOrderAsProblematic();
             $this->_fcpoAddShadowBasketCheckDate();
         } else {
@@ -959,6 +972,7 @@ protected function _fcpoFinishOrder($blRecalculatingOrder, $oUser, $oBasket, $oU
     protected function _fcpoSaveAfterRedirect($blSaveAfterRedirect) 
     {
         if ($blSaveAfterRedirect === true) {
+            $this->_oFcpoHelper->debugLog('Finalize order : save after redirect order nr', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $sQuery = "UPDATE fcpotransactionstatus SET fcpo_ordernr = '{$this->oxorder__oxordernr->value}' WHERE fcpo_txid = '" . $this->_oFcpoHelper->fcpoGetSessionVariable('fcpoTxid') . "'";
             $this->_oFcpoDb->Execute($sQuery);
         }
@@ -1088,6 +1102,10 @@ protected function _fcpoCheckTxid()
         }
         $this->_fcpoSetAppointedError($blAppointedError);
 
+        if ($blAppointedError) {
+            $this->_oFcpoHelper->debugLog('Order moved to error folder : Txid check failed', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
+        }
+
         return $blAppointedError;
     }
 
@@ -1521,6 +1539,7 @@ public function validateStock($oBasket)
         ) ? false : true;
 
         if ($blCheckProduct) {
+            $this->_oFcpoHelper->debugLog('Finalize order : check stocks', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             parent::validateStock($oBasket);
         }
 
@@ -1643,6 +1662,7 @@ public function fcIsPayPalOrder()
      */
     public function fcHandleAuthorization($blReturnRedirectUrl = false, $oPayGateway = null) 
     {
+        $this->_oFcpoHelper->debugLog('Finalize order : handle authorization', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $oConfig = $this->_oFcpoHelper->fcpoGetConfig();
         $aDynvalueForm = $this->_oFcpoHelper->fcpoGetRequestParameter('dynvalue');
         if ($this->oxorder__oxpaymenttype->value === 'fcpoklarna_directdebit' && $this->_oFcpoHelper->fcpoGetSessionVariable('klarna_authorization_token') === '' ) {
@@ -1813,6 +1833,7 @@ protected function _fcpoFlagOrderPaymentAsRedirect($blFlaggedAsRedirect = true)
      */
     protected function _fcpoHandleAuthorizationRedirect($aResponse, $sRefNr, $sAuthorizationType, $sMode, $blReturnRedirectUrl) 
     {
+        $this->_oFcpoHelper->debugLog('Finalize order : handle redirect authorization', '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
         $this->_fcpoFlagOrderPaymentAsRedirect();
         $oConfig = $this->_oFcpoHelper->fcpoGetConfig();
         $oUtils = $this->_oFcpoHelper->fcpoGetUtils();

diff --git a/lib/fcpodebuglogger.php b/lib/fcpodebuglogger.php
@@ -0,0 +1,70 @@
+<?php
+/**
+ * 0079203 : Temporary debug logger class
+ * */
+
+class fcpodebuglogger extends oxBase
+{
+
+    const LOG_DIR_SUFFIX = 'payone/debug/';
+
+    /**
+     * Helper object for dealing with different shop versions
+     *
+     * @var object
+     */
+    protected $_oFcpoHelper = null;
+
+    /**
+     * @var string
+     */
+    private $sLogDirPath = '';
+
+    public function __construct()
+    {
+        parent::__construct();
+        $this->_oFcpoHelper = oxNew('fcpohelper');
+        $this->sLogDirPath = $this->_oFcpoHelper->fcpoGetConfig()->getLogsDir() . self::LOG_DIR_SUFFIX;
+    }
+
+    /**
+     * @param string $message
+     * @param string $location
+     */
+    public function writeEntry($message = '', $location = '')
+    {
+        $sTimestamp = $this->getDate()->format('[Y-m-d H:i:s]');
+        $sLogEntry = $sTimestamp . ' ' . $location . ' ' . $message . PHP_EOL;
+
+        file_put_contents($this->getCurrentLogFile(), $sLogEntry, FILE_APPEND);
+    }
+
+    protected function getCurrentLogFile()
+    {
+        $sToday = $this->getDate()->format('Y-m-d');
+        $sDailyLogFile = $this->getLogDir() . '' . $sToday . '_debug_log.log';
+
+        return $sDailyLogFile;
+    }
+
+    /**
+     * @return string
+     */
+    protected function getLogDir()
+    {
+        if (!is_dir($this->sLogDirPath)) {
+            mkdir($this->sLogDirPath,0755, true);
+        }
+
+        return $this->sLogDirPath;
+    }
+
+    /**
+     * @return DateTimeImmutable
+     */
+    private function getDate()
+    {
+        return new DateTimeImmutable('now', new DateTimeZone('Europe/Berlin'));
+    }
+
+}
diff --git a/lib/fcpohelper.php b/lib/fcpohelper.php
@@ -21,6 +21,11 @@
 class fcpohelper extends oxBase
 {
 
+    /** @var bool Log or not the various steps of payment checkout */
+    protected static $_blDebugLogEntries = true;
+    /** @var bool Log or not the php GLOBALs (SERVER, SESSION, GET, POST, FcpoSession) when call a controller */
+    protected static $_blDebugLogGlobals = true;
+
     /**
      * Flags if shop uses registry
      *
@@ -622,4 +627,35 @@ protected static function _useRegistry()
         return self::$_blUseRegistry;
     }
 
+    /**
+     * @param string $message
+     * @param string $location
+     */
+    public function debugLog($message, $location = '')
+    {
+        if (self::$_blDebugLogEntries) {
+            $oLogger = oxNew('fcpodebuglogger');
+            $oLogger->writeEntry($message, $location);
+        }
+    }
+
+    /**
+     * @param string $location
+     */
+    public function debugGlobalVariables($location = '')
+    {
+        if (self::$_blDebugLogGlobals) {
+            $oLogger = oxNew('fcpodebuglogger');
+            $aVariables = [
+                'REQUEST' => $_REQUEST,
+                'SESSION' => $_SESSION,
+                'GET' => $_GET,
+                'POST' => $_POST,
+                'FCPOSession' => $this->fcpoGetSession()
+            ];
+
+            $oLogger->writeEntry(var_export($aVariables, true), $location);
+        }
+    }
+
 }
diff --git a/metadata.php b/metadata.php
@@ -99,6 +99,7 @@
         'fcpohelper'                        => 'fc/fcpayone/lib/fcpohelper.php',
         'fcporequest'                       => 'fc/fcpayone/lib/fcporequest.php',
         'fcpoparamsparser'                  => 'fc/fcpayone/lib/fcpoparamsparser.php',
+        'fcpodebuglogger'                  => 'fc/fcpayone/lib/fcpodebuglogger.php',
         // core
         'fcpayone_events'                   => 'fc/fcpayone/core/fcpayone_events.php',
     ),

diff --git a/status.php b/status.php
@@ -343,6 +343,8 @@ protected function _handleMapping()
     public function handle() 
     {
         try {
+            $oFcpoHelper = oxNew('fcpohelper');
+            $oFcpoHelper->debugLog('Handling txstatus for order (' . $this->fcGetPostParam('reference') . ') : ' . $this->fcGetPostParam('txaction'), '(' . __CLASS__ . '::' . __FUNCTION__ . ')');
             $this->_isKeyValid();
             $sStatusmessageId = $this->log();
             $this->_allowDebit();