From 463f4ce22d40b95abe428382113c2a9a20690c3f Mon Sep 17 00:00:00 2001 From: Jonathan Jenne Date: Tue, 12 Mar 2019 15:48:47 +0100 Subject: [PATCH] Tweak logging, ZUGFeRD Import --- Jobs/EDMI/ZUGFeRD/ImportZUGFeRDFiles.vb | 242 ++++++++++++------------ Jobs/Exceptions.vb | 4 +- Modules.Logging/Logger.vb | 10 +- 3 files changed, 136 insertions(+), 120 deletions(-) diff --git a/Jobs/EDMI/ZUGFeRD/ImportZUGFeRDFiles.vb b/Jobs/EDMI/ZUGFeRD/ImportZUGFeRDFiles.vb index 554bd7d7..33b292ab 100644 --- a/Jobs/EDMI/ZUGFeRD/ImportZUGFeRDFiles.vb +++ b/Jobs/EDMI/ZUGFeRD/ImportZUGFeRDFiles.vb @@ -4,7 +4,6 @@ Imports System.Linq Imports DigitalData.Modules.Database Imports DigitalData.Modules.Interfaces Imports DigitalData.Modules.Logging -Imports DigitalData.Modules.Filesystem Imports System.Text.RegularExpressions Imports DigitalData.Modules.Jobs.Exceptions Imports FirebirdSql.Data.FirebirdClient @@ -111,7 +110,7 @@ Public Class ImportZUGFeRDFiles _firebird.ExecuteNonQuery(oSQLInsert) - _logger.Info("Email Queue updated for MessageId {0}.", FileGuid, oEmailTo) + _logger.Debug("Email Queue updated for MessageId {0}.", FileGuid, oEmailTo) Catch ex As Exception _logger.Error(ex) End Try @@ -160,139 +159,148 @@ Public Class ImportZUGFeRDFiles _logger.Info("Starting Job {0}", Me.GetType.Name) - For Each oPath As String In args.WatchDirectories - Dim oDirInfo As New DirectoryInfo(oPath) - - _logger.Info($"Start processing directory {oDirInfo.FullName}") - - If oDirInfo.Exists Then - ' Filter out *.lock files - Dim oFiles As List(Of FileInfo) = oDirInfo. - GetFiles(). - Where(Function(f) Not f.Name.EndsWith(".lock")). - ToList() - Dim oFileCount = oFiles.Count - Dim oCurrentFileCount = 0 - - _logger.Info("Found {0} files", oFileCount) - - ' Group files by messageId - Dim oGrouped As Dictionary(Of String, List(Of FileInfo)) = GroupFiles(oFiles) - - _logger.Info("Found {0} file groups", oGrouped.Count) - - ' Process each file group together - For Each oFileGroup In oGrouped - ' Start a new transaction for each file group. - ' This way we can rollback database changes for the whole filegroup in case something goes wrong. - Dim oConnection As FbConnection = _firebird.GetConnection() - Dim oTransaction As FbTransaction = oConnection.BeginTransaction() - ' Count the amount of ZUGFeRD files - Dim oZUGFeRDCount As Integer = 0 - ' Set the default Move Directory - Dim oMoveDirectory As String = args.SuccessDirectory - Dim oFileGroupFiles As List(Of FileInfo) = oFileGroup.Value - Dim oFileGroupId As String = oFileGroup.Key - Dim oMissingProperties As New List(Of String) - - _logger.Info("Start processing file group {0}", oFileGroupId) - - Try - For Each oFile In oFileGroupFiles - Dim oDocument As CrossIndustryDocumentType - - ' Clear missing properties for the new file - oMissingProperties = New List(Of String) - oCurrentFileCount += 1 - - _logger.Info($"({oCurrentFileCount}/{oFileCount}) Start processing file {oFile.Name}") - - Try - oDocument = _zugferd.ExtractZUGFeRDFile(oFile.FullName) - Catch ex As Exception - _logger.Warn($"({oCurrentFileCount}/{oFileCount}) File is not a valid ZUGFeRD document! Skipping.") - Continue For - End Try - - ' Check if there are more than one ZUGFeRD files - If oZUGFeRDCount = 1 Then - Throw New TooMuchFerdsException() - End If + Try + For Each oPath As String In args.WatchDirectories + Dim oDirInfo As New DirectoryInfo(oPath) + + _logger.Info($"Start processing directory {oDirInfo.FullName}") + + If oDirInfo.Exists Then + ' Filter out *.lock files + Dim oFiles As List(Of FileInfo) = oDirInfo. + GetFiles(). + Where(Function(f) Not f.Name.EndsWith(".lock")). + ToList() + Dim oFileCount = oFiles.Count + Dim oCurrentFileCount = 0 + + _logger.Info("Found {0} files", oFileCount) + + ' Group files by messageId + Dim oGrouped As Dictionary(Of String, List(Of FileInfo)) = GroupFiles(oFiles) + + _logger.Info("Found {0} file groups", oGrouped.Count) + + ' Process each file group together + For Each oFileGroup In oGrouped + ' Start a new transaction for each file group. + ' This way we can rollback database changes for the whole filegroup in case something goes wrong. + Dim oConnection As FbConnection = _firebird.GetConnection() + Dim oTransaction As FbTransaction = oConnection.BeginTransaction() + ' Count the amount of ZUGFeRD files + Dim oZUGFeRDCount As Integer = 0 + ' Set the default Move Directory + Dim oMoveDirectory As String = args.SuccessDirectory + Dim oFileGroupFiles As List(Of FileInfo) = oFileGroup.Value + Dim oFileGroupId As String = oFileGroup.Key + Dim oMissingProperties As New List(Of String) + + _logger.NewBlock($"Message Id {oFileGroupId}") + _logger.Info("Start processing file group {0}", oFileGroupId) + + Try + For Each oFile In oFileGroupFiles + Dim oDocument As CrossIndustryDocumentType + + ' Clear missing properties for the new file + oMissingProperties = New List(Of String) + oCurrentFileCount += 1 + + _logger.Info("Start processing file {0}", oFile.Name) + + Try + oDocument = _zugferd.ExtractZUGFeRDFile(oFile.FullName) + Catch ex As Exception + _logger.Warn("File is not a valid ZUGFeRD document! Skipping.") + Continue For + End Try + + ' Check if there are more than one ZUGFeRD files + If oZUGFeRDCount = 1 Then + Throw New TooMuchFerdsException() + End If - ' Since extraction went well, increase the amount of ZUGFeRD files - oZUGFeRDCount += 1 - - For Each Item As KeyValuePair(Of String, XmlItemProperty) In args.PropertyMap - Dim propertyValue As String = PropertyValues.GetPropValue(oDocument, Item.Key) - Dim propertyDescripton As String = Item.Value.Description - - If String.IsNullOrEmpty(propertyValue) Then - If Item.Value.IsRequired Then - _logger.Warn("Property {0} is empty but marked as required! Skipping.", propertyDescripton) - oMissingProperties.Add(propertyDescripton) - Continue For - Else - _logger.Debug("Property {0} is empty or not found. Skipping.", propertyDescripton) - Continue For + ' Since extraction went well, increase the amount of ZUGFeRD files + oZUGFeRDCount += 1 + + For Each Item As KeyValuePair(Of String, XmlItemProperty) In args.PropertyMap + Dim propertyValue As String = PropertyValues.GetPropValue(oDocument, Item.Key) + Dim propertyDescripton As String = Item.Value.Description + + If String.IsNullOrEmpty(propertyValue) Then + If Item.Value.IsRequired Then + _logger.Warn("Property {0} is empty but marked as required! Skipping.", propertyDescripton) + oMissingProperties.Add(propertyDescripton) + Continue For + Else + _logger.Debug("Property {0} is empty or not found. Skipping.", propertyDescripton) + Continue For + End If End If - End If - Dim oTableName = Item.Value.TableName - Dim oCommand = $"INSERT INTO {oTableName} (REFERENCE_GUID, ITEM_DESCRIPTION, ITEM_VALUE) VALUES ('{oFileGroupId}', '{propertyDescripton}', '{propertyValue}')" + Dim oTableName = Item.Value.TableName + Dim oCommand = $"INSERT INTO {oTableName} (REFERENCE_GUID, ITEM_DESCRIPTION, ITEM_VALUE) VALUES ('{oFileGroupId}', '{propertyDescripton}', '{propertyValue}')" - _logger.Debug("Mapping Property {0} to value {1}. Will be inserted into table {2}", propertyDescripton, propertyValue, oTableName) + _logger.Debug("Mapping Property {0} to value {1}. Will be inserted into table {2}", propertyDescripton, propertyValue, oTableName) - _firebird.ExecuteNonQueryWithConnection(oCommand, oConnection, Firebird.TransactionMode.ExternalTransaction, oTransaction) + _firebird.ExecuteNonQueryWithConnection(oCommand, oConnection, Firebird.TransactionMode.ExternalTransaction, oTransaction) + Next + + If oMissingProperties.Count > 0 Then + Throw New MissingValueException(oFile) + End If Next - If oMissingProperties.Count > 0 Then - Throw New MissingValueException(oFile) + ' Check if there are no ZUGFeRD files + If oZUGFeRDCount = 0 Then + Throw New NoFerdsException() End If - Next - ' Check if there are no ZUGFeRD files - If oZUGFeRDCount = 0 Then - Throw New NoFerdsException() - End If + ' If no errors occurred, commit the transaction + oTransaction.Commit() + Catch ex As TooMuchFerdsException + _logger.Error(ex) - ' If no errors occurred, commit the transaction - oTransaction.Commit() - Catch ex As TooMuchFerdsException - _logger.Error(ex) + oMoveDirectory = args.ErrorDirectory - oMoveDirectory = args.ErrorDirectory + Dim oBody = "

