Improved logging for bunq routine. #1607

app/Factory/TransactionCurrencyFactory.php

@@ -84,7 +84,7 @@ class TransactionCurrencyFactory
         $currencyId   = (int)$currencyId;
 
         if ('' === $currencyCode && 0 === $currencyId) {
-            Log::warning('Cannot find anything on empty currency code and empty currency ID!');
+            Log::debug('Cannot find anything on empty currency code and empty currency ID!');
 
             return null;
         }

app/Http/Controllers/Import/JobConfigurationController.php

@@ -76,7 +76,7 @@ class JobConfigurationController extends Controller
         Log::debug('Now in JobConfigurationController::index()');
         $allowed = ['has_prereq', 'need_job_config'];
         if (null !== $importJob && !\in_array($importJob->status, $allowed, true)) {
-            Log::debug(sprintf('Job has state "%s", but we only accept %s', $importJob->status, json_encode($allowed)));
+            Log::error(sprintf('Job has state "%s", but we only accept %s', $importJob->status, json_encode($allowed)));
             session()->flash('error', (string)trans('import.bad_job_status', ['status' => $importJob->status]));
 
             return redirect(route('import.index'));

app/Http/Controllers/Import/JobStatusController.php

@@ -135,7 +135,7 @@ class JobStatusController extends Controller
      */
     public function start(ImportJob $importJob): JsonResponse
     {
-        Log::debug('Now in JobStatusController::start');
+        Log::info('Now in JobStatusController::start');
         // catch impossible status:
         $allowed = ['ready_to_run', 'need_job_config'];
 
@@ -152,8 +152,10 @@ class JobStatusController extends Controller
         $className      = config($key);
         if (null === $className || !class_exists($className)) {
             // @codeCoverageIgnoreStart
+            $message = sprintf('Cannot find import routine class for job of type "%s".', $importProvider);
+            Log::error($message);
             return response()->json(
-                ['status' => 'NOK', 'message' => sprintf('Cannot find import routine class for job of type "%s".', $importProvider)]
+                ['status' => 'NOK', 'message' => $message]
             );
             // @codeCoverageIgnoreEnd
         }
@@ -179,6 +181,7 @@ class JobStatusController extends Controller
         }
 
         // expect nothing from routine, just return OK to user.
+        Log::info('Now finished with JobStatusController::start');
         return response()->json(['status' => 'OK', 'message' => 'stage_finished']);
     }
 
