> For the complete documentation index, see [llms.txt](https://docs.pagopa.it/centrostella-1/llms.txt). Markdown versions of documentation pages are available by appending `.md` to page URLs; this page is available as [Markdown](https://docs.pagopa.it/centrostella-1/centro-stella/instructions-for-agenzia-delle-entrate-mandate/appendixes/appendix-7-console-log-overview.md). # 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 [Broken mention](broken://pages/ZA8dlA7le05HoAx5jDAy))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 process ``` ### Lifecycle 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.csv ``` after 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: COMPLETED ``` another 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 85286E3AC9C03C5B69AF61C589580E7CC3771ED4 ``` at 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) ```