j-easy / easy-batch

The simple, stupid batch framework for Java
https://github.com/j-easy/easy-batch/wiki
MIT License
611 stars 199 forks source link

BatchJob log validation errors too verbose #390

Closed seseso closed 3 years ago

seseso commented 3 years ago

I's noticed that if I have a validator where I throw an exception for each validation error (that's how it should be used, right?), the BatchJob class will fill the log with those exceptions (line 234, LOGGER.error("Unable to process record {}", record, e);). Would it be possible to have a configuration to control this log messages? I was testing a batch with about one million records and if I have a validation error on each one, the log will be filled with those messages and the time taken to run is almost 10x slower because of that. My suggestion would be to have a JobParameter to control this loggging line (ex. disableProcessLogError). Would you think this would make sense?

fmbenhassine commented 3 years ago

yes, it is expected to throw an exception from the validator if a record is invalid. Easy Batch is logging those errors at the error log level. Aren't you interested in knowing what caused each record to be rejected? I mean isn't this what logs are for?

Changing the log level to debug seems incorrect to me, validation errors should be logged as errors. Completely removing this line is not an option neither, because this means one must use a custom pipelineListener.onRecordProcessingException to log processing/validation errors somewhere. The suggested feature of adding a flag disableProcessLogError to guard logging does not feel right to add in a batch framework, this is really a logging concern (I'm ready to accept that Easy Batch is using the wrong log level but I'm not sure adding such flag is judicious, because this flag would make things inconsistent and open the door for suggesting to add flags like disableReadLogError, disableWriteLogError, etc and all the logging in the code base would be guarded with different flags..).

I was testing a batch with about one million records and if I have a validation error on each one, the log will be filled with those messages and the time taken to run is almost 10x slower because of that.

I understand what's happening, but how frequent does this happen? If all records are invalid, this means you have something fundamentally wrong with your file. This might happens at the first stages of your job development/testing (where it's ok to have a slower execution but a precise log), but after that in practice you would have a few invalid records but not every single one. What I'm trying to explain is that if this really happens, it's ok to have a slower execution for that particular execution. I would not add a guarded log to make a very particular case faster at the cost of making all executions slower. Do you agree?

seseso commented 3 years ago

I have thrid party systems that generate those files, which I don't control. I understand and accept your points but, I would very much appreciate a flag for, at least, making optional the "trace" of the error:

if(disableErrorTrace) {
    LOGGER.error("Unable to process record {}", record);)
} else {
    LOGGER.error("Unable to process record {}", record**, e**);)
}

By default, this flag could / should be false. This would maintain your (correct) view on how this should work but allow other use cases as well. My biggest problem is not the error log but the trace associated with it. For a million file length, the log will multiply thos rows by the extension of the trace. Is this reasonble for you?

fmbenhassine commented 3 years ago

Logging an error without its root cause is an anti-pattern (even tools like sonar might complain about that). Moreover, if we do this here, we should do it everywhere for consistency as disableErrorTrace is a generic name: the average user would expect this flag to be applied everywhere (and there are a dozen places where LOGGER.error is called, and not all of them have access to the job parameters to check this flag). I won't talk about performance without a benchmark, but this means there would be an additional test of disableErrorTrace for each error.

Adding a "logging feature" in a batch framework does not feel right to me. I still believe you are trying to address a false problem here: if you have a file with one million invalid records, I'm not surprised to get a log file with one million error messages with their respective traces. Again, pragmatically speaking, how often does this happen? I'm not sure this would be frequently the case (otherwise, there is something fundamentally wrong with your interface with those third party systems), and for that particular seldom case when this happens, it's ok IMO to have a slower execution (this could even be a good sign that something is wrong..). That's why I would not impact the average user with a confusing flag about a logging flag that does not belong to a batch framework in the first place.

If you find these logs verbose for your particular use case, you can disable them and implement your approach in a custom PipelineListener, something like:

class LoggingListener implements PipelineListener {

    private final Logger LOGGER = LoggerFactory.getLogger(LoggingListener.class.getName());
    private final boolean disableErrorTrace;

    public LoggingListener(boolean disableErrorTrace) {
        this.disableErrorTrace = disableErrorTrace;
    }

    @Override
    public <P> void onRecordProcessingException(Record<P> record, Throwable throwable) {
        if(disableErrorTrace) {
            LOGGER.error("Unable to process record {}", record);
        } else {
            LOGGER.error("Unable to process record {}", record, throwable);
        }
    }
}

This listener could be polymorphic and implement other listeners if you are interested in logging other parts of the process.

I'm closing this issue for now, but feel free to add a comment if you want to discuss this further.