Appendix 7 - Console log overview
Console logs are fundamental in order to observe the state of the executions. Below some common log patterns are shown and explained.
No new file to process
When scheduled the process will look at the directory pointed by the variable ACQ_BATCH_TRX_INPUT_PATH (see )and attempt to process any file placed into it. In case nothing has been found the execution log will look like this:
2022-03-02 13:09:00.001 INFO 4268 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : CsvTransactionReader scheduled job started at Wed Mar 02 13:09:00 CET 2022
2022-03-02 13:09:00.002 INFO 4268 --- [poolScheduler-1] i.g.p.r.t.batch.TransactionFilterBatch : No transaction file has been found on configured path: file:/tmp/batch_acquirer/input_trx/
2022-03-02 13:09:00.002 INFO 4268 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : CsvTransactionReader scheduled job ended at Wed Mar 02 13:09:00 CET 2022
2022-03-02 13:09:00.002 INFO 4268 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : Completed in: 1 (ms)A file has been found: start of batch execution
Otherwise, if a new file has been found in the input directory those lines will be displayed at the start of the execution log:
2022-03-02 13:15:30.005 INFO 4268 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : CsvTransactionReader scheduled job started at Wed Mar 02 13:15:30 CET 2022
2022-03-02 13:15:30.007 INFO 4268 --- [poolScheduler-1] i.g.p.r.t.batch.TransactionFilterBatch : Found 1 resource. Starting filtering processLifecycle of an input file processing
Each time the Batch Acquirer starts processing a file a proper line will be logged:
2022-03-02 13:15:31.387 INFO 4268 --- [rTaskExecutor-2] .r.t.b.s.l.TransactionReaderStepListener : Starting processing for file: file:/tmp/batch_acquirer/input_trx/CSTAR.99999.TRNLOG.20220302.121521.001.csvafter completion a new line will log the end of the file processing:
2022-03-02 13:15:31.502 INFO 4268 --- [rTaskExecutor-2] .r.t.b.s.l.TransactionReaderStepListener : Processing for file: file:/tmp/batch_acquirer/input_trx/CSTAR.99999.TRNLOG.20220302.121521.001.csv ended with status: COMPLETEDanother log will highlight that the file being processed will be encrypted:
2022-03-02 13:15:31.532 INFO 4268 --- [rTaskExecutor-2] i.g.p.r.t.b.s.w.PGPFlatFileItemWriter : Encrypting file CSTAR.99999.TRNLOG.20220302.121521.001.csv with PGP key 85286E3AC9C03C5B69AF61C589580E7CC3771ED4at last a new line will log the outcome of the upload of the file to CentroStella:
2022-03-02 13:15:32.134 INFO 4268 --- [rTaskExecutor-3] i.g.p.r.t.connector.HpanRestClientImpl : File CSTAR.99999.TRNLOG.20220302.121521.001.csv.pgp uploaded with success (status was: 201)Log of a complete run
Execution log
2022-07-05 10:42:20.000 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : CsvTransactionReader scheduled job started at Tue Jul 05 10:42:20 UTC 2022
2022-07-05 10:42:20.052 INFO 11 --- [poolScheduler-1] i.g.p.r.t.batch.TransactionFilterBatch : Found 1 resource. Starting filtering process
2022-07-05 10:42:20.260 INFO 11 --- [poolScheduler-1] o.s.b.c.l.support.SimpleJobLauncher : Job: [FlowJob: [name=transaction-filter-job]] launched with the following parameters: [{startDateTime=1657017740000}]
2022-07-05 10:42:20.344 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-public-key-recovery-step]
2022-07-05 10:42:21.167 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-public-key-recovery-step] executed in 823ms
2022-07-05 10:42:21.172 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-select-target-input-file-step]
2022-07-05 10:42:21.174 INFO 11 --- [poolScheduler-1] p.r.t.b.s.t.SelectTargetInputFileTasklet : Current job execution will process input file: CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:42:21.175 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-select-target-input-file-step] executed in 3ms
2022-07-05 10:42:21.179 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [prevent-reprocessing-filename-already-seen-step]
2022-07-05 10:42:21.181 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [prevent-reprocessing-filename-already-seen-step] executed in 2ms
2022-07-05 10:42:21.185 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-checksum-master-step]
2022-07-05 10:42:33.605 INFO 11 --- [rTaskExecutor-1] g.p.r.t.b.s.t.TransactionChecksumTasklet : File CSTAR.99999.TRNLOG.20220705.122412.001.csv SHA256 digest: e07867bda383f918f87b0c211e519663830ba96f97cb352dbdf21d37f67ead4c
2022-07-05 10:42:33.607 INFO 11 --- [rTaskExecutor-1] o.s.batch.core.step.AbstractStep : Step: [transaction-checksum-worker-step:partition0] executed in 12s405ms
2022-07-05 10:42:33.609 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-checksum-master-step] executed in 12s424ms
2022-07-05 10:42:33.612 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-abi-to-fiscalcode-recovery-step]
2022-07-05 10:42:33.613 INFO 11 --- [poolScheduler-1] .b.s.t.AbiToFiscalCodeMapRecoveryTasklet : Retrieving acquirer fake abi to fiscal code map
2022-07-05 10:42:33.964 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-abi-to-fiscalcode-recovery-step] executed in 352ms
2022-07-05 10:42:33.979 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-aggregation-reader-master-step]
2022-07-05 10:42:33.987 INFO 11 --- [rTaskExecutor-2] .r.t.b.s.l.TransactionReaderStepListener : Starting processing for file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:42:34.081 WARN 11 --- [rTaskExecutor-2] o.s.batch.core.step.item.ChunkMonitor : No ItemReader set (must be concurrent step), so ignoring offset data.
2022-07-05 10:42:34.432 WARN 11 --- [rTaskExecutor-3] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 7
2022-07-05 10:42:34.439 WARN 11 --- [rTaskExecutor-1] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 14
2022-07-05 10:42:34.443 WARN 11 --- [rTaskExecutor-1] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 15
2022-07-05 10:42:34.444 WARN 11 --- [rTaskExecutor-1] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 16
2022-07-05 10:42:34.444 WARN 11 --- [rTaskExecutor-3] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 8
2022-07-05 10:42:34.445 WARN 11 --- [rTaskExecutor-1] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 17
2022-07-05 10:42:34.445 WARN 11 --- [rTaskExecutor-3] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 9
2022-07-05 10:42:34.449 WARN 11 --- [rTaskExecutor-3] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 10
2022-07-05 10:42:34.450 WARN 11 --- [rTaskExecutor-3] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 11
2022-07-05 10:42:34.450 WARN 11 --- [rTaskExecutor-3] .p.TransactionAggregationReaderProcessor : Dirty data found on either VAT or POS type fields at line 12
2022-07-05 10:42:34.805 WARN 11 --- [rTaskExecutor-4] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:42:34.809 WARN 11 --- [rTaskExecutor-1] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:42:34.817 WARN 11 --- [rTaskExecutor-2] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:42:34.822 WARN 11 --- [rTaskExecutor-3] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:42:35.009 WARN 11 --- [rTaskExecutor-5] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:44:25.806 INFO 11 --- [rTaskExecutor-2] .r.t.b.s.l.TransactionReaderStepListener : Processing for file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv ended with status: COMPLETED
2022-07-05 10:44:25.808 INFO 11 --- [rTaskExecutor-2] o.s.batch.core.step.AbstractStep : Step: [transaction-aggregation-reader-worker-step:partition0] executed in 1m51s823ms
2022-07-05 10:44:25.810 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-aggregation-reader-master-step] executed in 1m51s831ms
2022-07-05 10:44:25.819 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-enforce-uniqueness-acquirer-code-step]
2022-07-05 10:44:25.820 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-enforce-uniqueness-acquirer-code-step] executed in
2022-07-05 10:44:25.824 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-aggregation-writer-master-step]
2022-07-05 10:44:34.117 INFO 11 --- [rTaskExecutor-3] o.s.batch.core.step.AbstractStep : Step: [transaction-aggregation-writer-worker-step:partition0] executed in 8s289ms
2022-07-05 10:44:34.146 INFO 11 --- [rTaskExecutor-3] i.g.p.r.t.b.s.w.PGPFlatFileItemWriter : Encrypting file ADE.99999.TRNLOG.20220705.122412.001.csv with PGP key 85286E3AC9C03C5B69AF61C589580E7CC3771ED4
2022-07-05 10:44:45.836 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-aggregation-writer-master-step] executed in 20s12ms
2022-07-05 10:44:45.839 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-purge-aggregates-from-memory-step]
2022-07-05 10:44:45.841 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-purge-aggregates-from-memory-step] executed in 2ms
2022-07-05 10:44:45.842 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-sender-ade-master-step]
2022-07-05 10:45:36.876 INFO 11 --- [rTaskExecutor-4] i.g.p.r.t.connector.HpanRestClientImpl : File ADE.99999.TRNLOG.20220705.122412.001.csv.pgp uploaded with success (status was: 201)
2022-07-05 10:45:36.878 INFO 11 --- [rTaskExecutor-4] o.s.batch.core.step.AbstractStep : Step: [transaction-sender-ade-worker-step:partition0] executed in 50s976ms
2022-07-05 10:45:36.879 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-sender-ade-master-step] executed in 51s37ms
2022-07-05 10:45:36.882 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-salt-hpan-list-recovery-step]
2022-07-05 10:45:36.884 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-salt-hpan-list-recovery-step] executed in 1ms
2022-07-05 10:45:36.894 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-salt-recovery-step]
2022-07-05 10:45:37.146 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-salt-recovery-step] executed in 252ms
2022-07-05 10:45:37.147 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [hpan-recovery-master-step]
2022-07-05 10:45:37.186 WARN 11 --- [rTaskExecutor-5] o.s.batch.core.step.item.ChunkMonitor : No ItemReader set (must be concurrent step), so ignoring offset data.
2022-07-05 10:45:37.199 WARN 11 --- [rTaskExecutor-5] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:45:37.200 WARN 11 --- [rTaskExecutor-1] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:45:37.201 WARN 11 --- [rTaskExecutor-4] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:45:37.202 WARN 11 --- [rTaskExecutor-3] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:45:37.211 WARN 11 --- [rTaskExecutor-2] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:46:48.752 INFO 11 --- [rTaskExecutor-5] o.s.batch.core.step.AbstractStep : Step: [hpan-recovery-worker-step:partition0] executed in 1m11s601ms
2022-07-05 10:46:48.754 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [hpan-recovery-master-step] executed in 1m11s607ms
2022-07-05 10:46:48.756 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-master-step]
2022-07-05 10:46:48.758 INFO 11 --- [rTaskExecutor-1] .r.t.b.s.l.TransactionReaderStepListener : Starting processing for file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:46:48.800 WARN 11 --- [rTaskExecutor-1] o.s.batch.core.step.item.ChunkMonitor : No ItemReader set (must be concurrent step), so ignoring offset data.
2022-07-05 10:46:49.204 WARN 11 --- [rTaskExecutor-3] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:46:49.211 WARN 11 --- [rTaskExecutor-1] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:46:49.219 WARN 11 --- [rTaskExecutor-4] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:46:49.253 WARN 11 --- [rTaskExecutor-5] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:46:49.381 WARN 11 --- [rTaskExecutor-2] o.s.batch.core.step.item.ChunkMonitor : ItemStream was opened in a different thread. Restart data could be compromised.
2022-07-05 10:49:40.749 INFO 11 --- [rTaskExecutor-1] .r.t.b.s.l.TransactionReaderStepListener : Processing for file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv ended with status: COMPLETED
2022-07-05 10:49:40.751 INFO 11 --- [rTaskExecutor-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-worker-step:partition0] executed in 2m51s993ms
2022-07-05 10:49:40.755 INFO 11 --- [rTaskExecutor-1] i.g.p.r.t.b.s.w.PGPFlatFileItemWriter : Encrypting file CSTAR.99999.TRNLOG.20220705.122412.001.csv with PGP key 85286E3AC9C03C5B69AF61C589580E7CC3771ED4
2022-07-05 10:50:59.321 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-master-step] executed in 4m10s563ms
2022-07-05 10:50:59.326 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-sender-rtd-master-step]
2022-07-05 10:57:33.163 INFO 11 --- [rTaskExecutor-2] i.g.p.r.t.connector.HpanRestClientImpl : File CSTAR.99999.TRNLOG.20220705.122412.001.csv.pgp uploaded with success (status was: 201)
2022-07-05 10:57:33.167 INFO 11 --- [rTaskExecutor-2] o.s.batch.core.step.AbstractStep : Step: [transaction-sender-rtd-worker-step:partition0] executed in 6m33s774ms
2022-07-05 10:57:33.170 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-sender-rtd-master-step] executed in 6m33s844ms
2022-07-05 10:57:33.174 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-sender-ade-ack-files-recovery-step]
2022-07-05 10:57:33.873 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-sender-ade-ack-files-recovery-step] executed in 699ms
2022-07-05 10:57:33.874 INFO 11 --- [poolScheduler-1] o.s.batch.core.job.SimpleStepHandler : Executing step: [transaction-filter-file-management-step]
2022-07-05 10:57:33.937 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Archiving processed file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:57:55.899 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Already managed file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:57:55.902 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Already managed file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:57:55.905 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Archiving processed file: file:/workdir/output/ADE.99999.TRNLOG.20220705.122412.001.csv.pgp
2022-07-05 10:57:55.912 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Already managed file: file:/workdir/input/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:57:55.912 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Archiving processed file: file:/workdir/output/CSTAR.99999.TRNLOG.20220705.122412.001.csv.pgp
2022-07-05 10:57:55.919 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Deleting output file: /workdir/output/ADE.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:57:55.923 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.s.t.FileManagementTasklet : Deleting output file: /workdir/output/CSTAR.99999.TRNLOG.20220705.122412.001.csv
2022-07-05 10:57:56.015 INFO 11 --- [poolScheduler-1] o.s.batch.core.step.AbstractStep : Step: [transaction-filter-file-management-step] executed in 22s141ms
2022-07-05 10:57:56.020 INFO 11 --- [poolScheduler-1] o.s.b.c.l.support.SimpleJobLauncher : Job: [FlowJob: [name=transaction-filter-job]] completed with the following parameters: [{startDateTime=1657017740000}] and the following status: [COMPLETED] in 15m35s690ms
2022-07-05 10:57:56.021 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : CsvTransactionReader scheduled job ended at Tue Jul 05 10:57:56 UTC 2022
2022-07-05 10:57:56.021 INFO 11 --- [poolScheduler-1] i.g.p.r.t.b.TransactionFilterScheduler : Completed in: 936021 (ms)Last updated