You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by "Tolga Kavukcu (JIRA)" <ji...@apache.org> on 2017/09/29 06:11:00 UTC

[jira] [Updated] (LOG4J2-2060) AbstactDatabase appender issue with AsyncLogger

     [ https://issues.apache.org/jira/browse/LOG4J2-2060?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Tolga Kavukcu updated LOG4J2-2060:
----------------------------------
    Description: 
Log4j2 AsycLogger Implementation with a database appender has an issue.

As i investigated the async logger mechanism works like that.

Messages are put into DistruptorRingBuffer

Than

*RingBufferLogEventHandler*'s *onEvent* mehtod is called and message is passed to appender asyncronously.

In *AbstractDatabaseAppender* case

The messages also put into an *ArrayList* to make batches for bulk insert to table.


{code:java}
@Override
public final void append(final LogEvent event) {
    this.readLock.lock();
    try {
        this.getManager().write(event);
    } catch (final LoggingException e) {
        LOGGER.error("Unable to write to database [{}] for appender [{}].", this.getManager().getName(),
                this.getName(), e);
        throw e;
    } catch (final Exception e) {
        LOGGER.error("Unable to write to database [{}] for appender [{}].", this.getManager().getName(),
                this.getName(), e);
        throw new AppenderLoggingException("Unable to write to database in appender: " + e.getMessage(), e);
    } finally {
        this.readLock.unlock();
    }
}
{code}


Than *Abstract Database Manager* puts *LogEvent* into *ArrayList*


{code:java}
public final synchronized void write(final LogEvent event) {
    if (this.bufferSize > 0) {

        this.buffer.add(event);
        if (this.buffer.size() >= this.bufferSize || event.isEndOfBatch()) {
            this.flush();
        }
    } else {
        this.connectAndStart();
        try {
            this.writeInternal(event);
        } finally {
            this.commitAndClose();
        }
    }
}
{code}


After that correspoding *LogEvent* object can be re-used in the *DistruptorRingBuffer* mechanism.

When a delay happens in the database the *LogEvent* objects are overriden with same referance which causes inconsitency while preparing batches.

I believe this points to a bug or design problem. 

I would like to contribute solution if anyone can guide where to start what might be the possible design.

  was:
Log4j2 AsycLogger Implementation with a database appender has an issue.

As i investigated the async logger mechanism works like that.

Messages are put into DistruptorRingBuffer

Than

*RingBufferLogEventHandler*'s *onEvent* mehtod is called and message is passed to appender asyncronously.

In *AbstractDatabaseAppender* case

The messages also put into an *ArrayList* to make batches for bulk insert to table.


{code:java}
@Override
public final void append(final LogEvent event) {
    this.readLock.lock();
    try {
        this.getManager().write(event);
    } catch (final LoggingException e) {
        LOGGER.error("Unable to write to database [{}] for appender [{}].", this.getManager().getName(),
                this.getName(), e);
        throw e;
    } catch (final Exception e) {
        LOGGER.error("Unable to write to database [{}] for appender [{}].", this.getManager().getName(),
                this.getName(), e);
        throw new AppenderLoggingException("Unable to write to database in appender: " + e.getMessage(), e);
    } finally {
        this.readLock.unlock();
    }
}
{code}


Than *Abstract Database Manager* puts *LogEvent* into *ArrayList*


{code:java}
public final synchronized void write(final LogEvent event) {
    if (this.bufferSize > 0) {

        this.buffer.add(event);
        if (this.buffer.size() >= this.bufferSize || event.isEndOfBatch()) {
            this.flush();
        }
    } else {
        this.connectAndStart();
        try {
            this.writeInternal(event);
        } finally {
            this.commitAndClose();
        }
    }
}
{code}


After that correspoding *LogEvent* object can be re-used in the *DistruptorRingBuffer* mechanism.

So if a delay could happen in the database the *LogEvent* objects are overriden with same referance which causes inconsitency while preparing batches.

I believe this points to a bug or design problem. 

I would like to contribute solution if anyone can guide where to start what might be the possible design.


> AbstactDatabase appender issue with AsyncLogger
> -----------------------------------------------
>
>                 Key: LOG4J2-2060
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2060
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 2.8.1, 2.8.2
>            Reporter: Tolga Kavukcu
>
> Log4j2 AsycLogger Implementation with a database appender has an issue.
> As i investigated the async logger mechanism works like that.
> Messages are put into DistruptorRingBuffer
> Than
> *RingBufferLogEventHandler*'s *onEvent* mehtod is called and message is passed to appender asyncronously.
> In *AbstractDatabaseAppender* case
> The messages also put into an *ArrayList* to make batches for bulk insert to table.
> {code:java}
> @Override
> public final void append(final LogEvent event) {
>     this.readLock.lock();
>     try {
>         this.getManager().write(event);
>     } catch (final LoggingException e) {
>         LOGGER.error("Unable to write to database [{}] for appender [{}].", this.getManager().getName(),
>                 this.getName(), e);
>         throw e;
>     } catch (final Exception e) {
>         LOGGER.error("Unable to write to database [{}] for appender [{}].", this.getManager().getName(),
>                 this.getName(), e);
>         throw new AppenderLoggingException("Unable to write to database in appender: " + e.getMessage(), e);
>     } finally {
>         this.readLock.unlock();
>     }
> }
> {code}
> Than *Abstract Database Manager* puts *LogEvent* into *ArrayList*
> {code:java}
> public final synchronized void write(final LogEvent event) {
>     if (this.bufferSize > 0) {
>         this.buffer.add(event);
>         if (this.buffer.size() >= this.bufferSize || event.isEndOfBatch()) {
>             this.flush();
>         }
>     } else {
>         this.connectAndStart();
>         try {
>             this.writeInternal(event);
>         } finally {
>             this.commitAndClose();
>         }
>     }
> }
> {code}
> After that correspoding *LogEvent* object can be re-used in the *DistruptorRingBuffer* mechanism.
> When a delay happens in the database the *LogEvent* objects are overriden with same referance which causes inconsitency while preparing batches.
> I believe this points to a bug or design problem. 
> I would like to contribute solution if anyone can guide where to start what might be the possible design.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)