@@ -194,6 +197,7 @@ class JobStatusController extends Controller
      */
     public function store(ImportJob $importJob): JsonResponse
     {
+        Log::info('Now in JobStatusController::store');
         // catch impossible status:
         $allowed = ['provider_finished', 'storing_data'];
         if (null !== $importJob && !\in_array($importJob->status, $allowed, true)) {
@@ -222,7 +226,7 @@ class JobStatusController extends Controller
         // set storage to be finished:
         $this->repository->setStatus($importJob, 'storage_finished');
 
-
+        Log::info('Now finished with JobStatusController::start');
         // expect nothing from routine, just return OK to user.
         return response()->json(['status' => 'OK', 'message' => 'storage_finished']);
     }

app/Import/Routine/BunqRoutine.php

@@ -50,7 +50,7 @@ class BunqRoutine implements RoutineInterface
      */
     public function run(): void
     {
-        Log::debug(sprintf('Now in BunqRoutine::run() with status "%s" and stage "%s".', $this->importJob->status, $this->importJob->stage));
+        Log::info(sprintf('Now in BunqRoutine::run() with status "%s" and stage "%s".', $this->importJob->status, $this->importJob->stage));
         $valid = ['ready_to_run']; // should be only ready_to_run
         if (\in_array($this->importJob->status, $valid, true)) {
             switch ($this->importJob->stage) {

app/Import/Storage/ImportArrayStorage.php

@@ -424,7 +424,7 @@ class ImportArrayStorage
         $count   = \count($array);
         $toStore = [];
 
-        Log::debug(sprintf('Now in store(). Count of items is %d.', $count));
+        Log::notice(sprintf('Will now store the transactions. Count of items is %d.', $count));
 
         /*
          * Detect duplicates in initial array:
@@ -432,6 +432,7 @@ class ImportArrayStorage
         foreach ($array as $index => $transaction) {
             Log::debug(sprintf('Now at item %d out of %d', $index + 1, $count));
             if ($this->duplicateDetected($index, $transaction)) {
+                Log::warning(sprintf('Row #%d seems to be a duplicate entry and will be ignored.', $index));
                 continue;
             }
             $transaction['importHashV2'] = $this->getHash($transaction);
@@ -443,13 +444,14 @@ class ImportArrayStorage
 
             return new Collection;
         }
-
+        Log::notice(sprintf('After a first check for duplicates, the count of items is %d.', $count));
-        Log::debug('Going to store...');
+        Log::notice('Going to store...');
         // now actually store them:
         $collection = new Collection;
         foreach ($toStore as $index => $store) {
             // do duplicate detection again!
             if ($this->duplicateDetected($index, $store)) {
+                Log::warning(sprintf('Row #%d seems to be a imported already and will be ignored.', $index), $store);
                 continue;
             }
 
@@ -466,6 +468,8 @@ class ImportArrayStorage
                 $this->repository->addErrorMessage($this->importJob, sprintf('Row #%d could not be imported. %s', $index, $e->getMessage()));
                 continue;
             }
+
+            Log::info(sprintf('Stored #%d: "%s" (ID #%d)', $index, $journal->description, $journal->id));
             Log::debug(sprintf('Stored as journal #%d', $journal->id));
             $collection->push($journal);
 
@@ -477,7 +481,7 @@ class ImportArrayStorage
                 Log::debug(sprintf('List length is now %d', $this->transfers->count()));
             }
         }
-        Log::debug('DONE storing!');
+        Log::notice(sprintf('Done storing. Firefly III has stored %d transactions.', $collection->count()));
 
         return $collection;
     }

app/Support/Import/JobConfiguration/Bunq/ChooseAccountsHandler.php

@@ -32,6 +32,7 @@ use FireflyIII\Repositories\Account\AccountRepositoryInterface;
 use FireflyIII\Repositories\Currency\CurrencyRepositoryInterface;
 use FireflyIII\Repositories\ImportJob\ImportJobRepositoryInterface;
 use Illuminate\Support\MessageBag;
+use Log;
 
 /**
  * Class ChooseAccountsHandler
@@ -119,6 +120,9 @@ class ChooseAccountsHandler implements BunqJobConfigurationInterface
         $config['apply-rules'] = $applyRules;
         $this->repository->setConfiguration($this->importJob, $config);
 
+        Log::info('Account mapping: ', $final);
+        Log::info('Bunq IBAN array: ', $ibanToAsset);
+
         return new MessageBag;
     }
 

app/Support/Import/Routine/Bunq/StageImportDataHandler.php

@@ -104,8 +104,8 @@ class StageImportDataHandler
         foreach ($accounts as $bunqAccount) {
             $bunqAccountId = $bunqAccount['id'] ?? 0;
             $localId       = $mapping[$bunqAccountId] ?? 0;
-            Log::debug(sprintf('Looping accounts, now at bunq account #%d and local account #%d', $bunqAccountId, $localId));
             if (0 !== $localId && 0 !== $bunqAccountId) {
+                Log::info(sprintf('Now at bunq account #%d and local account #%d', $bunqAccountId, $localId));
                 $localAccount = $this->getLocalAccount((int)$localId);
                 $collection[] = $this->getTransactionsFromBunq($bunqAccountId, $localAccount);
             }
@@ -205,6 +205,7 @@ class StageImportDataHandler
                 ],
             ],
         ];
+        Log::info(sprintf('Parsed %s: "%s" (%s).', $created->format('Y-m-d'), $storeData['description'], $storeData['transactions'][0]['amount']));
 
         return $storeData;
     }
@@ -267,7 +268,7 @@ class StageImportDataHandler
         $account = $this->accountFactory->create($data);
         Log::debug(
             sprintf(
-                'Converted label monetary account %s to %s account %s (#%d)',
+                'Converted label monetary account "%s" to "%s" account "%s" (#%d)',
                 $party->getLabelUser()->getDisplayName(),
                 $expectedType,
                 $account->name, $account->id
@@ -362,6 +363,7 @@ class StageImportDataHandler
         $direction = $this->getDirection($bunqAccountId);
         $return    = [];
         if (self::DOWNLOAD_BACKWARDS === $direction) {
+            Log::info('For this account we go backwards in time.');
             // go back either from NULL or from ID.
             // ID is the very last transaction downloaded from bunq.
             $preference    = \Preferences::getForUser($this->importJob->user, sprintf('bunq-oldest-transaction-%d', $bunqAccountId), 0);
@@ -369,6 +371,7 @@ class StageImportDataHandler
             $return        = $this->goBackInTime($bunqAccountId, $localAccount, $transactionId);
         }
         if (self::DOWNLOAD_FORWARDS === $direction) {
+            Log::info('For this account we go forwards in time.');
             // go forward from ID. There is no NULL, young padawan
             $return = $this->goForwardInTime($bunqAccountId, $localAccount);
         }
@@ -415,7 +418,7 @@ class StageImportDataHandler
              */
             /** @var Payment $paymentRequest */
             $paymentRequest = app(Payment::class);
-            $params         = ['count' => 53, 'older_id' => $olderId];
+            $params         = ['count' => 79, 'older_id' => $olderId];
             $response       = $paymentRequest->listing($bunqAccountId, $params);
             $pagination     = $response->getPagination();
             Log::debug('Params for the request to bunq are: ', $params);
@@ -472,13 +475,13 @@ class StageImportDataHandler
                  */
                 $oldestTransaction = 0;
             }
-            sleep(1);
+            // half a second.
-
+            usleep(500000);
-
         }
         // store newest and oldest tranasction ID to be used later:
         \Preferences::setForUser($this->importJob->user, sprintf('bunq-oldest-transaction-%d', $bunqAccountId), $oldestTransaction);
         \Preferences::setForUser($this->importJob->user, sprintf('bunq-newest-transaction-%d', $bunqAccountId), $newestTransaction);
+        Log::info(sprintf('Downloaded and parsed %d transactions from bunq.', \count($return)));
 
         return $return;
     }
@@ -567,11 +570,12 @@ class StageImportDataHandler
                 $hasMoreTransactions = false;
                 $this->stillRunning  = false;
             }