Your email contained more than one ZUGFeRD-Document.

" + AddToEmailQueue(oFileGroupId, oBody) + Catch ex As NoFerdsException + _logger.Error(ex) - Dim oBody = "

Your email contained more than one ZUGFeRD-Document.

" - AddToEmailQueue(oFileGroupId, oBody) - Catch ex As NoFerdsException - _logger.Error(ex) + oMoveDirectory = args.ErrorDirectory - oMoveDirectory = args.ErrorDirectory + Dim oBody = "

Your email contained no ZUGFeRD-Documents.

" + AddToEmailQueue(oFileGroupId, oBody) + Catch ex As MissingValueException + _logger.Error(ex) - Dim oBody = "

Your email contained no ZUGFeRD-Documents.

" - AddToEmailQueue(oFileGroupId, oBody) - Catch ex As MissingValueException - _logger.Error(ex) + oMoveDirectory = args.ErrorDirectory - oMoveDirectory = args.ErrorDirectory + Dim oBody = CreateBodyForMissingProperties(ex.File.Name, oMissingProperties) + AddToEmailQueue(oFileGroupId, oBody) + Finally + oConnection.Close() - Dim oBody = CreateBodyForMissingProperties(ex.File.Name, oMissingProperties) - AddToEmailQueue(oFileGroupId, oBody) - Finally - oConnection.Close() + ' Move all files of the current group + For Each oFile In oFileGroupFiles + _filesystem.MoveTo(oFile.FullName, oMoveDirectory) + _logger.Info("Finished processing file {0}", oFile.Name) + _logger.Info("File moved to {0}", oMoveDirectory) + Next - ' Move all files of the current group - For Each oFile In oFileGroupFiles - _filesystem.MoveTo(oFile.FullName, oMoveDirectory) - _logger.Info("({1}/{2}) Finished processing file {0}", oFile.Name, oCurrentFileCount, oFileCount) - _logger.Info($"({1}/{2}) File moved to {0}", oMoveDirectory) - Next + _logger.Info("Finished processing file group {0}", oFileGroupId) + _logger.EndBlock() + End Try + Next + End If + Next - _logger.Info("Finished processing file group {0}", oFileGroupId) - End Try - Next - End If - Next + _logger.Info("Finishing Job {0}", Me.GetType.Name) + Catch ex As Exception + _logger.Error(ex) + _logger.Info("Job Failed! See error log for details") + End Try End Sub diff --git a/Jobs/Exceptions.vb b/Jobs/Exceptions.vb index d7b8cd5c..9c326b51 100644 --- a/Jobs/Exceptions.vb +++ b/Jobs/Exceptions.vb @@ -17,7 +17,7 @@ Public Class Exceptions Inherits ApplicationException Public Sub New() - MyBase.New() + MyBase.New("More than one ZUGFeRD document found") End Sub End Class @@ -25,7 +25,7 @@ Public Class Exceptions Inherits ApplicationException Public Sub New() - MyBase.New() + MyBase.New("No ZUGFeRD documents found") End Sub End Class End Class diff --git a/Modules.Logging/Logger.vb b/Modules.Logging/Logger.vb index 3360b653..f908714d 100644 --- a/Modules.Logging/Logger.vb +++ b/Modules.Logging/Logger.vb @@ -8,7 +8,15 @@ Public Class Logger ''' ''' A unique Identifier for this block, eg. DocId, FullPath, .. Public Sub NewBlock(blockId As String) - Dim message As String = $"=========={vbTab}{vbTab}Start of Block {blockId}{vbTab}{vbTab}==========" + Dim message As String = $"-----> Start of Block {blockId}" + Dim logEventInfo As New LogEventInfo(LogLevel.Info, Name, message) + Dim WrapperType As Type = GetType(Logger) + + Log(WrapperType, logEventInfo) + End Sub + + Public Sub EndBlock() + Dim message As String = $"<----- End of Block" Dim logEventInfo As New LogEventInfo(LogLevel.Info, Name, message) Dim WrapperType As Type = GetType(Logger)