From 53ed5b2975c17ed26321e851418e07ca1504995c Mon Sep 17 00:00:00 2001 From: James Cole Date: Wed, 31 Oct 2018 16:25:21 +0100 Subject: [PATCH] Improved logging for bunq routine. #1607 --- app/Factory/TransactionCurrencyFactory.php | 2 +- .../Import/JobConfigurationController.php | 2 +- .../Import/JobStatusController.php | 10 ++++--- app/Import/Routine/BunqRoutine.php | 2 +- app/Import/Storage/ImportArrayStorage.php | 12 ++++++--- .../Bunq/ChooseAccountsHandler.php | 4 +++ .../Routine/Bunq/StageImportDataHandler.php | 18 ++++++++----- .../Import/Routine/Bunq/StageNewHandler.php | 27 +++++++++++++++++++ 8 files changed, 60 insertions(+), 17 deletions(-) diff --git a/app/Factory/TransactionCurrencyFactory.php b/app/Factory/TransactionCurrencyFactory.php index bbf87849f8..9d827c59b4 100644 --- a/app/Factory/TransactionCurrencyFactory.php +++ b/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; } diff --git a/app/Http/Controllers/Import/JobConfigurationController.php b/app/Http/Controllers/Import/JobConfigurationController.php index 0a2d9e96d5..30460f3dea 100644 --- a/app/Http/Controllers/Import/JobConfigurationController.php +++ b/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')); diff --git a/app/Http/Controllers/Import/JobStatusController.php b/app/Http/Controllers/Import/JobStatusController.php index 9d256a5817..93e0a6e3c5 100644 --- a/app/Http/Controllers/Import/JobStatusController.php +++ b/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']); } diff --git a/app/Import/Routine/BunqRoutine.php b/app/Import/Routine/BunqRoutine.php index f5b6deb3b3..625b2d7437 100644 --- a/app/Import/Routine/BunqRoutine.php +++ b/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) { diff --git a/app/Import/Storage/ImportArrayStorage.php b/app/Import/Storage/ImportArrayStorage.php index 4d649883f9..6f7601a78d 100644 --- a/app/Import/Storage/ImportArrayStorage.php +++ b/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::debug('Going to store...'); + Log::notice(sprintf('After a first check for duplicates, the count of items is %d.', $count)); + 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; } diff --git a/app/Support/Import/JobConfiguration/Bunq/ChooseAccountsHandler.php b/app/Support/Import/JobConfiguration/Bunq/ChooseAccountsHandler.php index 0846e8ae79..8b1558202f 100644 --- a/app/Support/Import/JobConfiguration/Bunq/ChooseAccountsHandler.php +++ b/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; } diff --git a/app/Support/Import/Routine/Bunq/StageImportDataHandler.php b/app/Support/Import/Routine/Bunq/StageImportDataHandler.php index 704cc0bb62..326c9bb5df 100644 --- a/app/Support/Import/Routine/Bunq/StageImportDataHandler.php +++ b/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; } diff --git a/app/Support/Import/Routine/Bunq/StageNewHandler.php b/app/Support/Import/Routine/Bunq/StageNewHandler.php index 05debeba55..89ef3a4075 100644 --- a/app/Support/Import/Routine/Bunq/StageNewHandler.php +++ b/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)); + } }