-            sleep(1);
+            usleep(500000);
         }
 
         // store newest tranasction ID to be used later:
         \Preferences::setForUser($this->importJob->user, sprintf('bunq-newest-transaction-%d', $bunqAccountId), $newestTransaction);
+        Log::info(sprintf('Downloaded and parsed %d transactions from bunq.', \count($return)));
 
         return $return;
     }

app/Support/Import/Routine/Bunq/StageNewHandler.php

@@ -53,6 +53,7 @@ class StageNewHandler
      */
     public function run(): void
     {
+        Log::info('Now in StageNewHandler::run()');
         /** @var Preference $preference */
         $preference = app('preferences')->getForUser($this->importJob->user, 'bunq_api_context', null);
         if (null !== $preference && '' !== (string)$preference->data) {
@@ -68,6 +69,7 @@ class StageNewHandler
             $config             = $this->repository->getConfiguration($this->importJob);
             $config['accounts'] = $accounts;
             $this->repository->setConfiguration($this->importJob, $config);
+
             return;
         }
         throw new FireflyException('The bunq API context is unexpectedly empty.'); // @codeCoverageIgnore
@@ -127,9 +129,11 @@ class StageNewHandler
                 }
                 if (null !== $array) {
                     $accounts[] = $array;
+                    $this->reportFinding($array);
                 }
             }
         }
+        Log::info(sprintf('Found %d account(s) at bunq', \count($accounts)));
 
         return $accounts;
     }
@@ -274,4 +278,27 @@ class StageNewHandler
 
         return $return;
     }
+
+    /**
+     * Basic report method.
+     *
+     * @param array $array
+     */
+    private function reportFinding(array $array): void
+    {
+        $bunqId          = $array['id'] ?? '';
+        $bunqDescription = $array['description'] ?? '';
+        $bunqIBAN        = '';
+
+        // find IBAN:
+        $aliases = $array['aliases'] ?? [];
+        foreach ($aliases as $alias) {
+            $type = $alias['type'] ?? 'none';
+            if ('IBAN' === $type) {
+                $bunqIBAN = $alias['value'] ?? '';
+            }
+        }
+
+        Log::info(sprintf('Found account at bunq. ID #%d, title "%s" and IBAN "%s" ', $bunqId, $bunqDescription, $bunqIBAN));
+    }
 }